背景

在大型MySQL集群增加了新的库，运行正常（没有开启GTID）。几天后将新加入的库开启GTID。

MySQL版本：5.7.19

故障现象

变更后，当业务压力开始上升，发现其中一个节点以大概半小时的频率，业务会间断性地发生阻塞。

分析过程

1.观察故障现象

根据业务研发同事描述，大概每半小时发生一次故障。等到故障发生时，观测到以下现象：

a.show processlist发现有4000左右正在执行的insert，执行时间在10～300s

b. show global variables like 'thread_running' 无响应

c. top观察CPU只使用到1个核，内存正常，iowait值3%左右

d. iostat观察到700M/s read，随后使用iotop观察有一个MySQL线程700M/s read

2.定位700M/s read线程

显然700M/s的读IO极不正常，问题突破点就在这里，接下来我们要找到数据库在做什么导致了这么高的读IO。

iotop可查找到问题线程TID，通过performance_schema.threads查找到对应的MySQL内部真实线程：

（以下截图均为测试环境复现截图，虚拟机IO差很多只有97M/s）

查得MySQL中线程正在做一个insert，且只插入一行数据。

第一反应是insert为什么会造成700M/s的读IO，并且会持续3-5分钟之久？分析insert语句，只插入1行数据，更加不可理解。几次故障观察到同一现象。

3.分析binlog

猜测：这是一个大事务，事务包含了大量insert语句。

解析binlog，使用insert语句中的唯一ID过滤binlog，发现：

a. 这个insert所在事务只有1条insert；

b. 这个insert所在事务位于binlog最末尾。

得到结论：insert语句正常，并非大事务。那是什么原因？“insert所在事务位于binlog最末尾”好像有点意思。

继续解析binlog，发现几次故障时的insert所在事务也是位于binlog最末尾。

这不是巧合，应该与binlog rotate有关！好像发现了什么！

4.确认故障与binlog rotate相关联

前面提到每次故障发生，MySQL的thread_running会飙升至4000左右，并且无响应。

通过这个信息，我们打开监控图表，对照binlog的刷新时间点，基本吻合。

到这里，我们基本可以认为故障与binlog rotate是相关联的。接下来就是验证了。

5.复现与验证

情况紧急，接下来的操作需要在从库（因为从库也发生过故障导致了主从切换）验证，从库执行flush logs手工刷新binlog，并使用strace观测MySQL到底做了什么导致了700M/s的读IO。

a. 开启strace，strace -o /tmp/strace_output.txt -T -tt -f -e trace=read,open -p 'mysql_pid'

b. 从库flush logs；

c. iotop观察到有一个700M/s读的线程，问题复现！

d. 关闭strace

6.原因定位

（以下截图均为测试环境复现截图，虚拟机IO差很多只有97M/s）

上一步复现了故障，并且获取strace信息，接下来进行分析：

看到strace信息中大量重复的文件句柄号：

统计strace信息中 文件句柄72 的总行数，占strace信息总行数的90%以上，由此可大致判断：对文件句柄72存在大量读操作：

查看MySQL进程下的文件句柄，发现 文件句柄72 对应文件为binlog：

再分析strace信息中open函数，发现open的文件都是binlog，且在按顺序打开binlog文件！离真相越来越近了：）

这时我们脑海里会出现一个问题：为什么binlog刷新时会从头至尾扫描binlog？

扫描脑子里的知识库：binlog_gtid_simple_recovery

以下是MySQL官方手册解释：

结合源码归纳后可以理解为：

当MySQL重启，且binlog_gtid_simple_recovery=false：

更新gtid_executed，从最新的binlog开始扫描，直到找到第一个有Previous_gtids_log_event的binlog为止；更新gtid_purged，从最旧的binlog开始扫描，直到找到第一个有Previous_gtids_log_event的binlog为止；

当MySQL重启，且binlog_gtid_simple_recovery=true：

更新gtid_executed，只扫描最新的那个binlog，如果这个binlog不包含gtid，直接将GLOBAL.GTID_EXECUTED设置为空；更新gtid_purged，只扫描最旧的那个binlog，如果这个binlog不包含gtid，直接将GLOBAL.GTID_PURGED设置为空；

当删除binlog，且binlog_gtid_simple_recovery=false：

更新gtid_purged，从最旧的binlog开始扫描，直到找到第一个有Previous_gtids_log_event的binlog为止；

当删除binlog，且binlog_gtid_simple_recovery=true：

更新gtid_purged，只扫描最旧的那个binlog，如果这个binlog不包含gtid，直接将GLOBAL.GTID_PURGED设置为空；

另外还有一种情况就是relay_log_recovery=0的情况，扫描relay_log以更新all_gtids (Retrieved_Gtid_Set)

故障MySQL设置是binlog_gtid_simple_recovery=false，并且变更前是没有开启GTID的，意味着有一百多个binlog没有记录GTID，所以大量的读IO发生在扫描这一百多个binlog，符合故障现象。

再等等，好像有什么不对？我们的故障现场是binlog rotate（包括手工flush logs），和手册上描述的“MySQL重启”、“binlog被删除”不是一回事啊！

排除法：故障时MySQL并没有重启，那就是“binlog被删除”导致的了。

解到这里只剩最后一个问题了：binlog rotate（和手工flush logs）会导致binlog被删除吗？

答案是：expire_logs_days

再看下官方手册：

翻译一下就是：当开启了expire_logs_days，MySQL会自动删除binlog，触发条件是“启动”和“binlog的刷新”。

再次验证，在数据库中执行purge binary logs to 'mysql-bin.xxx'，观察strace，iotop能够稳定复现故障现象。

结论

MySQL由非GTID模式到开启GTID，之前的binlog（一百多个）都没有记录GTID。

开启GTID后，受参数expire_logs_days=5影响，每次binlog rotate时会触发binlog的自动删除，当binlog被删除时：

由于参数binlog_gtid_simple_recovery=false，MySQL会从头至尾扫描binlog直到找到第一个有Previous_gtids_log_event的binlog为止。最终造成了数据库阻塞。

解决方案

删除没有记录GTID的binlog，因为purge binary logs to 'xxx'命令会触发binlog扫描，所以这里只能使用rm方式进行删除，删除后将mysql-bin.index文件中对应的行删除，注意不留空行。

如何避免

最好是创建数据库时直接启用GTID，GTID的好处谁用谁知道；当MySQL由非GTID模式升级为开启GTID时：

1. 设置参数binlog_gtid_simple_recovery=true；

2. 重启MySQL后，备份binlog，执行reset master；

3. 运行后不要切换GTID模式，以免造成GTID的紊乱。

关注爱可生云数据库，一起交流更多数据库技术。