问题

最近年底,大家的数据库经常跑批量大事务,会发现复制突然断开,报错“心跳与本地信息不兼容”:

会是什么原因?

实验

我们先来复现一下,再进行分析。 

宽油,做一对主从数据库:

我们先造一个 500M 的空文件,下一步有用:

再制造一张大表,这里用到了之前的造表法,不同的是使用了一个 longblob 字段,让少数的几行记录就能占用很大的 binlog 空间,方便我们后面做实验。

这里的 longblob 字段,用到了上一步我们做的空文件,

这样我们获得了一个行数较少,但体积很大的表。

现在起两个会话,一个事务造表 t2,一个事务造表 t3,并同时提交操作,以下举例其中一个事务:

这样就获得了一个超大的 binlog,一共 32G,前 16G 是一个事务,后 16G 是另一个事务。

小贴士

一个事务超过 binlog 的限制大小(最大 1G),就会在事务后直接切换到新的 binlog。

在同一个 binlog 中,我们想让一个超大事务后再记录一个事务,所以让两个事务同时提交,放在同一个提交组中。

查看一下 master 上的 GTID,最后两个事务分别是 25 和 26:

下面登录到 slave上,开始表演:

我们先重置 GTID 和复制状态,然后骗 slave 说它已经接到了 1-25 事务,要从 26 号事务开始传输,也就是从 32G binlog 的中间位置开始传输。

然后开始复制的 IO 线程,过十几秒,就可以看到复制报错:

查看 Error log:

和我们想要复现的报错一样。

下面我们来看一下原理:

这个复现中有几个要素:

1. 从报错得知,报错与心跳有关,复制线必须配置复制心跳。
2. 一个 binlog 中包含两个事务,第一个事务超过 4G。(我们在复现中为了方便,将第二个事务也做成了大事务,这一点不是必须的)。
3. 从大事务后的位置,开始进行 binlog 复制传输。

我们用 tcpdump 抓个包:

用 wireshark 解开抓包,找到有问题的包(这里怎么找,我们分析后会有方法):

我们来分析一下包结构,这里我们将包的内容誊写下来,方便大家阅读:

首先阅读,https://dev.mysql.com/doc/internals/en/mysql-packet.html,了解 MySQL 的客户端网络包头结构:

将我们的包对应上去:

其后的一位 00,是 MySQL 的 command type(https://dev.mysql.com/doc/internals/en/command-phase.html),在此没有意义,我们将其忽略,

再继续阅读,https://dev.mysql.com/doc/internals/en/event-header-fields.html,了解 binlog event 的头结构如下:

将我们的包对应上去:

接下来是个字符串,明显是一个 binlog 的名字,最后四个字节(下图中用黄色标注)是 checksum,

至此我们完成了一个心跳包的解析,并没有看出严重的问题,不妨往前再找一个心跳包看看规律:

我将重点在图中标注,就是 next_position 的位置,在这个包中为 0xfa000557,而其下一个包中为 0x19400583,明显后面的 next_position 比前面的 next_position 小,这个不符合常理。

而 MySQL 的报错 heartbeat is not compatible with local info,也是在报这个问题:心跳包中的 position 不应比当前的 position 小。

那是什么导致了这个问题,我们注意到 next_position 的字段长只有 4 字节:

也就是说,该字段最大值为 2 的 31 次方,也就是 4G,当前 binlog 的位置大于 4G 时,该字段就会溢出。也就是说,之前我们看到的位置 0x19400583,实际丢掉了最高的一位,应当是 0x119400583。

这也就导致了 binlog event 传输时,next_position 突然会变小,心跳机制会检查到这个变化,产生报错。

那我们怎么解决这个问题?

目前可能的方法有以下两种:

1. 别用大事务,别用大事务,别用大事务。数据库系统本来就不是为大事务设计的,总会踩到不少坑。
2. 停用心跳机制,这个问题并不是心跳机制带来的问题,每个 binlog event 都会带有这个包头。只是心跳机制让问题暴露了出来。如果关掉,提出问题的心跳机制,那么复制对于网络故障就会不敏感,导致更大的问题。这种方式不推荐使用。

复盘

因为文章比较长,我们对逻辑进行一下复盘:

1. 我们通过抓包分析,知道 binlog 传输的网络包里,next_position 只有 4 个字节,最大数值为 4G。

2. 我们在 master 上做了一个超过 4G 的大事务,让 slave 从这个大事务后开始传输。此时 master 会发送一个心跳包。

3. 心跳包中的 next_position 是 log event 在 binlog 位置,由于这个位置大于 4G,会被截断,导致 next_position 比实际的小。

slave 收到心跳包,进行检测时发现 next_position 比实际的小,进行报错。

以上只是一种容易复现问题的场景。实际使用中,master 在一段时间不发送数据包后,或者特殊触发条件,都会发送心跳包。

对于一主多从的环境,每条复制链路的心跳是单独发送的,也就会导致多个 slave 的表现会有所不同,有的 slave 会触发报错,有的 slave 由于 master 没发送心跳包而不会触发报错。

最后送上几个小贴士:


1)我们如何快速找到有问题的包?

报错信息里已经标志了出错的 log position 是 423626115,转换成 16 进制为:0x19400583,找到由此数据的包即可。


2)一位一位读包太麻烦了,怎么办?

好办,先找到 server_id 的十六进制形式,以此为基准往后推定位数就可以。

比如我们的 server_id 是 19327,很容易找到基准位置。


3)报错里有一段乱码是啥?

最后这四位,是 MySQL 程序有缺陷,将包中的 checksum 作为文件名输出了,对程序逻辑没有影响。

0x11 是 17,对应 ASCII 码 “device control 1 character”,键盘表达形式是 “ctrl + Q”,打印形式就是 “^Q”。


本文相关的 MySQL 的 bug 列表:

https://bugs.mysql.com/bug.php?id=101948

https://bugs.mysql.com/bug.php?id=101955

关于 MySQL 的技术内容,你们还有什么想知道的吗?赶紧留言告诉小编吧!