
作者:陈伟,爱可生 DBA 团队成员,负责 MySQL 日常维护及故障处理MySQL 。
爱可生开源社区出品,原创内容未经授权不得随意使用,转载请联系小编并注明来源MySQL 。
本文约 2600 字,预计阅读需要 8 分钟MySQL 。
1. 故障背景
客户反馈 MySQL 主从复制出现故障,检查后发现 SQL 线程停止写入报错 1594,但 IO 线程仍能正常拉取日志MySQL 。
在从库执行 reset slave命令并重建复制后,主从复制恢复正常MySQL 。下面分析此次报错的详细原因。
为了给予客户更全面的的解答,本次采取全面排查的方式,逐个分析所有可能导致该故障的因素,找出最有可能引发此次故障的原因,以给客户提供一个准确的解释MySQL 。
以下是本次故障分析的思路MySQL 。
2. 故障分析
MySQL 版本:5.7.26,GTID 已启用MySQL 。
2.1 查看从库报错信息mysql> showslavestatus\G
*************************** 1.row***************************
Slave_IO_State: Waiting formastertosend 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_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 notparserelay logevententry. 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 logiscorrupted (you can checkthis byrunning 'mysqlbinlog'onthe relay log), a network problem, ora bug inthe master's or slave's MySQL code. Ifyou want tocheckthe master's binary log or slave's relay log, you will be able toknow their namesbyissuing 'SHOW SLAVE STATUS'onthis slave.
Skip_Counter: 0
根据 show slave status\G得到主从报错的信息,我们可以很明确,读取 relay log 失败,无法解析中继日志中的事务MySQL 。
2.2 查看从库错误日志
查看从库对应时间点的错误日志MySQL 。
根据错误日志中的报错信息MySQL ,我们可以得到一些关键信息如下:
#可以发现有 Event crc check failed 信息输出,这个错误通常表示日志事件的 CRC 校验失败,可能是由于事件的数据损坏或日志文件不完整MySQL 。
#当从库读取中继日志时MySQL ,如果发生 CRC 校验错误,是可能导致从库的 SQL 线程中止,并报错 Relay Log Read Failure
根据错误日志得到的信息,可以发现存在日志事件的 CRC 校验失败MySQL 。CRC 校验失败通常意味着数据在传输或存储过程中发生了损坏,可能的原因包括磁盘故障、网络问题、MySQL 服务异常关闭或者主库的 binlog 文件损坏或者从库的 relay log 损坏,从而导致无法解析中继日志中的事务。
2.3 进一步排查可能中断的原因
首先检查一下对应时间点的系统日志,没有异常信息输出,排除磁盘故障,也未发现报错时段的 MySQL OOM 信息MySQL 。
排查是否是事务过大,比如事务超过 max_allowed_packet限制,发生的分片写入错误MySQL 。
最后检查了主库故障时间点的 MySQL 服务状态以及对应时间主库的 binlog 文件,并没有发现任何异常,同时查看故障时间点的网络监控,也是正常的MySQL 。
到这基本很明确是 relay log 这边出现了问题,从而导致无法解析中继日志中的事务MySQL 。由于客户环境未能保留报错时的 relay log ,所以只能去通过自己的环境去复现客户故障,并与客户故障环境已采集的信息作比对。
2.4 本地环境复现
查看当前环境主从状态MySQL 。
mysql> showslavestatus\G
*************************** 1.row***************************
Slave_IO_State: Waiting formastertosend event
Master_Host: 10.186.63.44
Master_User: universe_op
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000001
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 。
mysql> STOPSLAVESQL_THREAD;
Query OK, 0 rows affected (0.00 sec)
查看当前复制状态MySQL 。
mysql> showslavestatus\G
*************************** 1.row***************************
Slave_IO_State: Waiting formastertosend event
Master_Host: 10.186.63.44
Master_User: universe_op
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000001
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 。
mysql> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting formaster 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
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 线程正常拉取日志MySQL 。
模拟 SQL 线程故障:使用 hexedit[1]编辑 relay log 文件MySQL 。
hexedit mysql-relay.000007
开启 SQL 线程查看复制状态MySQL 。
mysql> STARTSLAVESQL_THREAD;
Query OK, 0 rows affected (0.02 sec)
mysql> showslavestatus\G
*************************** 1.row***************************
Slave_IO_State: Waiting formastertosend event
Master_Host: 10.186.63.44
Master_User: universe_op
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000001
Relay_Log_File: mysql-relay.000007
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 notparserelay logevententry. 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 logiscorrupted (you can checkthis byrunning 'mysqlbinlog'onthe relay log), a network problem, ora bug inthe master's or slave's MySQL code. Ifyou want tocheckthe master's binary log or slave's relay log, you will be able toknow their namesbyissuing 'SHOW SLAVE STATUS'onthis slave.
Skip_Counter: 0
查看 MySQL 报错信息MySQL 。
至此,通过上面的排除法,以及通过比对本地环境复现的报错信息,可明显判断导致 1594 报错的原因是:在传输或者写入 relay log 的过程中,中继文件意外发生了损坏,从而导致 SQL 线程无法拉取中继日志MySQL 。
2.5 继续解析 relay log
下面我们解析一下 relay log ,看一下有哪些报错的提示信息输出,并进行总结MySQL 。
首先先解析 relay log 查看报错,可以正常解析,看不出来什么异常MySQL 。
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ee2fddba-c6c7-11ef-8e2a-02000aba3f2c:8109'/*!*/;
BEGIN;44006
# /*ustats-10-186-63-44*/update universe.u_delay set real_timestamp=now, logic_timestamp = logic_timestamp + 1 where source = 'ustats'
BINLOG '/T4ongAAANTpOQCAAIYvKnVzdGF0cy0xMC0xODYtNjMtNDQqL3VwZGF0ZSB1bml2ZXJz
ZS51X2RlbGF5IHNldCByZWFsX3RpbWVzdGFtcD1ub3coKSwgbG9naWNfdGltZXN0YW1wID0gbG9n
aWNfdGltZXN0YW1wICsgMSB3aGVyZSBzb3VyY2UgPSAndXN0YXRzJ3ukutE=
g9RyZxMz/T4oOwAAAA/qOQAAANMAAAAAAAEACHVuaXZlcnNlAAd1X2RlbGF5AAMPEggD+AIABgGb
hZs=Zx8z/T4oUAAAAF/qOQAAANMAAAAAAAEAAgAD4BgB1c3RhdHOZtT4TIkQfAAAAAAAA+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 */
COMMIT/*!*/;
由于可以正常解析,那么我们就通过 MySQL 自带的 mysqlbinlog 来验证 relay log 中故障时间点前后事件的 CRC,看看有没有什么异常信息输出MySQL 。
命令及输入如下:
mysqlbinlog --verify-binlog-checksum mysql-relay.000007
查看输出内容:
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ee2fddba-c6c7-11ef-8e2a-02000aba3f2c:8109'/*!*/;
BEGIN
ERROR: Error inLog_event::read_log_event: 'Event crc check failed! Most likely there is event corruption.', data_len: 80, event_type: 31
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 inthe middle of a statement. The event(s) from the partial statement have not been written to output.
发现有 CRC 报错输出,relay log 读取报错原因是 最后一个事务未完整写入MySQL 。
3. 总结
首先,在进行 MySQL 故障处理时,应先尽量保留下必要的信息以方便后续排查具体的原因,再去处理故障、恢复业务MySQL 。其次,针对 1594 主从故障,一般情况有以下几个原因导致,我们可以针对可能导致的原因并结合数据库的错误日志进行进一步排查和修复。
中继日志文件损坏:磁盘故障、非正常关机导致文件损坏MySQL 。
磁盘空间不足:从库无法写入新的事件到中继日志MySQL 。
主库日志丢失:主库清理了未同步的二进制日志,导致从库请求的日志位置失效MySQL 。
权限或路径错误:MySQL 进程无权访问中继日志文件,或路径配置错误MySQL 。
参考资料
[1]
hexedit: /