< 返回技术文档列表

binlog rotate引发的MySQL阻塞事件

发布时间:2017-06-27 发布人:huchengqing

背景

在大型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)

1510625381448941.png

1510625381859944.png


查得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信息中大量重复的文件句柄号:

1510625381990810.png


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

1510625381479546.png


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

1510625381130368.png


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

1510625655153270.png


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

扫描脑子里的知识库:binlog_gtid_simple_recovery

以下是MySQL官方手册解释:

blob.png

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


当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文件中对应的行删除,注意不留空行。

blob.png

如何避免

  • 最好是创建数据库时直接启用GTID,GTID的好处谁用谁知道;

  • 当MySQL由非GTID模式升级为开启GTID时:

1. 设置参数binlog_gtid_simple_recovery=true

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

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


在线咨询
免费电话
返回顶部