问题现象
-
某客户反馈，在利用binlog做基于时间点的恢复时，频繁出现无法正确恢复数据的情况（出现概率大约5%~10%）。
-
数据库环境为MySQL 5.7.27版本的级联复制拓扑（A->B->C），主库A提供写服务，从库B提供读服务，级联复制从库C提供数据的备份和恢复服务。其中，AB库为生产服务库，数据的备份和恢复服务是利用级联复制从库C的数据做定期与手动快照，然后结合从库C的binlog做基于时间点的数据恢复。无法正确恢复数据的情况，具体指的就是实际恢复出来的数据对应的时间点比mysqlbinlog命令指定的时间点要早很多（例如：主库数据已经到达12:00、从库C的快照时间点是10:00、执行恢复操作命令指定的截止时间点是11:00、最终恢复出来的数据时间点是10:30；或者干脆最终恢复出来的数据只有快照数据——即只有10:00的数据，没有任何binlog补偿的数据）。
粗略推导分析
* 级联复制的逐级复制可能导致复制的延迟逐级增加、或者大事务导致复制延迟，然后，由于延迟导致的问题。
* 执行备份恢复这一套系统逻辑有BUG导致的问题。
* mysqlbinlog解析工具有BUG、或者MySQL Server在从库端写binlog有BUG导致的问题、或者高负载导致MySQL的脑子坏了？
* 一些未暴露出来的骚操作导致的问题。
-
咋一看，有点懵，脑子里迅速推导了几种可能性（不是很靠谱那种）。
PS：
-
显然，通过这些简单的信息和粗略的推导分析，并不能确定问题的真相，而要确定问题的真相，就需要更详尽的信息以及可复现的方法。下面，我们将遵循这个套路带着大家一步一步剖析问题的真相。
1、信息收集
需要收集哪些信息呢？下面我们大致罗列几种对分析问题可能有帮助的信息。
-
收集跟问题现象直接相关的数据，用于直观感受问题具体长什么样子。
* 跟问题现象相关的操作有哪些，具体是如何操作的。
* 在从库C中解析binlog的原始命令文本，以及对应的binlog原始文件。
* 从库C复制状态与延迟信息。
* 从库C的my.cnf配置模板。
* 从库C中的事务信息、锁信息、show processlist线程状态信息。 -
收集从库C的主机负载信息和数据库的负载信息，用于判断一些可能由于高负载导致的问题。
-
收集从库C的MySQL错误日志、操作系统常规日志、操作系统安全日志，用于判断是否有某些错误或者BUG被触发。
收集到上述罗列的信息之后，就使得我们的分析排查工作具备了较强的可操作性了，但这些信息中有的可能是完全没有用的干扰信息、有的可能不是导致问题的因素但可以帮助矫正排查问题的方向（例如：被证实不是它导致的问题之后，就不会往这个方向继续深入分析排查）。真正有用的信息也许大多数时候都在跟你玩捉迷藏。因此我们需要对这些信息进行去伪存真，然后，真正有用的信息大概率就存在于剩下这一部分信息里边了。下面我们将遵循这个原则先在收集到的所有信息中筛选出有用的信息。
PS：留意下文代码段中的中文注释。
2、分析排查
根据收集到的主机负载和数据库的负载信息来判断，从库C的主机负载和数据库的负载信息都比较低，暂时排除高负载导致的问题。
根据收集到的各种错误日志来判断，从库C中未找到任何报错信息，暂时排除MySQL Server的BUG导致的问题（但存疑）。
根据收集到的跟问题现象直接相关的数据。
* FDE、Previous-GTIDs类型的event时间戳为19:09:10
* 记录数据的event(GTID、Query、Table_map、Update_rows|Delete_rows|Update_rows、Xid)时间戳范围为 19:03:30 ~ 19:12:34
* Rotate类型的event时间戳为19:12:34
-
并没有发现什么明显的骚操作，排除人为操作事务的可能性。
-
从库延迟平均在5~20小时（需要引起注意）。
-
通过mysqlbinlog解析并查看从库C原始的binlog文件后发现，大多数binlog中记录的内容没有发现异常，但有极少数的binlog中的event时间戳顺序是乱序的（需要引起注意）：
-
mysqlbinlog解析命令指定的--stop-datetime时间戳为'19:08:10'（需要引起注意）。
-
配置模板没有发现什么异常，排除参数配置不当导致的可能性。
-
数据库线程状态无异常、无大事务、也没有长时间的锁等待信息，排除大事务、锁等待、长时间未提交的事务导致的可能性。
根据以上收集到的信息，现在，我们能够大致判断是由于复制延迟引起的，那么，问题来了，复制延迟与基于时间点恢复数据不正确有啥关系？binlog中的event时间戳顺序乱序是怎么回事？mysqlbinlog解析命令指定时间戳为'19:08:10'，是否是碰到了FDE、Previous-GTIDs类型的event时间戳为19:09:10时，发现不满足时间范围条件，直接跳过了解析后续的event(也就是说跳过了数据部分的event解析)？要搞清楚这三个问题，我们就需要想办法复现问题现象了（由于客户现场是不能随便折腾的，所以，我们需要自己找环境来复现该现象，根据上述收集到的信息，复现该问题首先需要刻意制造复制延迟）。
PS：啰嗦一句，我们是如何判断上述信息的有效性的呢？除了需要具备一定的底层知识之外，我个人认为，能够让你感觉到一丝丝不安的因素，都需要注意，不能有意无意地忽略一些潜在的风险点。
3、找到原因
我们在自己的复制环境中，故意制造了复制延迟，以便在从库中制造复制延迟相关的数据（一主一从复制拓扑，使用sysbench 64线程持续对主库加压）。
在从库中停止SQL线程，并手动执行flush binary logs语句滚动日志，记录下滚动之后的最后一个binlog。
# 停止SQL线程
root@localhost : (none) 05:21:12> stop slave sql_thread;
Query OK, 0 rows affected (0.00 sec)
# 为了便于后续查看数据以及避免之前记录的binlog内容的干扰，先手动在从库中切换binlog
root@localhost : (none) 05:21:31> flush binary logs;
Query OK, 0 rows affected (0.01 sec)
root@localhost : (none) 05:22:00> show binary logs;
+------------------+-----------+
| Log_name | File_size |
+------------------+-----------+
| mysql-bin.000001 | 60392080 |
......
| mysql-bin.000010 | 194 | # 滚动之后，罪行的binlog file为mysql-bin.000010
+------------------+-----------+
10 rows in set (0.00 sec)
大约过了10分钟，我们在从库中启动了SQL线程追赶数据，此时查看复制状态，可以发现复制出现了延迟。
# 启动SQL线程
root@localhost : (none) 05:22:13> start slave sql_thread;
Query OK, 0 rows affected (0.00 sec)
# 查看复制状态
root@localhost : (none) 05:30:08> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 10.10.30.163
Master_User: repl
Master_Port: 3306
Connect_Retry: 10
Master_Log_File: mysql-bin.000015
Read_Master_Log_Pos: 375161305
Relay_Log_File: mysql-relay-bin.000026
Relay_Log_Pos: 148909788
Relay_Master_Log_File: mysql-bin.000009
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
......
Exec_Master_Log_Pos: 148909575
Relay_Log_Space: 3596749378
......
Seconds_Behind_Master: 648 # 成功制造复制延迟为648秒（当然，这个延迟时间可能不精确，但这里不是重点）
......在从库中使用mysqlbinlog命令解析查看mysql-bin.000010文件中的内容。
[root@node3 binlog]# ll
total 4836776
......
-rw-r----- 1 mysql mysql 536903179 Jul 29 17:31 mysql-bin.000010
-
最低0.47元/天 解锁文章
712
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
