MySQL binlog基于时间点恢复数据失败是什么鬼？

沃趣技术 2019-08-02

350

作者罗小波·沃趣科技高级数据库技术专家

出品沃趣科技

问题现象

某客户反馈，在利用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导致的问题（但存疑）。

根据收集到的跟问题现象直接相关的数据。

并没有发现什么明显的骚操作，排除人为操作事务的可能性。
从库延迟平均在5~20小时（需要引起注意）。
通过mysqlbinlog解析并查看从库C原始的binlog文件后发现，大多数binlog中记录的内容没有发现异常，但有极少数的binlog中的event时间戳顺序是乱序的（需要引起注意）：

* 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

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
-rw-r----- 1 mysql mysql 21004292 Jul 29 17:31 mysql-bin.000011
-rw-r----- 1 mysql mysql 572 Jul 29 17:31 mysql-bin.index

# 解析文件mysql-bin.000010
[root@node3 binlog]# mysqlbinlog mysql-bin.000010 > a.sql
# 过滤一下a.sql中带server id的数据行，也就是标记event类型的那些文本行
[root@node3 binlog]# grep -E 'server id|GTID_NEXT' a.sql > a.txt 

# 查看两个文件的大小
[root@node3 binlog]# ls -lh a.*
-rw-r--r-- 1 root root 878M Jul 29 17:32 a.sql
-rw-r--r-- 1 root root 322M Jul 29 17:44 a.txt
复制

在从库中使用vim打开a.txt文件，查看所有的event的时间戳信息。

[root@node3 binlog]# vim a.txt
# 发现binlog中event的时间戳乱序了，内容如下(FDE、Previous-GTIDs的时间戳为190729 17:22:00，记录数据的GTID、Query、Table_map、Update_rows|Delete_rows|Update_rows、Xid时间戳在190729 17:19:18 ~ 190729 17:20:57之间，Rotate时间戳为190729 17:20:57)
#190729 17:22:00 server id 33062 end_log_pos 123 CRC32 0xc3a9ea93 Start: binlog v 4, server v 5.7.27-log created 190729 17:22:00
#190729 17:22:00 server id 33062 end_log_pos 194 CRC32 0x22797305 Previous-GTIDs
#190729 17:19:18 server id 33061 end_log_pos 259 CRC32 0xd48537a6 GTID last_committed=0 sequence_number=1 rbr_only=yes
SET @@SESSION.GTID_NEXT= 'd9c5c228-b1e0-11e9-b14d-525400c33752:258161'/*!*/;
#190729 17:19:18 server id 33061 end_log_pos 327 CRC32 0x78818eeb Query thread_id=364 exec_time=650 error_code=0
#190729 17:19:18 server id 33061 end_log_pos 451 CRC32 0x6ca05182 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:19:18 server id 33061 end_log_pos 867 CRC32 0xce1dc10f Update_rows: table id 115 flags: STMT_END_F
#190729 17:19:18 server id 33061 end_log_pos 986 CRC32 0xf4d017ed Table_map: `sbtest`.`sbtest2` mapped to number 114
#190729 17:19:18 server id 33061 end_log_pos 1211 CRC32 0xbbaebd66 Delete_rows: table id 114 flags: STMT_END_F
#190729 17:19:18 server id 33061 end_log_pos 1541 CRC32 0x14f2e853 Table_map: `sbtest`.`sbtest2` mapped to number 114
#190729 17:19:18 server id 33061 end_log_pos 1766 CRC32 0xd9080627 Write_rows: table id 114 flags: STMT_END_F
#190729 17:19:18 server id 33061 end_log_pos 1797 CRC32 0x1d0265e4 Xid = 1084024
......
#190729 17:20:57 server id 33061 end_log_pos 536900936 CRC32 0x12796d01 GTID last_committed=260141 sequence_number=260157 rbr_only=yes
SET @@SESSION.GTID_NEXT= 'd9c5c228-b1e0-11e9-b14d-525400c33752:518317'/*!*/;
#190729 17:20:57 server id 33061 end_log_pos 536901004 CRC32 0x8eb6df8a Query thread_id=360 exec_time=622 error_code=0
#190729 17:20:57 server id 33061 end_log_pos 536901128 CRC32 0x3e09a82e Table_map: `sbtest`.`sbtest2` mapped to number 114
#190729 17:20:57 server id 33061 end_log_pos 536901544 CRC32 0xa97d84de Update_rows: table id 114 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 536901786 CRC32 0x35aec8ff Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 536902202 CRC32 0x05064820 Update_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 536902321 CRC32 0x293c82e4 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 536902546 CRC32 0xe4bfcf8b Delete_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 536902876 CRC32 0x1fbc35a7 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 536903101 CRC32 0x45c6cc8e Write_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 536903132 CRC32 0xc6b80fb0 Xid = 2284911
#190729 17:20:57 server id 33062 end_log_pos 536903179 CRC32 0x23a1bcf6 Rotate to mysql-bin.000011 pos: 4
复制

