MySQL binlog基於時間點恢復資料失敗是什麼鬼？

沃趣科技發表於2019-08-02

問題現象

某客戶反饋，在利用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中處理時間戳的邏輯程式碼如下。

MySQL binlog基於時間點恢復資料失敗是什麼鬼？

除錯測試資料的binlog中的event資料如下。

MySQL binlog基於時間點恢復資料失敗是什麼鬼？

執行mysqlbinlog解析的命令如下。

MySQL binlog基於時間點恢復資料失敗是什麼鬼？

gdb除錯資訊如下，可以直觀地看到，在處理FORMAT_DESCRIPTION_EVENT（FDE）的event時，直接goto end退出了。

MySQL binlog基於時間點恢復資料失敗是什麼鬼？

現在，第三個問題也解決了，還剩下第一個問題：複製延遲與基於時間點恢復資料不正確有啥關係？我們解決了第二個問題和第三個問題，第一個問題似乎答案也呼之欲出，我們來複盤整理一下上文中的資訊。

我們在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儲存引擎，喜好專研開源技術，多次在公開場合做過線下線上資料庫專題分享，發表過多篇資料庫相關的研究文章。

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/28218939/viewspace-2652553/，如需轉載，請註明出處，否則將追究法律責任。

RMAN基於時間點恢復Oracle資料庫
2015-06-23
Oracle資料庫
mysql通過percona xtrabackup全備和mysql binlog實現基於時間點的資料庫恢復
2015-02-26
MySql資料庫
備份與恢復：Polardb資料庫資料基於時間點恢復
2020-11-12
資料庫
Oracle基於時間點的恢復
2011-01-20
Oracle
mysql資料庫連線失敗是什麼原因
2021-09-11
MySql資料庫
ORACLE資料庫基於時間點的不完全恢復
2019-05-01
Oracle資料庫
RAC 資料庫恢復到單例項下並且基於時間點恢復
2012-09-22
資料庫單例
基於percona xtrabackup之innobackupex實現基於時間點資料庫恢復
2019-11-05
資料庫
基於mysql-binlog的恢復實驗
2016-04-22
MySql
MySQL 通過 binlog 恢復資料
2018-12-06
MySql
MySQL 透過 binlog 恢復資料
2018-12-04
MySql
mongodb 基於oplog的時間點恢復
2019-12-03
MongoDB
用mysqlbinlog做基於時間點的資料恢復一例
2017-01-25
MySql資料恢復
oracle實驗記錄（恢復-表空間基於時間點恢復(rman)）
2009-08-28
Oracle
oracle基於時間點的不完全恢復
2017-05-06
Oracle
Mysql效能壓測、Binlog恢復資料
2021-07-13
MySql
利用binlog日誌恢復mysql資料
2020-10-20
MySql
【Mysql】如何透過binlog恢復資料
2023-03-09
MySql
通過binlog恢復mysql資料庫
2016-05-12
MySql資料庫
mysql使用binlog進行資料恢復
2013-07-14
MySql資料恢復
MySQL--binlog日誌恢復資料
2015-12-02
MySql
oracle實驗記錄（恢復-表空間基於時間點恢復(手動)）
2009-08-28
Oracle
RMAN基於備份控制檔案恢復失敗
2008-02-26
基於時間執行資料庫不完全恢復
2016-11-07
資料庫
【北亞資料恢復】什麼是Ceph？Ceph資料恢復研究
2022-03-22
資料恢復
【RMAN】表空間基於時間點的RMAN恢復-TSPITR
2016-04-29
【DATAGUARD】Oracle 通過Dataguard指定恢復時間用於找回丟失資料
2021-07-22
Oracle
寶塔資料庫恢復 mysql資料庫丟失恢復 mysql資料庫刪除庫恢復寶塔mysql資料庫恢復
2020-11-10
資料庫MySql
【vsan資料恢復】vsan資料重構失敗的資料恢復案例
2022-12-30
資料恢復
【TSPITR】RMAN表空間基於時間點的自動恢復
2015-05-26
大資料是個什麼鬼啦？
2014-08-22
大資料
oracle 閃回基於時間的恢復
2010-08-01
Oracle
【資料庫資料恢復】MongoDB資料庫服務啟動失敗的資料恢復案例
2023-04-18
資料庫資料恢復MongoDB
【伺服器資料恢復】伺服器之間遷移資料時資料丟失的資料恢復案例
2023-02-17
伺服器資料恢復
通過binlog恢復mysql備份之前的資料
2016-05-12
MySql
資料庫資料恢復—無備份，binlog未開啟的Mysql資料庫資料恢復案例
2023-12-08
資料庫資料恢復MySql
儲存互斥失敗導致資料丟失的資料恢復成功案例
2019-07-05
資料恢復
【備份恢復】閃回資料庫（三）基於時間戳閃回資料庫
2016-10-17
資料庫時間戳

MySQL binlog基於時間點恢復資料失敗是什麼鬼？

1、資訊收集

2、分析排查

3、找到原因

4、問題追蹤

相關文章