1 / 背景
一个主实例下面挂了7个只读实例,其中6个只读实例在相同时间报错误,我们分析了6个报错只读实例,他们报错信息一样都是1236错误:Last_IO_Error: Got fatal error 1236 from master when reading data from binary log[此处省略,后面详细分析],也确认了其中1个没有报错的只读实例,下面分析这个错误的排查过程。
2 / 排查过程
查询从库同步状态和信息。
执行show slave status
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'binlog truncated in the middle of event; consider out of disk space on master; the first event '' at 4, the last event read from '/data/mysql_root/log/20131/mysql-bin.001134' at 724213715, the last byte read from '/data/mysql_root/log/20131/mysql-bin.001134' at 724213760.'
首先分析这个现象表示什么错误?
从收到来自master的一个致命错误:
分析主库binlog。
[root@TENCENT64 /data/mysql_root/log/20131]# /data1/mysql_root/base_phony/20131/bin/mysqlbinlog --base64-output=DECODE-ROWS --start-position=724213715 mysql-bin.001134|less
binlog实际上由一个个不同类型的binlog event组成,每个at为一个event,每个binlog event还包含了event header部分和event data部分。通过分析下这段binlog可知道主库 event从724213715开始到724214527完成,但在传输过程中,从库接收到724213760就结束了【为了方便我们只看后四位】,3760属于3715-4527之间说明从库接收到的只是部分事件,并没有完整接收到全部。思考为什么mysql会知道自己没有接受完整的event报错呢?其实是因为每个event最后还有4bytes的校验位【event中footer包含校验值和算法描述】,如果对不上就会判定报错。
思考两个问题:
问题一:什么情况下会出现事件只传输一部分呢?
问题二:为什么是IO线程中断?
怀疑【主库】binlog是不是出现损坏——从6个从库同步都中断了,1个从库好的就可以判定【主库】binlog没有损坏。
怀疑主库网络抖动造成IO线程中断——进一步分析。
查询主库监控发现重传的报文数量【RetransSegs】有增加
进一步去看秒级监控分析下主库网络:可知10:58:25到11:00:20间主库Bytes_sent突降。
Bytes_received:接受的字节数
Bytes_sent:发送的字节数
通过监控定位到Bytes_sent值突然降下来,网络出现了约2分钟的异常,网络异常会导致IO线程中断,我们再详细分析下这个错误:
通过‘binlog truncated in the middle of event; consider out of disk space on master; ’查询调用了rpl_matser.cc下的LOG_READ_TRUNC;继续往下看数据库在做什么?
我们大概可知如果从库会去校验event传输是否完整,如果主库传输event不完整的话,会报出一个致命错误,并且把读取的最后位置详细说明,这就是我们看到的:binlog truncated in the middle of event; consider out of disk space on master; the first event '' at 4, the last event read from '/data/mysql_root/log/20131/mysql-bin.001134' at 724213715, the last byte read from '/data/mysql_root/log/20131/mysql-bin.001134' at 724213760.
然而很难保证网络永远是一直持续正常。我们也会去思考:为什么网络抖动IO线程断开,难道master没有重新发包吗?
master有尝试重试推送包的,slave也有尝试重连master,这时候线程应该还是正常但是重试了多次【这个次数不确定?怀疑是Retry_count次数限制:默认20次】仍是持续丢包从而调用io_slave_killed将IO线程kill掉。其实中间任意一次传输成功都会正常的。
下面这段表示主库有尝试重传包:
从库也有尝试重连主库,从库尝试重连20次仍然失败则kill掉IO线程:
比较修改一行和修改多行event大小:
MySQL [sissi_01]> update t_b set n1='cccccccc' limit 1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
at 202943
190516 18:35:05 server id 179395 end_log_pos 203026 Update_rows: table id 344 flags: STMT_END_F
203026-202943=83
--------
MySQL [sissi_01]> update t_b set n1='sssssss';
Query OK, 3072 rows affected (0.06 sec)
Rows matched: 3072 Changed: 3072 Warnings: 0
at 194787
190516 18:33:17 server id 179395 end_log_pos 202739 Update_rows: table id 344 flags: STMT_END_F
202739-194787=7952
测试后可以大致推断,业务可以使event 开始和结束的pos点差距变小,如果event差距很小,同步传输报错“binlog truncated in the middle of event; consider out of disk space on master;”的触发可能性就比较小了。
3 / 思考&&小结
思考
理论上如果event差距很小可以一定程度避免这个错误,云上这点可能比较难控制。
如果重试的次数够多也可以解决,待内核确认是否可行。
解决操作
stop slave;start slave;【可以考虑运维检测到这个报错,脚步自动跑】