开心 + 激动，赶紧在从库中用mysqlbinlog命令解析一下，这里只需要指定--stop-datetime时间戳小于190729 17:22:00，但大于190729 17:19:18，然后解析数据为空，就确认问题复现了。

# 这里我们就指定--stop-datetime时间戳为190729 17:20:00
[root@node3 binlog]# mysqlbinlog --stop-datetime='2019-07-29 17:20:00' mysql-bin.000010 > b.sql  

[root@node3 binlog]# ls -lh b.sql
-rw-r--r-- 1 root root 336 Jul 29 17:37 b.sql
复制

在从库中，使用vim打开b.sql，嘿，果然发现没有数据，问题现象确认复现了。

# 一字不漏的码出来，就这么点了，没有任何数据相关的event ...
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
复制

so...到这里，我们成功复现了问题现象，但对于前面提出的三个问题，现在，好像一个都没解决呢，现在回顾一下这三个问题：

第一个问题：复制延迟与基于时间点恢复数据不正确有啥关系？

* 对于这个问题，现在看起来好像还是没招。

第二个问题：binlog中的event时间戳顺序乱序是怎么回事？

* 对于这个问题，现在可以往前走一步。从a.txt文件中挑选一两个GTID事务号(前面列举的a.txt文件内容代码段中2个事务的GTID分别为d9c5c228-b1e0-11e9-b14d-525400c33752:258161和d9c5c228-b1e0-11e9-b14d-525400c33752:518317)，然后到主库中解析这个GTID事务号对应的binlog记录，看看在主库中该事务对应的时间戳是长什么样的。

第三个问题：mysqlbinlog解析命令指定时间戳为'2019-07-29 17:20:00'，是否是碰到了FDE、Previous-GTIDs类型的event时间戳为190729 17:22:00时，发现不满足时间范围条件，直接跳过了解析后续的event？"

* 对于这个问题，现在可以通过查看mysqlbinlog命令的源码结合gdb调试，确定是在哪个event退出的（也许不少人会说，mysqlbinlog就是在解析FDE、Previous-GTIDs类型的event时退出的，看起来好像的确是这样，但。。做技术要严谨，必须要有确凿的证据，所以，不建议在这个时候草率下定论）。

现在，我们从第二个问题开始着手，在主库中使用GTID字符串d9c5c228-b1e0-11e9-b14d-525400c33752:258161:518317解析主库binlog。

# 尴尬的是，不知道这两个GTID在主库的哪个binlog中，只能从第一个binlog开始，挨个向后解析主库binlog，并查看前50行中的Previous-GTIDs event中的GTID SET来判断，通过逐个解析binlog查看，发现我们需要寻找的两个GTID藏在主库的mysql-bin.000009 和mysql-bin.000010两个二进制日志文件中
# 解析mysql-bin.000009 文件
[root@node2 binlog]# mysqlbinlog mysql-bin.000009 |head -50  
......
'/*!*/;
# at 123
#190729 17:19:01 server id 33061 end_log_pos 194 CRC32 0xf53f1220 Previous-GTIDs
# d9c5c228-b1e0-11e9-b14d-525400c33752:1-214532
......

