~目录一、现象最近项目的测试环境遇到一个主备同步的问题备库的同步线程停止了无法同步主库的数据更改。备库报错如下从库同步报错信息完整的错误信息Relay log read failure: Could not parse relay log event entry. The possible reasons are: the masters binary log is corrupted (you can check this by running mysqlbinlog on the binary log), the slaves relay log is corrupted (you can check this by running mysqlbinlog on the relay log), a network problem, or a bug in the masters or slaves MySQL code. If you want to check the masters binary log or slaves relay log, you will be able to know their names by issuing SHOW SLAVE STATUS on this slave.上面的报错信息是什么意思呢翻译一下就是主库的 binlog 或者从库的 relay log 损坏了造成这个问题的原因可能是网络问题。也可能是主库或备库的代码 bug。首先我们还是得复习下主从同步的原理才能更好地分析原因。二、主从同步的原理主从同步的原理从库会生成两个线程一个 I/O 线程名字叫做 Slave_IO_Running另外一个是 SQL 线程名字叫做 Slave_SQL_Running;从库的 I/O 线程会去请求主库的 binlog 日志文件并将得到的 binlog 日志文件写到本地的 relay log (中继日志)文件中;主库会生成一个 dump 线程用来给从库 I/O 线程传 binlog;从库 SQL 线程会读取 relay log 文件中的日志并解析成 SQL 语句逐一执行。三、排查思路3.1 分析从库的同步状态我们可以打印下从库的同步状态看到如下几个关键信息分析从库的同步状态Master_Log_File: mysql-bin.000956代表从库读到的主库的 binlog fileRead_Master_Log_Pos: 528071913代表从库读到的主库的 binlog file 的日志偏移量Relay_Log_File: relay-bin.000094代表从库执行到了哪一个 relay logRelay_Log_Pos: 123408769代表从库执行的 relay log file 的日志偏移量Relay_Master_Log_File: mysql-bin.000955代表从库已经重放到了主库的哪个 binlog file。Exec_Master_Log_Pos: 123408556代表从库已经重放到了主库 binlog file 的偏移量。Slave_IO_Running: Yes说明 I/O 线程正在运行可以正常获取 binlog 并生成 relay log。Slave_SQL_Running: No说明 SQL 线程已经停止运行不能正常解析 relay log也就不能执行主库上已经执行的命令。Master_Log_File和Read_Master_Log_Pos这两个参数合起来表示的是读到的主库的最新位点。Relay_Master_Log_File和Exec_Master_Log_Pos这两个参数合起来表示的是从库执行的最新位点。如果红色框起来的两个参数Master_Log_File和Relay_Master_Log_File相等则说明从库读到的最新文件和主库上生成的文件相同这里前者是 mysql-bin.000956后者是 mysql-bin.000955说明两者不相同存在主从不同步。如果蓝色框起来的两个参数Read_Master_Log_Pos和Exec_Master_Log_Pos相等则说明从库读到的日志文件的位置和从库上执行日志文件的位置相同这里不相等说明主从不同步。当上面两组参数都相等时则说明主从同步正常且没有延迟。只要有任意一组不相等则说明主从不同步可能是从库停止同步了或者从库存在同步延迟。由于上面的 SQL 线程已经停止了说明是从库同步出现问题了。从库同步出现的问题在最开始的报错信息里面已经提到了可能是网络问题导致还有可能是 binlog 或 relay log 损坏。3.2 重启万能大法先通过重启来恢复从库的 SQL 线程试试看重启方式就是两种方式一从库重新开启同步。就是执行 stop slave; 和 start slave; 命令。方式二重启从库实例。就是重启 mysql 实例或 mysql 容器。这两种方式试了后都不能恢复从库的 SQL 线程。3.3 查看 binlog再来看下 binlog 是否有损坏在主库上通过这个命令打开 mysql-bin.000955 文件。mysqlbinlog /var/lib/mysql/log/mysql-bin.000955没有报错信息如下图所示binlog 日志3.4 查看 relay log看到从库同步的 Relay_Log_File 到 relay-bin.00094 就停止同步了如下图所示可能是这个文件损坏了。relay log 日志在从库上通过 mysqlbinlog 命令打开这个文件mysqlbinlog /var/lib/mysql/log/relay-bin.000094可以看到有个报错信息ERROR: Error in Log_event::read_log_event(): read error, data_len: 7644, event_type: 31 ERROR: Could not read entry at offset 243899899: Error in log format or read error.这段文字翻译过来就是读取错误数据长度 7644在读取偏移量为 243899899 的日志时发生了错误可能是日志文件格式错误或是读取文件错误。relay log 报错信息3.5 找原因3.5.1 猜测事务日志太大根据这个报错信息可以知道这个事务日志数据太长了data_len: 7644而导致读取错误。而且上面还有很多 Update_rows 的操作。猜测会不会是主库执行了一个大事务造成该事务生成的一条 binlog 日志太大了从库生成的对应的一条 relay log 日志也很大 SQL 线程去解析这条 relay log 日志解析报错。3.5.2 验证到主库上查看下 binlog 日志里面有没有在那个时间点做特殊操作。感觉快找到原因了。执行以下命令来查看mysqlbinlog File --stop-datetimeT --start-datetimeTstop-datetime指定为读取 relay log 报错的时刻 2023-04-04 16:47:16start-datetime指定为读取 relay log 报错的时刻 2023-04-04 16:47:30。发现并没有找到 Update_rows 的操作。继续把时间往后加一点经过多次尝试把时间锁定在了 2023-04-04 17:00:30~17:00:31。这 1s 内能找到 2023-04-04 16:47:16 的操作日志。日志如下这个命令会打印 N 多日志直接把屏幕打满了难道真的 binlog 对应的这条事务日志太大了吗存疑 2023-04-04 16:47:16 时刻对数据库中的表做了某个大事务的操作造成该事务对应的这条 binlog 日志很大很大。生成的 relay log 也很大SQL 线程解析 relay log 报错。3.6 这是真相吗问了下熟悉这张表的同事有没有在这个时刻做什么大事务操作。同事看了下代码发现有个批量插入的操作一次执行 400 条难道是 400 条太多了这不应该是真正的原因400 条也不多。不经意间问了下这张表的数据量有多大该同事在 4月4号 16:45:25 做了一个手动备份xx_dance表的操作这张表有 25 万条数据。备份表 xx_dance_0404 的信息这个备份操作是在一个事务里面执行的生成的一条 binlog 日志很大。这里只是一个猜测还未得到验证文末会说明真正的原因。如果真的是这样那我可以先恢复从库的同步备份表的操作在从库上其实不需要。3.7 GTID不知道细心的你是否有发现上面的 binlog 里面有一个GTIDc5d74746-d7ec-11ec-bf8f-0242ac110002:8634832binlog 中 GTID记住 GTID 中的数字8634832后面恢复从库同步时要用到。我们再来看下从库的状态发现也有一个 GTID如下图所示值为8634831正好相差 1感觉这两个 GTID 值之间有不可告人的秘密。从库的状态GTID 集合那么从库 SQL 线程停止运行的原因就是卡在 8634832 这里了我们可否跳过这个 GTID 呢这里就需要了解 GTID 的原理了。你可能对 GTID 的原理很感兴趣可以查看之前悟空写的一篇文章MySQL 主从模式采用 GTID 的实践四、GTID 同步方式的原理这里还是把主从同步采用 GTID 方式的流程拿出来看下帮助大家快速回顾下熟悉的同学可以跳过本节内容。GTID 方案主库计算主库 GTID 集合和从库 GTID 的集合的差集然后主库推送差集 binlog 给从库。当从库设置完同步参数后假定主库 A 的GTID 集合记为集合 x从库 B 的 GTID 集合记为 y。从库同步的逻辑如下GTID 同步方式的原理从库 B 指定主库 A基于主备协议简历连接。从库 B 把集合 y 发给主库 A。主库 A 计算出集合 x 和集合 y 的差集也就是集合 x 中存在集合 y 中不存在的 GTID 集合。比如集合 x 是 1~100集合 y 是 1~90那么这个差集就是 91~100。这里会判断集合 x 是不是包含有集合 y 的所有 GTID如果不是则说明主库 A 删除了从库 B 需要的 binlog主库 A 直接返回错误。主库 A 从自己的 binlog 文件里面找到第一个不在集合 y 中的事务 GTID也就是找到了 91。主库 A 从 GTID 91 的事务开始往后读 binlog 文件按顺序取 binlog然后发给 B。从库 B 的 I/O 线程读取 binlog 文件生成 relay logSQL 线程解析 relay log然后执行 SQL 语句。GTID 同步方案和位点同步的方案区别是位点同步方案是通过人工在从库上指定哪个位点主库就发哪个位点不做日志的完整性判断。而 GTID 方案是通过主库来自动计算位点的不需要人工去设置位点对运维人员友好。五、恢复从库的同步5.1 查看从库执行 GTID 的进度在从库上执行show slave status \G来查看 GTID 集合。Retrieved_Gtid_Set表示从库收到的所有日志的 GTID 集合。Executed_Gtid_Set表示从库已经执行完成的 GTID 集合。如果 Executed_Gtid_Set 集合是包含 Retrieved_Gtid_Set则表示从库接收到的日志已经同步完成。这里 Executed_Gtid_Set 的集合为 1-8634831而 Retrieved_Gtid_Set 为 1-9101426说明从库有些 GTID 是没有执行的。从库已经执行到了 8634831下一个要执行的 GTID 为 8634832。因为我们采用的同步方式是 GTID 方式所以只要让从库跳过这个 GTID 从下一个 GTID 开始同步就行。带来的问题就是这个 GTID 对应的事务没有执行。因为报错的操作是从库备份一张大表所以从库跳过这个备份操作也是可以接受的。5.2 手动设置 GTID来手动设置一把 GTID 试下。5.2.1 重置从库进度首先重置下从库同步的进度 reset slave这条命令会把所有的 relog 给清理掉重新启用一个新的 relay log文件。stop slave; reset slave;重新开启同步后主库会计算主库 GTID 集合和从库 GTID 的集合的差集然后主库推送差集 binlog 给从库。5.2.1 设置 GTID 为一个值执行以下命令设置 GTID 为下一个值。set gtid_nextc5d74746-d7ec-11ec-bf8f-0242ac110002:8634832; begin; commit; set gtid_nextautomatic; start slave;gtid_next 表示设置下一个 GTID 8634832这个值是在原来的 8634831 加 1。后面的 begin 和 commit 是提交了一个空事务把这个 GTID 加到从库的 GTID 集合中。那么从库的 GTID 集合就变成了c5d74746-d7ec-11ec-bf8f-0242ac110002:1-8634832;5.2.2 查看当前 GTID 集合我们可以通过 show master status\G 命令来查看从库的 GTID 集合。下方截图是执行上述命令之前的。GTID集合为 1-8634831。另外 GTID 集合 为 1 和 GTID 集合为 1-4 的可以忽略因为它们前面的 Master_UUID 不是当前主库的 uuid。show master status\G 的结果也可以通过 show slave status\G 命令来查看 GTID 集合结果也是一样的。5.3 开启从库同步再次启动从库的同步start slave 命令)I/O 线程和 SQL 线程的状态都为 YES说明启动成功了。而且查看从库的同步状态时观察到从库的同步是存在延迟的。通过观察这个字段 Seconds_Behind_Master 在不断减小说明主从同步的延迟越来越小了。两个线程都是正常运行主从同步延迟越来越小过一段时间后执行的 GTID 等于收到的 GTID 集合Seconds_Behind_Master 0说明主从完全同步了。六、原因上面的推测备份大表造成 binlog 的一条日志太大relay log 也跟着变大SQL 线程无法正常解析。但这是真相吗虽然从库重新开启了同步且跳过了这条日志但带来的是从库上就不会出现这个备用表 xx_dance_0404 。但出现了两个奇怪的问题问题 1从库开启同步后居然出现了这个备份表 xx_dance_0404。不是跳过这个备份操作了吗目前没想到原因。问题 2为了重现这个问题我到主库上做了一个备份表的操作表名为 xx_dance_0412从库也同步了这个新的备份表 xx_dance_0412。而且 binlog 出现的日志现象也是一样的对应的这条 binlog 日志也很大但是从库同步正常。我又备份了一张 300 万的大表依然没重现。通过问题 2 可以说明上面的推测是错误的备份大表并不会影响主从同步。那么 relay log 报错的原因是什么只有一个原因了relay log 文件真的是损坏的从库的状态上也说明了原因relay log is corrupted损坏。SQL 线程去解析 relay log 时报错了导致 SQL 线程停止从库不能正常执行同步。小结relay log 损坏了导致从库的 SQL 线程解析 relay log 时出现异常。从库恢复方式是通过手动设置当时出错的 GTID 的下一个值让从库不从主库同步这个 GTID最后从库就能正常同步这个 GTID 之后的 binlog 了后续 SQL 线程也能正常解析 relay log 了。如果你对上面的排查思路、结论、恢复方式有其他想法欢迎拍砖