一次MySQL主从同步异常，扒个底朝天都没排查出来……( 二 ) _MySQL

binlog 日志
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 报错信息
5、找原因
1）猜测事务日志太大
根据这个报错信息可以知道这个事务日志数据太长了，data_len: 7644，而导致读取错误。
而且上面还有很多 Update_rows 的操作。
猜测：会不会是主库执行了一个大事务，造成该事务生成的一条 binlog 日志太大了，从库生成的对应的一条 relay log 日志也很大，SQL 线程去解析这条 relay log 日志解析报错。
2）验证
到主库上查看下 binlog 日志里面有没有在那个时间点做特殊操作。
感觉快找到原因了。执行以下命令来查看：
mysqlbinlog File --stop-datetime=T --start-datetime=T
stop-datetime 指定为读取 relay log 报错的时刻 2023-04-04 16:47:16；
start-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 报错。
6、这是真相吗？
问了下熟悉这张表的同事，有没有在这个时刻做什么大事务操作。
同事看了下代码，发现有个批量插入的操作，一次执行 400 条，难道是 400 条太多了？这不应该是真正的原因，400 条也不多。
不经意间问了下这张表的数据量有多大，该同事在 4月4号 16:45:25 做了一个手动备份 xx_dance 表的操作，这张表有 25 万条数据。

文章插图
备份表 xx_dance_0404 的信息
这个备份操作是在一个事务里面执行的，生成的一条 binlog 日志很大。
这里只是一个猜测，还未得到验证，文末会说明真正的原因。
如果真的是这样，那我可以先恢复从库的同步，备份表的操作在从库上其实不需要。
7、GTID
不知道细心的你是否有发现上面的 binlog 里面有一个GTID 。
'c5d74746-d7ec-11ec-bf8f-0242ac110002:8634832

文章插图
binlog 中 GTID
记住 GTID 中的数字 8634832，后面恢复从库同步时要用到。
我们再来看下从库的状态，发现也有一个 GTID，如下图所示，值为 8634831，正好相差 1，感觉这两个 GTID 值之间有不可告人的秘密。

文章插图
从库的状态，GTID 集合
那么从库 SQL 线程停止运行的原因就是卡在 8634832 这里了，我们可否跳过这个 GTID 呢？这里就需要了解 GTID 的原理了。
四、GTID 同步方式的原理
这里还是把主从同步采用 GTID 方式的流程拿出来看下，帮助大家快速回顾下，熟悉的同学可以跳过本节内容。