# 解析mysql-bin.000010文件
[root@node2 binlog]# mysqlbinlog mysql-bin.000010 |head -50
......
'/*!*/;
# at 123
#190729 17:20:41 server id 33061 end_log_pos 194 CRC32 0x27fe0eac Previous-GTIDs
# d9c5c228-b1e0-11e9-b14d-525400c33752:1-474622

# 解析mysql-bin.000011文件
[root@node2 binlog]# mysqlbinlog mysql-bin.000011 |head -50 
......
'/*!*/;
# at 123
#190729 17:22:17 server id 33061 end_log_pos 194 CRC32 0x1457abd9 Previous-GTIDs
# d9c5c228-b1e0-11e9-b14d-525400c33752:1-731105
复制

在主库中，使用mysqlbinlog解析mysql-bin.000009 和mysql-bin.000010两个二进制日志文件，并指定GTID包含d9c5c228-b1e0-11e9-b14d-525400c33752:258161:518317

# 解析binlog
[root@node2 binlog]# mysqlbinlog mysql-bin.000009 mysql-bin.000010 --include-gtids='d9c5c228-b1e0-11e9-b14d-525400c33752:258161:518317' > c.sql

# 过滤出event事件类型的信息行
[root@node2 binlog]# grep -E 'server id|GTID_NEXT' c.sql > c.txt

# 查看一下c.sql和c.txt两个文件的大小
[root@node2 binlog]# ls -lh c.*
-rw-r--r-- 1 root root 102M Jul 29 18:16 c.sql
-rw-r--r-- 1 root root 3.3K Jul 29 18:18 c.txt

# vim查看c.txt文件中的内容
[root@node2 binlog]# vim c.txt 
#190729 17:19:01 server id 33061 end_log_pos 123 CRC32 0xfade248c Start: binlog v 4, server v 5.7.27-log created 190729 17:19:01
#190729 17:19:01 server id 33061 end_log_pos 194 CRC32 0xf53f1220 Previous-GTIDs

# GTID为 d9c5c228-b1e0-11e9-b14d-525400c33752:258161 的binlog event时间戳与从库中的binlog event时间戳完全相同
#190729 17:19:18 server id 33061 end_log_pos 88394786 CRC32 0x7a13b001 GTID last_committed=43590 sequence_number=43629 rbr_only=yes
SET @@SESSION.GTID_NEXT= 'd9c5c228-b1e0-11e9-b14d-525400c33752:258161'/*!*/;
#190729 17:19:18 server id 33061 end_log_pos 88394865 CRC32 0x1cb7f558 Query thread_id=364 exec_time=0 error_code=0
#190729 17:19:18 server id 33061 end_log_pos 88394989 CRC32 0xf07fac6f Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:19:18 server id 33061 end_log_pos 88395405 CRC32 0x8a0adc66 Update_rows: table id 115 flags: STMT_END_F
#190729 17:19:18 server id 33061 end_log_pos 88395524 CRC32 0x60282fdb Table_map: `sbtest`.`sbtest2` mapped to number 114
#190729 17:19:18 server id 33061 end_log_pos 88395749 CRC32 0xe041108a Delete_rows: table id 114 flags: STMT_END_F
#190729 17:19:18 server id 33061 end_log_pos 88396079 CRC32 0x1d8f8fd2 Table_map: `sbtest`.`sbtest2` mapped to number 114
#190729 17:19:18 server id 33061 end_log_pos 88396304 CRC32 0x704462b2 Write_rows: table id 114 flags: STMT_END_F
#190729 17:19:18 server id 33061 end_log_pos 88396335 CRC32 0xbf367aab Xid = 5087302
#190729 17:20:41 server id 33061 end_log_pos 536892835 CRC32 0x864ece23 Rotate to mysql-bin.000010 pos: 4
......
#190729 17:20:41 server id 33061 end_log_pos 123 CRC32 0x489dccb5 Start: binlog v 4, server v 5.7.27-log created 190729 17:20:41
#190729 17:20:41 server id 33061 end_log_pos 194 CRC32 0x27fe0eac Previous-GTIDs

