semi-sync插件崩溃导致MySQL重启的故障分析全过程
导读
semi-sync插件崩溃导致MySQL重启的故障分析全过程~
作者：刘安
现为爱可生高级测试工程师，拥有丰富的自动测试开发经验；曾先后在文思海辉、Splunk担任测试工程师。
一、起因：
在公司测试MySQL高可用组件时发现一个异常。如下：
停止从库，高可用组件将从库自动启动后，主库发生了重启。然而，正常情况下，主库不应发生重启。
二、环境：
1、OS： CentOS release 6.7 (Final)；
2、MySQL：Ver 14.14 Distrib 5.7.13, for linux-glibc2.5 (x86_64) using EditLine wrapper；
3、主从实例开启半同步 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脚本向主库不断插入数据：
#!/usr/bin/env 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'
所以这个故障复现有了两个必要条件：
-
启停semi-sync master；
-
数据库当时有事务提交。
（三）最后分析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。
/* wait for the position to be ACK'ed back */
assert(entry);
entry->n_waiters++;
wait_result= mysql_cond_timedwait(&entry->cond, &LOCK_binlog_, &abstime);
看来是这个‘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，二进制日志的提交由此可以简化为三个阶段：
-
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。
int ReplSemiSyncMaster::writeTranxInBinlog(const char* log_file_name, my_off_t log_file_pos)
{
...
if (is_on())
{
assert(active_tranxs_ != NULL);
if(active_tranxs_->insert_tranx_node(log_file_name, log_file_pos))
{
/*
if insert tranx_node failed, print a warning message
and turn off semi-sync
*/
sql_print_warning("Semi-sync failed to insert tranx_node for binlog file: %s, position: %lu",
log_file_name, (ulong)log_file_pos);
switch_off();
}
}
...
}
-
接下来是sync stage，在sync stage每个处于这个阶段的线程将会设置trx_wait_binlog_name和trx_wait_binlog_pos为事务对应binlog的相对位置；
-
最后再commit stage，semi-sync为了等从库的确认，会用trx_wait_binlog_name和trx_wait_binlog_pos获取这个位置关联的'entry', 参考: find entry；
int ReplSemiSyncMaster::commitTrx(const char* trx_wait_binlog_name, my_off_t trx_wait_binlog_pos)
{
...
TranxNode* entry= NULL;
mysql_cond_t* thd_cond= NULL;
if (active_tranxs_ != NULL && trx_wait_binlog_name)
{
entry=
active_tranxs_->find_active_tranx_node(trx_wait_binlog_name,
trx_wait_binlog_pos);
if (entry)
thd_cond= &entry->cond;
}
...
}
这里有两个场景会出现‘entry’找不到的情况：
1、从库已经确认的事务在binlog位置比当前等待从库确认的事务在binlog的位置要大；
2、当事务进入flush stage的时候semi-sync还没有开启，也就没有‘entry’被创建，然后插入active transaction链表。
情况1永远也不会进入等待阶段，因为它已经被从库确认过了；
情况2则会导致上述的断言异常，因为这里它无法在active transaction链表找到相应的’entry‘。
到这里我的疑问终于解开，原来开启semi-sync master的时机很重要，要恰巧撞到事务提交过了flush stage但还没有到commit stage这个缝隙。
四、结论：
最终修复的结果也很明显，就是遇到找不到‘entry’并且从库也没有确认的情况，这个事务提交就被认为是一次异步提交。
再看一眼在哪些版本修复了这个BUG：
所以升级MySQL版本可以解决问题。
五、复盘：
最后总结一下我的诊断路径：
-
观察故障出现的现象，分析MySQL的error log；
-
通过猜想和实验，构成简单的复现场景；
-
通过日志和MySQL源码的对应关系, 搜索代码历史, 定位BUG号；
-
通过阅读BUG的分析，了解异常发生的原理并知道了详细的复现条件。
