MySQL 主从复制异常报错案例一：heartbeat is not compatible with local info

由于个人能力有限，文中可能存在错误，并且很多细节没有深入分析，欢迎批评指正。

1.问题描述

记一次 IO 复制异常案例，某系统线上 1 套 MySQL 集群从库在最近一周每天22时57分左右都会发生 IO 复制线程中断的问题，查看 MySQL 日志记录的 error 信息为 “heartbeat is not compatible with local info”，初步判断跟主从复制心跳有关，DBA 通过命令启用 IO 复制线程即可恢复。

2.日志分析

2.1.主库日志

1）日志信息如下：

2021-09-11T22:54:02.307477+08:00 7337734 [Warning] Timeout waiting for reply of binlog (file: mysql-bin.001050, pos: 8081671672), semi-sync up to file mysql-bin.001050, position 234.
2021-09-11T22:55:15.606620+08:00 0 [ERROR] Read semi-sync reply magic number error
2021-09-11T22:55:15.607093+08:00 0 [ERROR] /usr/local/mysql/bin/mysqld: Got an error reading communication packets
2021-09-11T22:55:36.919916+08:00 7333647 [Warning] Timeout waiting for reply of binlog (file: mysql-bin.001050, pos: 25398346083), semi-sync up to file mysql-bin.001050, position 8081671672.
...
2021-09-12T22:54:48.389928+08:00 7533299 [Warning] Timeout waiting for reply of binlog (file: mysql-bin.001078, pos: 8081671672), semi-sync up to file mysql-bin.001078, position 234.
2021-09-12T22:56:02.291112+08:00 0 [ERROR] Read semi-sync reply magic number error
2021-09-12T22:56:02.291666+08:00 0 [ERROR] /usr/local/mysql/bin/mysqld: Got an error reading communication packets
2021-09-12T22:56:23.248059+08:00 7529261 [Warning] Timeout waiting for reply of binlog (file: mysql-bin.001078, pos: 25398613574), semi-sync up to file mysql-bin.001078, position 8081671672.
...
2021-09-13T22:54:29.329231+08:00 7728527 [Warning] Timeout waiting for reply of binlog (file: mysql-bin.001106, pos: 8081671672), semi-sync up to file mysql-bin.001106, position 234.
2021-09-13T22:55:43.308640+08:00 0 [ERROR] Read semi-sync reply magic number error
2021-09-13T22:55:43.308954+08:00 0 [ERROR] /usr/local/mysql/bin/mysqld: Got an error reading communication packets
2021-09-13T22:56:04.073410+08:00 7724514 [Warning] Timeout waiting for reply of binlog (file: mysql-bin.001106, pos: 25399063738), semi-sync up to file mysql-bin.001106, position 8081671672.

2）分析
主库日志打印半同步复制异常信息：

• Read semi-sync reply magic number error

• Got an error reading communication packets

这里为半同步复制的异常，也是 IO 复制线程中断引起的，并不是根因，所以这里主库日志记录的异常暂可忽略。

2.2.从库日志

1）日志信息如下：

2021-09-13T22:55:43.306352+08:00 1 [ERROR] Slave I/O for channel '': Unexpected master's heartbeat data: heartbeat is not compatible with local info; the event's data: log_file_name mysql-bin.001106ùÁò! log_pos 3786704376, Error_code: 1623
2021-09-13T22:55:43.313095+08:00 1 [ERROR] Slave I/O for channel '': Relay log write failure: could not queue event from master, Error_code: 1595
2021-09-13T23:01:03.132595+08:00 94910 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.

2）分析
从库日志打印IO复制线程异常信息：

• MySQL Error_code: 1623 ER_SLAVE_HEARTBEAT_FALLURE Unexpected master's heartbeat data:%s

• MySQL Error_code: 1595 ER_SLAVE_RELAY_LOG_WRITE_FALLURE Relay log write failure:%s

这里需要重点关注下，从错误信息字面意思来看，跟心跳有关，显示“心跳与本地信息不兼容”。再通过报错信息，定位源码内容，如下：

ER_SLAVE_HEARTBEAT_FALLURE 源码（rpl_slave.cc，第8339行到第8364行）

/* 
      compare local and event's versions of log_file, log_pos.
       
      Heartbeat is sent only after an event corresponding to the corrdinates
      the heartbeat carries.
      Slave can not have a difference in coordinates except in the only
      special case when mi->get_master_log_name(), mi->get_master_log_pos() have never
      been updated by Rotate event i.e when slave does not have any history
      with the master (and thereafter mi->get_master_log_pos() is NULL).

      TODO: handling `when' for SHOW SLAVE STATUS' snds behind
   */
   if (memcmp(const_cast<char *>(mi->get_master_log_name()),
              hb.get_log_ident(), hb.get_ident_len())
       || (mi->get_master_log_pos() > hb.common_header->log_pos))
   {
     /* missed events of heartbeat from the past */
     char errbuf[1024];
     char llbuf[22];
     sprintf(errbuf, "heartbeat is not compatible with local info; "
             "the event's data: log_file_name %-.512s log_pos %s",
             hb.get_log_ident(), llstr(hb.common_header->log_pos, llbuf));
     mi->report(ERROR_LEVEL, ER_SLAVE_HEARTBEAT_FAILURE,
                ER(ER_SLAVE_HEARTBEAT_FAILURE), errbuf);
     goto err;
   }

从源码内容来看，如果接收的 position 小于当前的 position，心跳机制会检查到这个变化，认为是错过获取过去的事件心跳，返回报错。

ER_SLAVE_RELAY_LOG_WRITE_FALLURE 源码（rpl_slave.cc，第5789行到第5798行）

/* XXX: 'synced' should be updated by queue_event to indicate
        whether event has been synced to disk */
   bool synced= 0;
   if (queue_event(mi, event_buf, event_len))
   {
       mi->report(ERROR_LEVEL, ER_SLAVE_RELAY_LOG_WRITE_FAILURE,
                  ER(ER_SLAVE_RELAY_LOG_WRITE_FAILURE),
                  "could not queue event from master");
       goto err;
   }

3.系统业务

与项目组沟通，获悉该系统每晚均会执行数据交换任务，全量数据写入当天最新的数据，该数据主要提供给报表平台进行业务报表展示。同时，对应写入的表数据量都是千万级，属于批量大事务执行。根据告警时间，定位到具体的数据交换任务。项目组调整任务时间，错开执行，未再出现 IO 复制异常的问题。

从任务执行情况来看，两个大事务基本是在比较接近的时间结束提交，同时结合源码内容，推测IO复制线程中断问题与两个大事务的 position 有关系，也就是其中一个事务发送到从库，下一个事务 position 小于前一个事务的 position 。

4.事件分析

目前配置的 binlog size 最大为 1G ，正常一个大事务执行完成后，会直接切换到下一个日志文件，除非是两个大事务几乎是在同一时间提交，分在同一个提交组，则可能会出现两个大事务写在同一个 binlog 文件。

其次，binlog event 的头结构 next_position 的字段长度只有4字节，也就是说该字段的最大值为 2 的 31 次方，也就是 4G，当前 binglog 的位置大于 4G 时，该字段就会溢出，这也就导致了 binlog event 传输时，next_position 突然会变小，心跳机制会检查到这个变化，产生报错。

官方之前也有类似BUG反馈，错误95418。

5.处理方式

1）对大事务进行拆分；
2）调整大事务任务执行时间。

参考资料

【1】《第29问：MySQL 的复制心跳说它不想跳了》