文章/答案/技术大牛

发布

社区首页 >专栏 >MySQL 主从复制 1594 报错分析

MySQL 主从复制 1594 报错分析

爱可生开源社区

发布于 2025-03-28 05:00:12

10900

代码可运行

文章被收录于专栏：爱可生开源社区爱可生开源社区

运行总次数：0

代码可运行

作者：陈伟，爱可生 DBA 团队成员，负责 MySQL 日常维护及故障处理。

爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

本文约 2600 字，预计阅读需要 8 分钟。

1. 故障背景

客户反馈 MySQL 主从复制出现故障，检查后发现 SQL 线程停止写入报错 1594，但 IO 线程仍能正常拉取日志。

在从库执行 reset slave 命令并重建复制后，主从复制恢复正常。下面分析此次报错的详细原因。

为了给予客户更全面的的解答，本次采取全面排查的方式，逐个分析所有可能导致该故障的因素，找出最有可能引发此次故障的原因，以给客户提供一个准确的解释。

以下是本次故障分析的思路。

2. 故障分析

MySQL 版本：5.7.26，GTID 已启用。

2.1 查看从库报错信息

mysql> show slavestatus\G
*************************** 1.row ***************************
               Slave_IO_State: Waiting formasterto send event
                  Master_Host: xx.xx.xx.xx
                  Master_User: universe_op
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.xxxxxx
          Read_Master_Log_Pos: xxxxxx
               Relay_Log_File: mysql-relay.xxxxxx
                Relay_Log_Pos: 243865
        Relay_Master_Log_File: mysql-bin.xxxxxx
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1594
                   Last_Error: Relay logreadfailure: Could notparse relay logevent entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay logis corrupted (you can check this by running 'mysqlbinlog'on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want tocheck the master's binary log or slave's relay log, you will be able to know their namesby issuing 'SHOW SLAVE STATUS'on this slave.
                 Skip_Counter: 0

根据 show slave status\G 得到主从报错的信息，我们可以很明确，读取 relay log 失败，无法解析中继日志中的事务。

2.2 查看从库错误日志

查看从库对应时间点的错误日志。

2024-12-29T00:22:19.824988+08:00 241186 [ERROR] Error in Log_event::read_log_event(): 'Event crc check failed! Most likely there is event corruption.', data_len: 8060, event_type: 31
2024-12-29T00:22:19.825014+08:00 241186 [ERROR] Error reading relay log event for channel '': slave SQL thread aborted because of I/O error
2024-12-29T00:22:19.825027+08:00 241186 [ERROR] Slave SQL for channel '': Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave. Error_code: 1594
2024-12-29T00:22:21.146920+08:00 241186 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.053394' position 264587564.

根据错误日志中的报错信息，我们可以得到一些关键信息如下:

2024-12-29T00:22:19.824988+08:00 241186 [ERROR] Error in Log_event::read_log_event(): 'Event crc check failed! Most likely there is event corruption.', data_len: 8060, event_type: 31
# 可以发现有 Event crc check failed 信息输出，这个错误通常表示日志事件的 CRC 校验失败，可能是由于事件的数据损坏或日志文件不完整。
# 当从库读取中继日志时，如果发生 CRC 校验错误，是可能导致从库的 SQL 线程中止，并报错 Relay Log Read Failure
2024-12-29T00:22:19.825027+08:00 241186 [ERROR] Slave SQL for channel '': Relay log read failure: Could not parse relay log event entry......... Error_code: 1594

根据错误日志得到的信息，可以发现存在日志事件的 CRC 校验失败。CRC 校验失败通常意味着数据在传输或存储过程中发生了损坏，可能的原因包括磁盘故障、网络问题、MySQL 服务异常关闭或者主库的 binlog 文件损坏或者从库的 relay log 损坏，从而导致无法解析中继日志中的事务。

2.3 进一步排查可能中断的原因

首先检查一下对应时间点的系统日志，没有异常信息输出，排除磁盘故障，也未发现报错时段的 MySQL OOM 信息。

排查是否是事务过大，比如事务超过 max_allowed_packet 限制，发生的分片写入错误。

根据中断时的最后一个 gtid 信息可得在写 019edbbe-8c87-11ee-a06d-005056943f0f:625715013 时 SQL 线程中断。计算该 gtid 事务的大小，根据计算得出该事务大小为 20M，本次故障排除事务过大导致。

最后检查了主库故障时间点的 MySQL 服务状态以及对应时间主库的 binlog 文件，并没有发现任何异常，同时查看故障时间点的网络监控，也是正常的。

到这基本很明确是 relay log 这边出现了问题，从而导致无法解析中继日志中的事务。由于客户环境未能保留报错时的 relay log ，所以只能去通过自己的环境去复现客户故障，并与客户故障环境已采集的信息作比对。

2.4 本地环境复现

查看当前环境主从状态。

mysql> show slavestatus\G
*************************** 1.row ***************************
               Slave_IO_State: Waiting formasterto send event
                  Master_Host: 10.186.63.44
                  Master_User: universe_op
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 3527783
               Relay_Log_File: mysql-relay.000003
                Relay_Log_Pos: 10303
        Relay_Master_Log_File: mysql-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:

手动关闭 SQL 线程。

mysql> STOP SLAVE SQL_THREAD;
Query OK, 0 rows affected (0.00 sec)

查看当前复制状态。

mysql> show slavestatus\G
*************************** 1.row ***************************
               Slave_IO_State: Waiting formasterto send event
                  Master_Host: 10.186.63.44
                  Master_User: universe_op
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 3510430
               Relay_Log_File: mysql-relay.000004
                Relay_Log_Pos: 12695
        Relay_Master_Log_File: mysql-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: No

再次查看复制状态。

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.186.63.44
                  Master_User: universe_op
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 3560144
               Relay_Log_File: mysql-relay.000007
                Relay_Log_Pos: 4675
        Relay_Master_Log_File: mysql-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: No

此刻观察到环境信息与客户环境一致，SQL 线程停止写入，IO 线程正常拉取日志。

模拟 SQL 线程故障：使用 hexedit[1] 编辑 relay log 文件。

hexedit mysql-relay.000007

开启 SQL 线程查看复制状态。

mysql> START SLAVE SQL_THREAD;
Query OK, 0 rows affected (0.02 sec)

mysql> showslavestatus\G
*************************** 1.row ***************************
               Slave_IO_State: Waiting formasterto send event
                  Master_Host: 10.186.63.44
                  Master_User: universe_op
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 32050487
               Relay_Log_File: mysql-relay.000007
                Relay_Log_Pos: 243865
        Relay_Master_Log_File: mysql-bin.000001
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1594
                   Last_Error: Relay logreadfailure: Could notparse relay logevent entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay logis corrupted (you can check this by running 'mysqlbinlog'on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want tocheck the master's binary log or slave's relay log, you will be able to know their namesby issuing 'SHOW SLAVE STATUS'on this slave.
                 Skip_Counter: 0

查看 MySQL 报错信息。

024-12-31T09:34:36.385535+08:00 1448 [ERROR] Error in Log_event::read_log_event(): 'Event crc check failed! Most likely there is event corruption.', data_len: 80, event_type: 31
2024-12-31T09:34:36.385593+08:00 1448 [ERROR] Error reading relay log event for channel '': slave SQL thread aborted because of I/O error
2024-12-31T09:34:36.385608+08:00 1448 [ERROR] Slave SQL for channel '': Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave. Error_code: 1594
2024-12-31T09:34:36.386764+08:00 1448 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000001' position 3795113.

至此，通过上面的排除法，以及通过比对本地环境复现的报错信息，可明显判断导致 1594 报错的原因是：在传输或者写入 relay log 的过程中，中继文件意外发生了损坏，从而导致 SQL 线程无法拉取中继日志。

2.5 继续解析 relay log

下面我们解析一下 relay log ，看一下有哪些报错的提示信息输出，并进行总结。

首先先解析 relay log 查看报错，可以正常解析，看不出来什么异常。

# at 243865
#241231  1:12:35 server id 675216691  end_log_pos 3795178 CRC32 0x886c766d      GTID    last_committed=8108     sequence_number=8109    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ee2fddba-c6c7-11ef-8e2a-02000aba3f2c:8109'/*!*/;
# at 243930
#241231  1:12:35 server id 675216691  end_log_pos 3795254 CRC32 0x31082f91      Query   thread_id=71    exec_time=0     error_code=0
SET TIMESTAMP=1735578755/*!*/;
BEGIN;44006
#241231  1:12:35 server id 675216691  end_log_pos 3795412 CRC32 0xd1baa47b      Rows_query
# /*ustats-10-186-63-44*/update universe.u_delay set real_timestamp=now(), logic_timestamp = logic_timestamp + 1 where source = 'ustats'
# at 244164
#241231  1:12:35 server id 675216691  end_log_pos 3795471 CRC32 0x9b859b01      Table_map: `universe`.`u_delay` mapped to number 211
# at 244223
#241231  1:12:35 server id 675216691  end_log_pos 3795551 CRC32 0x69696969      Update_rows: table id 211 flags: STMT_END_F
BINLOG '/T4ongAAANTpOQCAAIYvKnVzdGF0cy0xMC0xODYtNjMtNDQqL3VwZGF0ZSB1bml2ZXJz
ZS51X2RlbGF5IHNldCByZWFsX3RpbWVzdGFtcD1ub3coKSwgbG9naWNfdGltZXN0YW1wID0gbG9n
aWNfdGltZXN0YW1wICsgMSB3aGVyZSBzb3VyY2UgPSAndXN0YXRzJ3ukutE=
g9RyZxMz/T4oOwAAAA/qOQAAANMAAAAAAAEACHVuaXZlcnNlAAd1X2RlbGF5AAMPEggD+AIABgGb
hZs=Zx8z/T4oUAAAAF/qOQAAANMAAAAAAAEAAgAD///4BgB1c3RhdHOZtT4TIkQfAAAAAAAA+AYA
dXN0YXRzmbU+aWlpaWlpaWlpaWlpaWk=
'/*!*/;ATE `universe`.`u_delay`
### WHERE
###   @1='ustats' /* VARSTRING(760) meta=760 nullable=0 is_null=0 */
###   @2='2024-12-31 01:12:34' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
###   @3=8004 /* LONGINT meta=0 nullable=1 is_null=0 */
### SET1='ustats' /* VARSTRING(760) meta=760 nullable=0 is_null=0 */
###   @2='2024-12-31 06:37:41' /* DATETIME(0) meta=0 nullable=1 is_null=0 */
###   @3=7595718147998050665 /* LONGINT meta=0 nullable=1 is_null=0 */
# at 244303
#241230 17:35:37 server id 675216691  end_log_pos 3795582 CRC32 0x48e0358c      Xid = 85886
COMMIT/*!*/;

由于可以正常解析，那么我们就通过 MySQL 自带的 mysqlbinlog 来验证 relay log 中故障时间点前后事件的 CRC，看看有没有什么异常信息输出。

命令及输入如下：

mysqlbinlog --verify-binlog-checksum mysql-relay.000007

查看输出内容：

# at 243865
#241231  1:12:35 server id 675216691  end_log_pos 3795178 CRC32 0x886c766d      GTID    last_committed=8108     sequence_number=8109    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ee2fddba-c6c7-11ef-8e2a-02000aba3f2c:8109'/*!*/;
# at 243930
#241231  1:12:35 server id 675216691  end_log_pos 3795254 CRC32 0x31082f91      Query   thread_id=71    exec_time=0     error_code=0
SET TIMESTAMP=1735578755/*!*/;
BEGIN
/*!*/;
# at 244006
# at 244164
#241231  1:12:35 server id 675216691  end_log_pos 3795471 CRC32 0x9b859b01      Table_map: `universe`.`u_delay` mapped to number 211
ERROR: Error in Log_event::read_log_event(): 'Event crc check failed! Most likely there is event corruption.', data_len: 80, event_type: 31
ERROR: Could not read entry at offset 244223: Error inlog format or read error.
WARNING: The range of printed events ends with a row event or a table map event that does not have the STMT_END_F flag set. This might be because the last statement was not fully written to the log, or because you are using a --stop-position or --stop-datetime that refers to an event in the middle of a statement. The event(s) from the partial statement have not been written to output.