MySQL semi-sync插件崩溃导致MySQL重启的故障分析

发布时间:2017-09-12 浏览次数:719

起因:

测试公司的保障MySQL高可用组件时发现一个异常。

停止从库,高可用组件将从库自动启动后,主库发生重启。而正常情况下主库不应发生重启。

环境:

OS: CentOS release 6.7 (Final)

MySQL:Ver 14.14 Distrib 5.7.13, for linux-glibc2.5 (x86_64) using EditLine wrapper

主从实例开启半同步 MySQL semi-sync配置文档

分析:

首先,先分析log文件

在主库的mysql-error.log中我们可以发现如下几点:

1. 主库的semi-sync在崩溃前做了启停动作。

2017-07-25T16:02:38.636061+08:00 40 [Note] Semi-sync replication switched OFF.
2017-07-25T16:02:38.636105+08:00 40 [Note] Semi-sync replication disabled on the master.
2017-07-25T16:02:38.636137+08:00 0 [Note] Stopping ack receiver thread
2017-07-25T16:02:38.638008+08:00 40 [Note] Semi-sync replication enabled on the master.
2017-07-25T16:02:38.638131+08:00 0 [Note] Starting ack receiver thread

2. 主库的semi-sync启动后立即引发了semi-sync插件崩溃,并抛出Assert异常。

mysqld: /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master.cc:844: int ReplSemiSyncMaster::commitTrx(const char*, my_off_t): Assertion `entry' failed.
08:02:38 UTC - mysqld got signal 6 ;

3. 这里还有一个相当重要的复现故障的线索。简单说明一下,这条SQL语句是为了检测主从数据差,而由高可用中间件不断的向数据库更新时间戳。

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f408c0054c0): update universe.u_delay set real_timestamp=now(), logic_timestamp = logic_timestamp + 1 where source = 'ustats'
Connection ID (thread ID): 61
Status: NOT_KILLED

到这里初步判断是这个故障应与设置rpl_semi_sync_master_enabled开关相关,并且应该当时是有事务提交的。

进一步验证,这里只部署一组开启semi-sync的MySQL实例,而不安装高可用组件。

利用bash脚本向主库不断插入数据:

/opt/mysql/base/bin/mysql -uroot -p1 -S /opt/mysql/data/3306/mysqld.sock -e "create database if not exists test;use test;drop table if exists t1;create table t1(id int) "
i=0
while true
do
/opt/mysql/base/bin/mysql -uroot -p1 -S /opt/mysql/data/3306/mysqld.sock -e "insert into test.t1 values($i)"
i=$((i+1))
done

在主库的机器上,反复运行如下命令,启停semi-sync master,不超过5次必能复现这个故障。

/opt/mysql/base/bin/mysql -uroot -p1 -S /opt/mysql/data/3306/mysqld.sock -e'SET GLOBAL rpl_semi_sync_master_enabled = OFF;SET GLOBAL rpl_semi_sync_master_enabled = ON'

所以这个故障复现有了两个必要条件:

  1. 启停semi-sync master

  2. 数据库当时有事务提交

其次,分析MySQL源码

至于为什么不能每次启停semi-sync master都能触发这个故障,那我们就要看看MySQL的源码了

还好mysql-error.log明确的指出了抛出异常的位置:

mysqld: /export/home/pb2/build/sb_0-19016729-1464157976.67/mysql-5.7.13/plugin/semisync/semisync_master.cc:844: int ReplSemiSyncMaster::commitTrx(const char*, my_off_t): Assertion `entry' failed.
08:02:38 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

找到MySQL源码,抛出异常的的位置 mysql-5.7.13 semisync_master.cc#L844

无标题

看来是这个‘entry’的值为NULL,才抛出的异常,但是这还没有回答我的疑问。

再看MySQL的报错信息,MySQL自己也认识到这应该是个BUG,那它有没有修复这个故障呢?

我找到MySQL最新5.7.19的版本,查看它的历史记录mysql-5.7.19 semisync_master.cc history


这正是我想要的修复和提交,打开看看有没有对产生故障原因的分析。Bug#22202516: ENABLING SEMI-SYNC DURING COMMIT CAN CAUSE MASTER TO ASSERT.

为了方便解释这个BUG, 这里先简单的介绍一下MySQL binlog提交过程:

MySQL 在5.6版本引入了Binary Log Group Commit,二进制日志的提交由此可以简化为三个阶段:

image

这正是我想要的修复和提交,打开看看有没有对产生故障原因的分析。

这正是我想要的修复和提交,打开看看有没有对产生故障原因的分析。Bug#22202516: ENABLING SEMI-SYNC DURING COMMIT CAN CAUSE MASTER TO ASSERT.

为了方便解释这个BUG, 这里先简单的介绍一下MySQL binlog提交过程:

MySQL 在5.6版本引入了Binary Log Group Commit,二进制日志的提交由此可以简化为三个阶段:

无标题

Flush stage:将事务的日志写入binlog文件的缓存中

Sync stage: 将binlog文件中的缓存数据写入磁盘

Commit stage:根据顺序调用存储引擎提交事务。

MYSQL_BIN_LOG::ordered_commit,这个是事务在binlog阶段提交的核心函数。通过该函数,实现了事务日志写入binlog文件,以及触发dump线程将binlog发送到从库,在最后将事务设置为提交状态。

事实上,有没有semi-sync机制,上面介绍的MySQL的有关事务提交中关于binlog的流程都是一样的。semi-sync的作用只是主从之间的一个确认过程,主库等待从库返回相关位置的binlog已经同步到从库的确认,没有得到确认之前,事务提交则在该函数(步骤)上等待直至获得返回。

在半同步复制中,为了在主库提交事务时等待从库的确认,才引出了由‘entry’组成的active transaction链表。

在BUG分析中提到:

首先在flush stage,由semi-sync创建一个‘entry’,并关联一个或一组处于flush stage的事务。这个‘entry’被插入一个active transaction链表。 参考: create entry


上一篇: 记一次 MySQL semaphore crash 的分析(有彩蛋)

下一篇: binlog rotate引发的MySQL阻塞事件

在线咨询
免费电话