# GTID为 d9c5c228-b1e0-11e9-b14d-525400c33752:518317 的binlog event时间戳仍然与从库中的binlog event时间戳完全相同
#190729 17:20:57 server id 33061 end_log_pos 91264585 CRC32 0xc7ea8f93 GTID last_committed=43656 sequence_number=43695 rbr_only=yes
SET @@SESSION.GTID_NEXT= 'd9c5c228-b1e0-11e9-b14d-525400c33752:518317'/*!*/;
#190729 17:20:57 server id 33061 end_log_pos 91264664 CRC32 0x7b4539d5 Query thread_id=360 exec_time=0 error_code=0
#190729 17:20:57 server id 33061 end_log_pos 91264788 CRC32 0xf11c5c66 Table_map: `sbtest`.`sbtest2` mapped to number 114
#190729 17:20:57 server id 33061 end_log_pos 91265204 CRC32 0x856ae255 Update_rows: table id 114 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 91265446 CRC32 0xdcd7ee6b Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 91265862 CRC32 0x3a8a4aa2 Update_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 91265981 CRC32 0xf51f1fc2 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 91266206 CRC32 0xc52d3e94 Delete_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 91266536 CRC32 0xff5e2784 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 91266761 CRC32 0x708a7aaa Write_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 91266792 CRC32 0xcde1e798 Xid = 10289372
......

复制

通过比对主从库的binlog中，这两个事务的binlog event时间戳，发现完全相同，说明从库的binlog中该事务的时间戳是来自主库binlog中该事务的原始时间戳（这些事务对应的event的时间戳，在复制拓扑中不会被其他数据库实例改变），但，为何从库的binlog file中的FDE、Previous-GTIDs时间戳会大于事务的event时间戳呢？难道从库存在延迟之后，从库自身的每个binlog都是这样的吗？带着疑问，在从库中继续往后解析mysql-bin.000011、mysql-bin.000012 ...

# 解析mysql-bin.000011
[root@node3 binlog]# mysqlbinlog mysql-bin.000011 |grep -E 'server id|GTID_NEXT' > d.txt

# vim查看d.txt文件内容，并没有发现FDE、Previous-GTIDs时间戳比事务的binlog event时间戳大的情况（WTF...，这是神马情况？）
[root@node3 binlog]# vim d.txt
#190729 17:20:57 server id 33062 end_log_pos 123 CRC32 0xa03c5bbc Start: binlog v 4, server v 5.7.27-log created 190729 17:20:57
#190729 17:20:57 server id 33062 end_log_pos 194 CRC32 0xfff79f0a Previous-GTIDs
#190729 17:20:57 server id 33061 end_log_pos 259 CRC32 0x37ef05b1 GTID last_committed=0 sequence_number=1 rbr_only=yes
SET @@SESSION.GTID_NEXT= 'd9c5c228-b1e0-11e9-b14d-525400c33752:518318'/*!*/;
#190729 17:20:57 server id 33061 end_log_pos 327 CRC32 0xe88d5be8 Query thread_id=332 exec_time=622 error_code=0
#190729 17:20:57 server id 33061 end_log_pos 451 CRC32 0x3f4748f8 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 867 CRC32 0x6cab4c30 Update_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 986 CRC32 0x8f8db6cc Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 1211 CRC32 0x49418317 Delete_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 1541 CRC32 0x6faf4972 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:20:57 server id 33061 end_log_pos 1766 CRC32 0x35b274e6 Write_rows: table id 115 flags: STMT_END_F
#190729 17:20:57 server id 33061 end_log_pos 1797 CRC32 0x70757956 Xid = 2284921
......
#190729 17:22:34 server id 33062 end_log_pos 536885932 CRC32 0xe8e5a7b3 Rotate to mysql-bin.000012 pos: 4

