MySQL:主从binlog超过4G导致报错

2024-04-22 本文已影响0人重庆八怪

一、问题描述

最近遇到的问题，问题是在5.7上出现的，这个问题大概会有如下主要的报错，报错后主从中断

2024-04-23T09:54:45.586576+08:00 23 [ERROR] Slave I/O for channel '': Unexpected master's heartbeat data: inconsistent heartbeat event content; the event's data: log_file_name log_bin.000001k
log_pos 1(代表本次接收到心跳的位点), Error_code: 1623
2024-04-23T09:54:45.586608+08:00 23 [ERROR] Slave I/O for channel '': Relay log write failure: could not queue event from master, Error_code: 1595
2024-04-23T09:54:45.586612+08:00 23 [Note] Slave I/O thread exiting for channel '', read up to log 'log_bin.000001', position 154(代表io线程当前读取到的位置)

2024-04-23T11:10:29.466440+08:00 29 [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 log_bin.000001K4g_pos 21(代表本次接收到心跳的位点), Error_code: 1623
2024-04-23T11:10:34.388659+08:00 29 [ERROR] Slave I/O for channel '': Relay log write failure: could not queue event from master, Error_code: 1595
2024-04-23T11:10:34.388703+08:00 29 [Note] Slave I/O thread exiting for channel '', read up to log 'log_bin.000001', position 154(代表io线程当前读取到的位置)

其中它们的区别在于错误的第一句，但是其实本质上没有什么区别

inconsistent heartbeat event content，代表本次接收到心跳的位点必须大于4
heartbeat is not compatible with local info，代表io线程当前读取到的位置必须大于本次接收到心跳的位点

注意这里是模拟的

Slave I/O thread exiting for channel '', read up to log 'log_bin.000001', position 154

线上环境如果报错的话，报错中的postition一般会比较大，比如大于4G。报错后主从的状态显示如下，

                Last_IO_Error: Relay log write failure: could not queue event from master
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 333900
                  Master_UUID: e8eb8ce3-2ccb-11eb-832e-000c29621fc8
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 240423 11:10:34

二、问题分析

这个问题根据BUG的描述（BUG随后贴出），主要涉及到主从之间心跳event的发送，心跳发送时间和slave_net_timeout参数有关，默认slave_net_timeout为60秒，而所有主从通道心跳发送时间为30秒，也就是slave_net_timeout的一半，这样能够保证在主从超时之前心跳能够检测到，曾今有一个案例是建立主从通道后改小了slave_net_timeout参数，导致主从不断地重连，生成了大量relay log，如下，

MySQL：产生大量小relay log的故障一例
https://www.jianshu.com/p/0682472e9f22

具体的心跳时长可以查看channel的配置，如下

select CHANNEL_NAME,HEARTBEAT_INTERVAL from performance_schema.replication_connection_configuration;

心跳event是不会记录到relay log的，也就是io线程会将其处理，当处理的时候会通过发送过来的数据进行初始化和判断，如下

初始化的时候会判断发送的位点是否大于BIN_LOG_HEADER_SIZE(4字节，binlog文件开头的4个字节)，否则报错就是 inconsistent heartbeat event content

  if ((log_ident != NULL && header()->log_pos >= BIN_LOG_HEADER_SIZE)) //这里判定
    is_valid_param= true;

判断的时候会判定发送的位点和当前io线程接收到的位点，如果发送的心跳位点比当前接收的位点还要小就会报错，报错就是heartbeat is not compatible with local info

    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;
    }

那么问题就是什么时候dump线程在发送心跳event的时候位点出现错乱，这个问题实际上比较简单，就是当binlog文件大于4G的时候，因为发送的位点是一个uint32类型的，这里大于4G会出现截断，在Binlog_sender::send_heartbeat_event中我们很容易看到如下，

  int4store(header + SERVER_ID_OFFSET, server_id);
  int4store(header + EVENT_LEN_OFFSET, event_len);
  int4store(header + LOG_POS_OFFSET, static_cast<uint32>(log_pos));
  int2store(header + FLAGS_OFFSET, 0);

这里log_pos是一个unsigned long long类型的，而存储的时候转换为了unsigned int，肯定在大于4G的会出现截断，一旦截断后就会导致这种问题。

最后涉及到一个最重要的问题，什么时候发送心跳 event？

心跳event一般是在没有正常的event发送的时候才会去发送心跳event，也就是说当dump线程读取到当前binlog的末尾才会去发送心跳event，发送频率就是前面说的心跳时长。
启动主从时候，如果是包含了GTID，则会根据从库的GTID来判断哪些binlog event需要发送给从库，这个时候有一个过滤的过程，这个期间也需要不断地发送心跳event给从库来更新master postition位置，发送也取决于心跳时长。

但是我这里明显是正常的主从并没有重启过，那么考虑主要是第一点，主库切换binlog时间可能较长，因此遇到这个问题的机率并不会太大。

三、相关BUG和测试

这个问题已经是一个比较老的BUG了，但是一直没有修复，可能是考虑到兼容性的问题吧，如下，

https://bugs.mysql.com/bug.php?id=95418(腾讯报告，说明了原因)
https://bugs.mysql.com/bug.php?id=55231

测试比较简单，如果要模拟大事务确实比较困难，但是我们直接修改一下pos的位置，因此2的32次方最大为4294967296，因此我们修改为4294967297，就可以出现第一个错误，如果修改为4294967317就可以出现第二种错误。如下，

image.png

四、8036测试

接下来就是要测试一下MySQL的新版本是否也会如此，在测试中视乎有些许不同，最后在show slave status居然卡主了，但是没有做仔细分析了，但是报错依旧是如下，

2024-04-23T12:02:49.615140+08:00 10 [ERROR] [MY-013118] [Repl] Replica I/O for channel '': Unexpected source's heartbeat data: Replication heartbeat event contained the position 317 which is smaller than the position 4294967317 that was computed from earlier events received in the stream. The filename is 'mysql-bin.000035'. Error_code: MY-013118
2024-04-23T12:02:49.615310+08:00 10 [ERROR] [MY-013122] [Repl] Replica I/O for channel '': Relay log write failure: could not queue event from source, Error_code: MY-013122
2024-04-23T12:02:49.615352+08:00 10 [Note] [MY-010570] [Repl] Replica I/O thread exiting for channel '', read up to log 'mysql-bin.000035', position 4294967317

看来这个问题到最新版本依旧存在，但是发送心跳event的时机不知道有没有变化。

五、如果避免

避免大事务，大事务做拆分，不要让binlog大于4G，这是最好的办法
如果确实有大事务，并且经常导致binlog大于4G，并且经常遇到这个错误，可以考虑调大slave_net_timeout参数，重做主从。
报错后，如果是postition主从报错后重启可能都不行，但是GTID得主从应该可以重启解决，postition的主从无法发送大于4G以上的binlog位点，如下，

com_binlog_dump（传统基于位点的主从）
/*
    4 bytes is too little, but changing the protocol would break
    compatibility.  This has been fixed in the new protocol. @see
    com_binlog_dump_gtid(基于GTID AUTOPOSITION的主从).
  */