1236错误场景分析

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；【可以考虑运维检测到这个报错，脚步自动跑】

转载于:https://www.cnblogs.com/sallyluo/p/11307510.html