# 继续解析mysql-bin.000012
[root@node3 binlog]# mysqlbinlog mysql-bin.000012 |grep -E 'server id|GTID_NEXT' > e.txt 

# vim查看e.txt文件内容，仍然没有发现FDE、Previous-GTIDs时间戳比事务的binlog event时间戳大的情况
[root@node3 binlog]# vim e.txt
#190729 17:22:34 server id 33062 end_log_pos 123 CRC32 0x55c719a6 Start: binlog v 4, server v 5.7.27-log created 190729 17:22:34
#190729 17:22:34 server id 33062 end_log_pos 194 CRC32 0x246c1b20 Previous-GTIDs
#190729 17:22:34 server id 33061 end_log_pos 259 CRC32 0x5dbbac77 GTID last_committed=0 sequence_number=1 rbr_only=yes
SET @@SESSION.GTID_NEXT= 'd9c5c228-b1e0-11e9-b14d-525400c33752:776005'/*!*/;
#190729 17:22:34 server id 33061 end_log_pos 327 CRC32 0x86ca88e5 Query thread_id=331 exec_time=593 error_code=0
#190729 17:22:34 server id 33061 end_log_pos 451 CRC32 0xc2c13e95 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:22:34 server id 33061 end_log_pos 867 CRC32 0xd95ec374 Update_rows: table id 115 flags: STMT_END_F
#190729 17:22:34 server id 33061 end_log_pos 1109 CRC32 0xc698d4ca Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:22:34 server id 33061 end_log_pos 1525 CRC32 0x893ec0b8 Update_rows: table id 115 flags: STMT_END_F
#190729 17:22:34 server id 33061 end_log_pos 1644 CRC32 0x503ef822 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:22:34 server id 33061 end_log_pos 1869 CRC32 0x56078d13 Delete_rows: table id 115 flags: STMT_END_F
#190729 17:22:34 server id 33061 end_log_pos 2199 CRC32 0xb134e795 Table_map: `sbtest`.`sbtest1` mapped to number 115
#190729 17:22:34 server id 33061 end_log_pos 2424 CRC32 0x0bf4a350 Write_rows: table id 115 flags: STMT_END_F
#190729 17:22:34 server id 33061 end_log_pos 2455 CRC32 0x4d065250 Xid = 3484259
......
#190729 17:24:12 server id 33062 end_log_pos 536888910 CRC32 0x029b5df4 Rotate to mysql-bin.000013 pos: 4
复制

为毛从库的mysql-bin.000010文件中的event时间顺序有问题？而后续所有的binlog文件中的时间戳都没有问题？他们之间有哪里不同？想来想去，好像想起了，mysql-bin.000010是手动执行flush binary logs语句做切换时生成的，而后续的其他binlog文件，是自动切换的，自动切换怎么切换？当binlog大小达到max_binlog_size系统变量的设置，就会触发自动切换，我们在从库中查看一下binlog文件的大小以及max_binlog_size系统变量的设置。

# max_binlog_size系统变量的设置
root@localhost : (none) 06:56:20> show variables like '%max_binlog_size%';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| max_binlog_size | 536870912 |  # 转换为M单位就是512M
+-----------------+-----------+
1 row in set (0.00 sec)

# 查看binlog文件的大小
[root@node3 binlog]# ls -lh                                                                                                                                                                                                                   
total 9.4G
......
-rw-r----- 1 mysql mysql 176615208 Jul 29 17:22 mysql-bin.000009  # 在mysql-bin.000009的时候执行了flush binary logs切换到了mysql-bin.000010 ，所以mysql-bin.000009的文件大小小很多
-rw-r----- 1 mysql mysql 536903179 Jul 29 17:31 mysql-bin.000010  # 转换为M单位就是512M，刚好达到max_binlog_size系统变量的设置
-rw-r----- 1 mysql mysql 536885932 Jul 29 17:32 mysql-bin.000011
-rw-r----- 1 mysql mysql 536888910 Jul 29 17:33 mysql-bin.000012
-rw-r----- 1 mysql mysql 536887458 Jul 29 17:34 mysql-bin.000013
-rw-r----- 1 mysql mysql 536888575 Jul 29 17:35 mysql-bin.000014
-rw-r----- 1 mysql mysql 536903940 Jul 29 17:37 mysql-bin.000015
-rw-r----- 1 mysql mysql 491243565 Jul 29 18:14 mysql-bin.000016
-rw-r----- 1 mysql mysql 832 Jul 29 17:37 mysql-bin.index
复制

