测试公司的保障MySQL高可用组件时发现一个异常。
停止从库,高可用组件将从库自动启动后,主库发生重启。而正常情况下主库不应发生重启。
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 thread2017-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): 61Status: 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'
所以这个故障复现有了两个必要条件:
至于为什么不能每次启停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 binaryor 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 informationcollection 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.
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链表。
搜图
编辑
这里有两个场景会出现‘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版本可以解决问题。
最后总结一下我的诊断路径: