背景
在大型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为止。最终造成了数据库阻塞。
MySQL5.7.6以后,binlog_gtid_simple_recovery默认值为true,并且无论GTID是否开启,扫描binlog的行为如文中解释只与binlog_gtid_simple_recovery参数以及binlog中是否记录gtid有关。 举例:mysql5.7.7版本,从未开启gtid,binlog_gtid_simple_recovery=false,当binlog回收时,也会导致扫描全部binlog造成阻塞。 所以,mysql5.7.6之后,binlog_gtid_simple_recovery使用默认值即可。
解决方案
删除没有记录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的紊乱。