至此，我们离真相更进一步了，知道了从库中binlog文件 mysql-bin.000010 中的时间戳乱序是因为手动执行了flush binary logs语句切换日志导致的，而其他的binlog是自动触发滚动生成的就没有这个问题。但是。。还是比较迷糊，这两种方式产生的binlog中的FDE、Previous-GTIDs时间戳一定有蹊跷，如果要直接去找出在两种情况下各自获取时间戳的时机可能就比较复杂，这里我们采用了反证法，在复制存在延迟的情况下，先在从库中把复制线程停掉并执行flush binary logs; 发现FDE、Previous-GTIDs时间戳是从库实例的当前时间戳，然后，在从库中重新启动复制线程，让从库的binlog文件大小达到max_binlog_size系统变量的设置时自动切换，发现FDE、Previous-GTIDs时间戳是来自上一个binlog文件中最后一个事务对应的event的时间戳（即，自动切换的binlog中的FDE、Previous-GTIDs时间戳是跟随主库binlog event的，整个binlog中的event时间戳不会出现乱序，在使用mysqlbinlog解析binlog时就不可能出现无法解析事务对应的event的问题），有兴趣的同学可自行验证，这里不再赘述。

第二个问题到这里就已经解决了，现在，我们来解决第三个问题，怎么解决呢？翻看源码，做gdb调试，我们临时邀请了一位神秘友人相助（文末也提供了这位神秘友人相关文档的参考链接），下面是mysqlbinlog命令退出位置的关键证据。FDE、Previous-GTIDs时间戳为190825 0:01:37，数据的event时间戳为190724 14:07:36，mysqlbinlog解析binlog时指定--stop-datetime时间为2019-07-25 00:00:00（友情提示：该图中的数据是这位神秘友人的环境，与本文上下文中的数据不对应）。

源码文件mysqlbinlog.cc中处理时间戳的逻辑代码如下。

调试测试数据的binlog中的event数据如下。

执行mysqlbinlog解析的命令如下。

gdb调试信息如下，可以直观地看到，在处理FORMAT_DESCRIPTION_EVENT（FDE）的event时，直接goto end退出了。

现在，第三个问题也解决了，还剩下第一个问题：复制延迟与基于时间点恢复数据不正确有啥关系？我们解决了第二个问题和第三个问题，第一个问题似乎答案也呼之欲出，我们来复盘整理一下上文中的信息。

我们在sysbench压测过程中，先停止了SQL线程，然后手工执行了flush binary logs语句切换binlog，此时切换后的binlog文件名为mysql-bin.000010，该binlog中的FDE、Previous-GTIDs时间戳是从库的当前时间戳（190729 17:22:00），此时，SQL线程未启动，也就是说不会应用relay log中来自主库的binlog，也就是说从库自身的binlog中不会写入任何数据event。
然后，过了10分钟左右，我们启动了SQL线程，开始应用来自主库的binlog，写入mysql-bin.000010文件中第一个事务相关的event时间戳为190729 17:19:18（它是来自主库写入binlog时的时间戳，不会因为从库做任何操作而改变），也就是说，此时mysql-bin.000010中的event时间戳就处于一个乱序的状态了。
然后，使用mysqlbinlog解析binlog时，指定了--stop-datetime时间戳为2019-07-29 17:20:00，该时间小于FDE、Previous-GTIDs时间戳190729 17:22:00，根据上文中gdb调试的逻辑判断，指定的时间戳小于了FDE的时间戳，不满足条件，不再往后扫描（即使后续的数据event的时间戳为190729 17:19:18，满足小于mysqlbinlog指定的时间戳也无济于事），mysqlbinlog命令退出解析任务。

