Binlog 中不完整的 Event 排查

容灾切换中的老鼠屎

机房级别容灾的场景下，单次的 db 切换数量高达 2000+，难免遭遇各种各样平时难以遇到的问题。例如，下面这两个问题就困扰了我们一段时间：

• 第一个问题是：sql_thread 无法正常 stop，导致切换失败
  在进行主备切换的时候，为了避免 sql_thread 写入和业务写入冲突，首先会 stop slave sql_slave。但是在 stop slave 的时候，有很小的概率会执行超时。

• 第二个问题是：slave status 中的位点无法对齐，导致切换速度慢
  在进行主备切换之前，会等待一段时间，让新主库把拉取到的 relaylog 消费掉，等待过程中会根据 slave status 中的位点状态来判断 relaylog 是否消费完成：
  但是有很小的概率会遇到这样的情况：无论等待多长时间，mlf.rmpl 和 rmlf.emlp 都不会对齐。

Name	Value	Discription
Master_Log_File(mlf)	mysql-bin.000106	io_thread 正在读取的 master 的 binlog 文件
Read_Master_Log_Pos(rmlp)	41956375	io_thread 读取到的 master 的 binlog 的位点
Relay_Master_Log_File(rmlf)	mysql-bin.000106	sql_thread 最新执行完成的 event 所在 master 的 binlog 文件
Exec_Master_Log_Pos(emlp)	41956375	sql_thread 最新执行完成的 event 所在 master 的 binlog 的位点

问题的定位和重现

根据切换日志中记录的 mlf.rmpl 和 rmlf.emlp，通过解析 binlog 发现，没有被消费的 binlog 其实是一个不完整的事务，没有 COMMIT(Xid EVENT)：

Name	Value
Master_Log_File	mysql-bin.000106
Read_Master_Log_Pos	80338810
Relay_Master_Log_File	mysql-bin.000106
Exec_Master_Log_Pos	80322348

为了复现备库接收到半个事务的场景，通过在主库进行端口限流来控制 binlog 的 dump 速度，从而重现问题

shell 
# tc qdisc add dev eth0 root handle 1: htb default 30 
# tc class add dev eth0 parent 1: classid 1:1 htb rate 8kbit burst 15k 
# tc filter add dev eth0 protocol ip parent 1:0 prio 1 u32 match ip sport 3307 0xffff flowid 1:1 

问题重现后不难发现，问题一和问题二的触发原因是相同的，binlog 中存在半个事务。
问题已发生的根本原因是，coordinate 线程 hang 住了。
解决方案

slave status 中的位点无法对齐，导致切换速度慢
rmlf.emlp 在 20s 内无任何变化时，认为 relaylog 执行到终点，进行切换的下一步。
sqlthread 无法正常 stop，导致切换失败
stop slave 超时后，kill 掉 replication 的 worker 线程。

MTS 工作原理介绍

• worker 线程和 sql 线程一样，会直接执行拿到的 event
• 当 stop slave 或 kill thread，没有 commit 的事务会被回滚