MySQL 主从复制 1594 报错分析

wd123_cn • • 新闻资讯 • 阅读 7

图片

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

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

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

1. 故障背景

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

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

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

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

2. 故障分析

MySQL 版本：5.7.26，GTID 已启用。

2.1 查看从库报错信息

mysql> show slavestatusG*************************** 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 statusG 得到主从报错的信息，我们可以很明确，读取 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: 312024-12-29T00:22:19.825014+08:00 241186 [ERROR] Error reading relay log event for channel '': slave SQL thread aborted because of I/O error2024-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: 15942024-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 Failure2024-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 slavestatusG*************************** 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 slavestatusG*************************** 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 statusG*************************** 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> showslavestatusG*************************** 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: 312024-12-31T09:34:36.385593+08:00 1448 [ERROR] Error reading relay log event for channel '': slave SQL thread aborted because of I/O error2024-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: 15942024-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=0SET 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_FBINLOG '/T4ongAAANTpOQCAAIYvKnVzdGF0cy0xMC0xODYtNjMtNDQqL3VwZGF0ZSB1bml2ZXJzZS51X2RlbGF5IHNldCByZWFsX3RpbWVzdGFtcD1ub3coKSwgbG9naWNfdGltZXN0YW1wID0gbG9naWNfdGltZXN0YW1wICsgMSB3aGVyZSBzb3VyY2UgPSAndXN0YXRzJ3ukutE=g9RyZxMz/T4oOwAAAA/qOQAAANMAAAAAAAEACHVuaXZlcnNlAAd1X2RlbGF5AAMPEggD+AIABgGbhZs=Zx8z/T4oUAAAAF/qOQAAANMAAAAAAAEAAgAD///4BgB1c3RhdHOZtT4TIkQfAAAAAAAA+AYAdXN0YXRzmbU+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 = 85886COMMIT/*!*/;

由于可以正常解析，那么我们就通过 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=0SET 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 211ERROR: Error in Log_event::read_log_event(): 'Event crc check failed! Most likely there is event corruption.', data_len: 80, event_type: 31ERROR: 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.

发现有 CRC 报错输出，relay log 读取报错原因是 最后一个事务未完整写入。

3. 总结

首先，在进行 MySQL 故障处理时，应先尽量保留下必要的信息以方便后续排查具体的原因，再去处理故障、恢复业务。其次，针对 1594 主从故障，一般情况有以下几个原因导致，我们可以针对可能导致的原因并结合数据库的错误日志进行进一步排查和修复。

  • 中继日志文件损坏：磁盘故障、非正常关机导致文件损坏。

  • 磁盘空间不足：从库无法写入新的事件到中继日志。

  • 主库日志丢失：主库清理了未同步的二进制日志，导致从库请求的日志位置失效。

  • 权限或路径错误：MySQL 进程无权访问中继日志文件，或路径配置错误。

参考资料

[1]

hexedit: https://hexed.it/

图片

  推荐阅读：

  • 悟了：MySQL原来是这样执行SQL的！

  • 如何准确获取 MySQL 主从延迟时间？

  • Mysql 是什么？架构是怎么样的？

  • MySQL 索引失效了吧

  • MySQL探秘之旅：绕不开的数据库事务

    • 赞 (0)
    wd123_cnwd123_cn
    上一篇 2025年3月29日 下午1:24
    下一篇 2025年3月29日 下午1:25

    相关文章