至此，第三个问题也得到了解决。

导致基于时间点恢复数据不正确的原因是：在从库存在复制延迟的情况下，手工执行了flush binary logs语句切换binlog（这里要注意：从库存在复制延迟的情况下，如果重启从库数据库进程，binlog中的时间戳仍然会乱序），导致了binlog文件中的时间戳乱序，然后，mysqlbinlog工具指定了一个尴尬的时间戳（卡在了小于FDE、Previous-GTIDs的时间戳，但大于数据event的时间戳的范围内），导致解析任务退出，无法正确解析数据的event。

PS：到这里，我们通过上述一系列的分析排查步骤，已经找出了导致从库binlog中的时间戳乱序的2个直接原因。

手工执行flush bianry logs语句。
重启从库数据库进程。

4、问题追踪

此时此刻，是不是就可以收工交作业了呢？如果是纯技术研究，嗯，到此收工应该问题不大，但，这不是单纯的技术问题，而是一个由客户现场发现的实际问题，需要找出在实际环境中哪里执行了flush语句或者重启了从库数据库进程，并研究预防策略。因此，我们需要与客户现场做二次确认。

经再次确认，并没有手工执行flush binary logs语句，执行过一两次重启从库进程的操作，但，重启的一两次操作对于5%~10%的问题现象概率来说显然不匹配，其中一定有蹊跷，一定是哪里手动执行了flush binary logs;语句，但到此时，可被怀疑的因素已经不多了。实在要说哪里还可以被怀疑，首当其冲的应该就是数据库的管理系统的代码。

于是，向相关的研发人员反馈，建议在代码中查看是否有执行flush binary logs或者flush logs语句，以及是否做了一些不必要的重启从库进程的操作。第二天，他们果然在代码中找到了在对数据卷打快照时，加全局读锁之后有一个flush logs语句，对于数据库实现基于时间点恢复数据的功能逻辑来说，这个操作完全没必要，可以删除flush语句。但是，这里是否可以立即建议研发将管理系统代码中的flush语句删除就完事了呢？作为一个严谨的技术从业人员，不应该有意无意忽略潜在的风险点。你应该建议研发人员去追查代码提交信息，看看是什么时候提交的，谁提交的，然后，确认为什么会添加这个操作，然后再来评估是否需要删除flush语句相关的代码。

大约又过了一天，研发的小伙伴们惊奇地发现flush语句相关的代码是3.5年前提交的，提交注释上说只是为了实现打一个快照的功能，但已经没有人知道当初为何添加这个flush操作。那怎么办？我们最后建议研发删除flush语句相关的代码，然后，整个管理系统走一遍常规的功能测试，然后，再走一遍重压测试，等到所有测试走完，直到不再出现"基于时间点恢复数据"无法正确恢复数据的问题，且没有其他新的问题产生。然后，建议客户，除非必须，否则不要随意在从库中执行flush语句，不要随意重启从库，否则可能会造成什么影响等巴拉巴拉巴拉。。。

这时，你就可以出具相关报告文档交作业了。

参考链接：

重庆八怪（高鹏）：

https://www.jianshu.com/p/ba37faa3022a

作者简介

罗小波·沃趣科技高级数据库技术专家

IT从业多年，主要负责MySQL 产品的数据库支撑与售后二线支撑。曾参与版本发布系统、轻量级监控系统、运维管理平台、数据库管理平台的设计与编写，熟悉MySQL体系结构，Innodb存储引擎，喜好专研开源技术，多次在公开场合做过线下线上数据库专题分享，发表过多篇数据库相关的研究文章。

MySQL binlog基于时间点恢复数据失败是什么鬼？

1、信息收集

2、分析排查

3、找到原因

4、问题追踪

评论

相关阅读