MySQL 5.7複製配置不規範修改導致的坑（一）

沃趣科技發表於2017-07-18
MySql
沃趣科技  羅小波

1、復現與簡單分析
2、重新復現、詳細分析與驗證
2.1. 重新復現與詳細分析
2.1.1. stop slave
2.1.2. change master to master_auto_position=0
2.1.3. start slave
2.2. 解決方法驗證
3、總結
今天我們們同事說碰到一個古怪的問題，說MySQL 5.7.18上，主從複製結構中，從庫在使用change master語句切換master_auto_position=1為0時，SQL執行緒報錯了([ERROR] Slave SQL for channel '': Error '@@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.' on query. Default database: 'sbtest'. Query: 'BEGIN', Error_code: 1782)，然後，出於嘗試修復，又改成了1，重新啟動複製就恢復正常了，然後再改成0重新啟動複製，這個時候發生資料丟失了，再反覆切換幾次之後，MySQL crash了。。，當時我聽到這個問題的第一反應就是：一臉懵逼（因為1782錯誤通常是發生複製架構啟用GTID複製之後，從庫IO執行緒讀取到主庫的ANONYMOUS 事務時報錯）。。然後，發了一陣呆之後，想到了一些可能導致這個問題的原因，下文我們通過"復現與簡單分析"、"重新復現、詳細分析與驗證"、"總結"三個步驟來對這個問題的前因後果進行一次透析，大家請跟隨我往下看。
先列出硬體配置、作業系統和資料庫環境資訊

環境資訊

作業系統：CentOS Linux release 7.2.1511 (Core)
sysbench版本：sysbench-0.5-3.el6.x86_64
* 使用sysbench造數8張500W資料的表
percona-toolkit版本：percona-toolkit-3.0.3-1.el7.x86_64
percona-xtrabackup版本：percona-xtrabackup-24-2.4.4-1.el7.x86_64
資料庫版本：MySQL 5.7.18
資料庫配置關鍵引數：
  • * 主庫：雙一，log_slave_updates，log-bin，binlog_rows_query_log_events=ON，server-id=330614，slave_parallel_type=LOGICAL_CLOCK，enforce_gtid_consistency=ON，gtid_mode=on，innodb_buffer_pool_size=2G 
  • * 從庫：雙一，雙TABLE，log_slave_updates，log-bin，binlog_rows_query_log_events=ON，server-id=330615，slave_parallel_type=LOGICAL_CLOCK，enforce_gtid_consistency=ON，gtid_mode=on，innodb_buffer_pool_size=2G，slave_parallel_workers=4
主機配置硬體配置：
  • * CPU：4 vcpus 
  • * 記憶體：8G 
  • * 磁碟：50G SSD 
  • * 網路卡：Speed: 100Mb/s
IP：
  • * 主庫：10.10.20.14 
  • * 從庫：10.10.20.15
鄭重宣告：本文僅供學習交流，請勿在生產環境試車！！

1、復現與簡單分析

首先，我們使用主庫中造好數的備份，與從庫搭建主從複製結構（sysbench造數和搭建主備複製步驟省略），從庫初始搭建時使用master_auto_position=1啟動複製
主庫使用如下sysbench語句加壓
    1. sysbench --test=oltp --db-driver=mysql --mysql-table-engine=innodb --mysql-socket=/home/mysql/data/mysqldata1/sock/mysql.sock --mysql-port=3306 --mysql-db=sbtest \
    2.     --mysql-user='qbench' --mysql-password='qbench' --test=/usr/share/doc/sysbench/tests/db/update_non_index.lua --oltp-table-size=5000000 --oltp-tables-count=4 --num-threads=8 --max-time=1800 \
    3.     --max-requests=0 --report-interval=1 run
現在，我們準備把從庫切換master_auto_position=0
先在從庫上執行一下show slave status\G;語句檢視一下複製狀態，從下面的結果中可以看到，一切正常
    1. admin@localhost : (none) 02:46:49> show slave status\G;
    2.     *************************** 1. row ***************************
    3.                    Slave_IO_State: Waiting for master to send event
    4.     ......
    5.                   Master_Log_File: mysql-bin.000036
    6.               Read_Master_Log_Pos: 119450512
    7.                    Relay_Log_File: mysql-relay-bin.000002
    8.                     Relay_Log_Pos: 9530766
    9.             Relay_Master_Log_File: mysql-bin.000036
    10.                  Slave_IO_Running: Yes
    11.                 Slave_SQL_Running: Yes
    12.     ......
    13.               Exec_Master_Log_Pos: 101635141
    14.     ......
    15.             Seconds_Behind_Master: 47
    16.     Master_SSL_Verify_Server_Cert: No
    17.                     Last_IO_Errno: 0
    18.                     Last_IO_Error:
    19.                    Last_SQL_Errno: 0
    20.                    Last_SQL_Error:
    21.     ......
    22.           Slave_SQL_Running_State: Waiting for slave workers to process their queues
    23.     ......
    24.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-731881
    25.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710502:710504
    26.                     Auto_Position: 1
    27.     ......
    28.     1 row in set (0.02 sec)
執行master_auto_position=0
  1. admin@localhost : sbtest 09:02:42> stop slave;
  2.     Query OK, 0 rows affected (0.08 sec)
  3.     admin@localhost : sbtest 09:02:45> change master to master_auto_position=0;
  4.     Query OK, 0 rows affected (0.06 sec)
  5.     admin@localhost : sbtest 09:02:53> start slave;
  6.     Query OK, 0 rows affected (0.03 sec)
  7.     admin@localhost : sbtest 09:02:56> show slave status\G;
  8.     *************************** 1. row ***************************
  9.                    Slave_IO_State: Waiting for master to send event
  10.     ......
  11.                   Master_Log_File: mysql-bin.000036
  12.               Read_Master_Log_Pos: 125448945
  13.                    Relay_Log_File: mysql-relay-bin.000002
  14.                     Relay_Log_Pos: 320
  15.             Relay_Master_Log_File: mysql-bin.000036
  16.                  Slave_IO_Running: Yes
  17.                 Slave_SQL_Running: No
  18.     ......
  19.               Exec_Master_Log_Pos: 120336889
  20.     ......
  21.             Seconds_Behind_Master: NULL
  22.     Master_SSL_Verify_Server_Cert: No
  23.                     Last_IO_Errno: 0
  24.                     Last_IO_Error:
  25.                    Last_SQL_Errno: 1782
  26.                    Last_SQL_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction 'NOT_YET_DETERMINED' at master log\
  27.      mysql-bin.000036, end_log_pos 120336968. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.
  28.     ......
  29.           Last_IO_Error_Timestamp:
  30.          Last_SQL_Error_Timestamp: 170708 21:02:56
  31.     ......
  32.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947-739082
  33.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875
  34.                     Auto_Position: 0
  35.     ......
  36.     1 row in set (0.00 sec)
從上面的結果中可以看到，SQL執行緒報錯了，從Last_SQL_Error欄位顯示的資訊中我們可以得知，是某個workers執行緒報錯了，讓查詢錯誤日誌或者performance_schema.replication_applier_status_by_worker table表（為了防止備庫繼續落後於主庫，現在，我們把sysbench先停止）
現在，我們來查詢performance_schema.replication_applier_status_by_worker table表吧
  1. admin@localhost : sbtest 09:02:59> select * from performance_schema.replication_applier_status_by_worker where LAST_ERROR_MESSAGE != ''\G;
  2.     *************************** 1. row ***************************
  3.              CHANNEL_NAME:
  4.                 WORKER_ID: 1
  5.                 THREAD_ID: NULL
  6.             SERVICE_STATE: OFF
  7.     LAST_SEEN_TRANSACTION:
  8.         LAST_ERROR_NUMBER: 1782
  9.        LAST_ERROR_MESSAGE: Worker 1 failed executing transaction 'NOT_YET_DETERMINED' at master log mysql-bin.000036, end_log_pos 120336968; Error '@@SESSION.GTID_NEXT\
  10.      cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.' on query. Default database: 'sbtest'. Query: 'BEGIN'
  11.      LAST_ERROR_TIMESTAMP: 2017-07-08 21:02:56
  12.     1 row in set (0.00 sec)
發生什麼了？主庫的gtid_mode引數只有在設定為OFF和OFF_PERMISSIVE的時候，才會產生ANONYMOUS 事務並寫入binlog中，而此時主庫的gtid_mode配置引數是絕對沒有人動過的，而且在執行上述操作之前，從庫以GTID複製模式一直都工作得很正常，另外，通常這個錯誤是發生在IO執行緒讀取主庫的binlog時發生，SQL執行緒報這個錯誤還是頭一次見。。尷尬。保險起見，還是到主庫檢視一下gtid_mode的值
  1. admin@localhost : sbtest 08:59:15> show variables like 'gtid_mode';
  2.     +---------------+-------+
  3.     | Variable_name | Value |
  4.     +---------------+-------+
  5.     | gtid_mode | ON |
  6.     +---------------+-------+
  7.     1 row in set (0.01 sec)
從上面的結果中可以看到，主庫的gtid_mode引數並被修改過，既然SQL執行緒報了1782錯誤，那麼我們就解析一下relay log，找到Exec_Master_Log_Pos: 120336889（協調器執行緒停止的位置）和worker執行緒報錯的位置120336968（報錯的worker執行緒停止的位置），到底是不是ANONYMOUS 事務（注意，這個pos是主庫的binlog pos，不是relay log的pos，不能使用--start-position選項）
  1. '# 我們先檢視一下relay log目錄'
  2.     [root@luoxiaobo-02 relaylog]# ll
  3.     總用量 7092
  4.     -rw-r-----. 1 mysql mysql 247 7月 8 21:02 mysql-relay-bin.000001
  5.     -rw-r-----. 1 mysql mysql 7253186 7月 8 21:03 mysql-relay-bin.000002
  6.     -rw-r-----. 1 mysql mysql 120 7月 8 21:02 mysql-relay-bin.index
  7.     '# 發現有兩個，解析最後一個relay log（第一個可能並不包含資料）並重定向到一個檔案a.sql'
  8.     [root@luoxiaobo-02 relaylog]# mysqlbinlog -vv mysql-relay-bin.000002 > a.sql
  9.     '# vim開啟這個檔案，搜尋120336968（這裡只擷取我們需要的部分內容）'
  10.     # at 123
  11.     #170708 21:02:56 server id 330615 end_log_pos 154 CRC32 0x6a8ed689 Previous-GTIDs
  12.     '# 納尼。。這裡居然是empty。。。'
  13.     # [empty]
  14.     # at 154
  15.     '# 這裡是協調器執行緒報錯時的Exec_Master_Log_Pos位置，然而，由於使用多執行緒複製，這個報錯位置並不一定是workers執行緒真正觸發報錯的位置，我們需要查詢 performance_schema.replication_applier_status_by_worker表'\
  16.     '# 中查詢到的worker執行緒發生錯誤的位置，因為一旦有一個worker執行緒報錯，會觸發所有worker執行緒終止，協調器執行緒也會被終止'
  17.     #700101 8:00:00 server id 330614 end_log_pos 0 CRC32 0x122c770b Rotate to mysql-bin.000036 pos: 120336889
  18.     # at 201
  19.     '# 緊接著協調器執行緒停止的位置的event是relay log的FDE，說明協調器執行緒停止的位置並不是事務資料的event'
  20.     #170708 11:42:56 server id 330614 end_log_pos 0 CRC32 0x9433d36a Start: binlog v 4, server v 5.7.18-log created 170708 11:42:56
  21.     ......
  22.     # at 320
  23.     '# 這裡就是就觸發所有worker執行緒和協調器執行緒報錯停止的位置，這裡有啥好報錯的？仔細一看，這個Query event前面原本應該還有一個記錄一個GTID號的GTID event(開啟GTID複製時,'\
  24.     '# 對於DML語句，如果row格式複製，那麼在BEGIN語句前面一般都有用於記錄GTID的GTID event,EVENT中記錄的內容類似SET @@SESSION.GTID_NEXT= 'ec123678-5e26-11e7-9d38-000c295e08a0:34'/*!*/;，'\
  25.     '# 在5.7中，就算是使用傳統複製模式, 這個地方也會有一個GTID event，EVENT中記錄的內容類似：SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;)，現在卻缺失了!!!'
  26.     #170708 21:02:45 server id 330614 end_log_pos 120336968 CRC32 0x5a50ec65 Query thread_id=49 exec_time=0 error_code=0
  27.     SET TIMESTAMP=1499518965/*!*/;SET @@session.pseudo_thread_id=49/*!*/;
  28.     SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
  29.     SET @@session.sql_mode=1436549152/*!*/;
  30.     SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!*/;
  31.     /*!\C latin1 *//*!*/;
  32.     SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=83/*!*/;
  33.     SET @@session.lc_time_names=0/*!*/;
  34.     SET @@session.collation_database=DEFAULT/*!*/;
  35.     BEGIN
  36.     /*!*/;
  37.     # at 399
  38.     #170708 21:02:45 server id 330614 end_log_pos 120337151 CRC32 0xfebefb51 Rows_query
  39.     # UPDATE sbtest2 SET c='65170974949-02872074133-35491912643-76037682303-52924518173-58373441038-15151348493-46026501347-34340253549-84073419150' WHERE id=2476460
  40.     # at 582
  41.     #170708 21:02:45 server id 330614 end_log_pos 120337210 CRC32 0x6c83af43 Table_map: `sbtest`.`sbtest2` mapped to number 121
  42.     # at 641
  43.     #170708 21:02:45 server id 330614 end_log_pos 120337626 CRC32 0xde840c87 Update_rows: table id 121 flags: STMT_END_F
  44.     BINLOG
從上面的資訊中可以看到，Previous-GTIDs的event中原本應該記錄一個GTID SET的內容（類似：b57c75c2-6205-11e7-8d9f-525400a4b2e1:337711-412882），現在卻變成了" [empty]"，而後續緊接著的日誌中，Query event之前原本應該有個GTID event用於記錄GTID SET的，現在卻缺失了！！！神馬情況？
既然relay log中記錄的一個事務的binlog event組發生了丟失，那麼我們就去主庫的binlog中解析一把看看（解析 Relay_Master_Log_File: mysql-bin.000036,），從下面的資訊中我們可以看到主庫的binlog中120336968這個位置對應的事務完整的events組，其中GTID是"b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946"
  1. ......
  2.     # at 120336824
  3.     '# 這裡就是缺失的GTID EVENT'
  4.     #170708 21:02:45 server id 330614 end_log_pos 120336889 CRC32 0x5d86abf6 GTID last_committed=144511 sequence_number=144517
  5.     '# 缺失的GTID號'
  6.     SET @@SESSION.GTID_NEXT= 'b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946'/*!*/;
  7.     # at 120336889
  8.     #170708 21:02:45 server id 330614 end_log_pos 120336968 CRC32 0x5a50ec65 Query thread_id=49 exec_time=0 error_code=0
  9.     SET TIMESTAMP=1499518965/*!*/;
  10.     BEGIN
  11.     /*!*/;
  12.     # at 120336968
  13.     #170708 21:02:45 server id 330614 end_log_pos 120337151 CRC32 0xfebefb51 Rows_query
  14.     # UPDATE sbtest2 SET c='65170974949-02872074133-35491912643-76037682303-52924518173-58373441038-15151348493-46026501347-34340253549-84073419150' WHERE id=2476460
  15.     # at 120337151
  16.     #170708 21:02:45 server id 330614 end_log_pos 120337210 CRC32 0x6c83af43 Table_map: `sbtest`.`sbtest2` mapped to number 121
  17.     # at 120337210
  18.     #170708 21:02:45 server id 330614 end_log_pos 120337626 CRC32 0xde840c87 Update_rows: table id 121 flags: STMT_END_F
  19.     BINLOG
冷靜分析一下，從庫中的relay log為什麼缺失了？等等，在回頭看看執行操作前後的show slave status資訊，發現stop slave;change master to master_auto_position=0;start slave;之後的GTID相關資訊的差異如下：
  1. '# 執行切換之前：'
  2.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-731881
  3.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710502:710504
  4.     '# 執行切換之後：'
  5.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947-739082
  6.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875
  7.     '# 再看一下從庫的show master status資訊'
  8.     admin@localhost : sbtest 09:05:36> show master status;
  9.     +------------------+----------+--------------+------------------+-----------------------------------------------+
  10.     | File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
  11.     +------------------+----------+--------------+------------------+-----------------------------------------------+
  12.     | mysql-bin.000001 | 9717837 | | | b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-710875 |
  13.     +------------------+----------+--------------+------------------+-----------------------------------------------+
  14.     1 row in set (0.00 sec)
有問題！！我只是操作stop slave;change master to master_auto_position=0;start slave; 然而現在從我們能夠看到的資訊中有如下蹊蹺的地方：兩次show slave status輸出資訊中Retrieved_Gtid_Set的值完全沒有交集，前者GTID事務號是699054-731881，後者是732947-739082
Retrieved_Gtid_Set中最小的GTID比Executed_Gtid_Set最大的GTID還大22072個事務號
通過前面檢視從庫的relay log中，報錯的位置事務GTID事務號是b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946，正好+1之後正好是報錯時show slave status的Retrieved_Gtid_Set起始值，也就是說：就是由於這個事務（732946）的GTID EVENT缺失，同時由於relay log切換時，記錄GTID SET的Previous-GTIDs event記錄是[empty]，所以Retrieved_Gtid_Set最終計算起始值就從下一個事務，也就是 b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947開始計算了，那缺失的日誌去哪裡了？
我們解析一下mysql-relay-bin.000001，從下面的結果中可以看到，這個relay log中沒有任何資料相關的內容。那丟失的日誌去哪裡了？
  1. [root@luoxiaobo-02 relaylog]# mysqlbinlog -vv mysql-relay-bin.000001
  2.     mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'
  3.     /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
  4.     /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
  5.     DELIMITER /*!*/;
  6.     # at 4
  7.     #170708 21:02:53 server id 330615 end_log_pos 123 CRC32 0xc16fd9be Start: binlog v 4, server v 5.7.18-log created 170708 21:02:53 at startup
  8.     # This Format_description_event appears in a relay log and was generated by the slave thread.
  9.     # at 123
  10.     #170708 21:02:53 server id 330615 end_log_pos 194 CRC32 0xd425b7a8 Previous-GTIDs
  11.     # b57c75c2-6205-11e7-8d9f-525400a4b2e1:699054-732945
  12.     # at 194
  13.     #170708 21:02:56 server id 330615 end_log_pos 247 CRC32 0x43311780 Rotate to mysql-relay-bin.000002 pos: 4
  14.     SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
  15.     DELIMITER ;
  16.     # End of log file
  17.     /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
  18.     /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/
  • 分析到這裡，視乎也沒轍了。等等，一定是遺漏了什麼細節，我們先去官方翻一翻我們剛剛做的幾個動作stop slave;change master to master_auto_postion=0;start slave;時，mysql server後臺會做一些什麼事情
  • 功夫不負有心人，翻到了如下關鍵說明，大意是說，在基於GTID複製模式下轉換為基於檔案複製協議時，可以使用change master to master_auto_position=0語句，並且要指定MASTER_LOG_FILE和MASTER_LOG_POS選項（經驗證，如果不指定MASTER_LOG_FILE和MASTER_LOG_POS選項，則執行change master語句時，那麼SQL執行緒位置以IO執行緒位置為準，如果指定了MASTER_LOG_FILE和MASTER_LOG_POS選項，則IO執行緒位置以SQL執行緒位置為準），在5.7.4版本之後，使用change master to …語句時，如果IO和SQL執行緒都處於停止狀態，那麼將會刪除所有的relay log檔案，除非你同時指定了RELAY_LOG_FILE和RELAY_LOG_POS選項（經驗證，只要不指定RELAY_LOG_FILE和RELAY_LOG_POS選項就會刪除當前所有的relay log，無論其他選項如何指定）：

  • 也就是說，我們使用change master 語句的時候，只使用master_auto_position選項而不指定MASTER_LOG_FILE和MASTER_LOG_POS選項本身就是一種不規範的行為，再加上沒有指定RELAY_LOG_FILE和RELAY_LOG_POS選項，導致relay log被清理了，我們知道，在前面執行stop slave;語句時，我們可以看到還有複製延遲的（Seconds_Behind_Master: 47），也就是說，這部分複製延遲的relay log被清理可能就是導致worker執行緒發生錯誤的原因（缺失的GTID EVENT就記錄在被清理的relay log中）

  • 現在，原因我們應該找到了，但是還需要進一步確認，但根據目前的犯罪現場，已經調查不下去了，我們需要把複製先恢復之後，重新復現並在每一個步驟檢視盡可能全面的資訊以進行診斷。

  • 要恢復複製環境，我們可以把master_auto_position設定為1，根據GTID複製協議，設定為1啟動複製時，會根據公式"UNION(@@global.gtid_executed, Retrieved_gtid_set - last_received_GTID)"自動計算IO執行緒重新向主庫請求binlog的GTID SET，告訴主庫自己當前已經執行了哪些事務，主庫會把從庫缺失的事務傳送給從庫。所以理論上只需要把master_auto_position設定為1啟動的複製就可以恢復正常。

    1. admin@localhost : sbtest 09:52:41> stop slave;
    2.     Query OK, 0 rows affected (0.00 sec)
    3.     admin@localhost : sbtest 09:52:47> change master to master_auto_position=1;
    4.     Query OK, 0 rows affected (0.02 sec)
    5.     admin@localhost : sbtest 09:53:01> start slave;
    6.     Query OK, 0 rows affected (0.02 sec)
    7.     admin@localhost : sbtest 09:53:11> show slave status\G;
    8.     *************************** 1. row ***************************
    9.                    Slave_IO_State: Waiting for master to send event
    10.     ......
    11.                   Master_Log_File: mysql-bin.000036
    12.               Read_Master_Log_Pos: 127589755
    13.                    Relay_Log_File: mysql-relay-bin.000002
    14.                     Relay_Log_Pos: 849241
    15.             Relay_Master_Log_File: mysql-bin.000036
    16.                  Slave_IO_Running: Yes
    17.                 Slave_SQL_Running: Yes
    18.     ......
    19.               Exec_Master_Log_Pos: 102801341
    20.     ......
    21.             Seconds_Behind_Master: 3075
    22.     Master_SSL_Verify_Server_Cert: No
    23.                     Last_IO_Errno: 0
    24.                     Last_IO_Error:
    25.                    Last_SQL_Errno: 0
    26.                    Last_SQL_Error:
    27.     ......
    28.           Last_IO_Error_Timestamp:
    29.          Last_SQL_Error_Timestamp:
    30.     ......
    31.                Retrieved_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:710876-741652
    32.                 Executed_Gtid_Set: b57c75c2-6205-11e7-8d9f-525400a4b2e1:1-711894
    33.                     Auto_Position: 1
    34.     ...
    35.     1 row in set (0.01 sec)


  • 從上面的結果中，我們可以看到，從庫的複製恢復正常，現在，我們需要做的就是等待從庫的SQL執行緒追上IO執行緒，然後使用pt工具做一次主從資料校驗，從下面的結果中可以看到，測試庫sbtest在主從庫中資料一致，沒有差異
    1. [root@luoxiaobo-01 ~]# pt-table-checksum --nocheck-replication-filters --no-check-binlog-format --replicate=xiaoboluo.checksums --databases sbtest h=localhost,u=admin,p=letsg0,P=3306
    2.     Checksumming sbtest.sbtest1: 57% 00:24 remain
    3.                 TS ERRORS DIFFS ROWS CHUNKS SKIPPED TIME TABLE
    4.     07-08T22:19:10 0 0 5007738 28 0 59.849 sbtest.sbtest1
    5.     Checksumming sbtest.sbtest2: 49% 00:30 remain
    6.     Checksumming sbtest.sbtest2: 97% 00:01 remain
    7.     07-08T22:20:17 0 0 5007905 27 0 67.127 sbtest.sbtest2
    8.     Checksumming sbtest.sbtest3: 52% 00:27 remain
    9.     07-08T22:21:23 0 0 5007858 28 0 65.440 sbtest.sbtest3
    10.     Checksumming sbtest.sbtest4: 48% 00:32 remain
    11.     Checksumming sbtest.sbtest4: 92% 00:04 remain
    12.     07-08T22:22:35 0 0 5007914 29 0 71.766 sbtest.sbtest4
    13.     Checksumming sbtest.sbtest5: 61% 00:19 remain
    14.     07-08T22:23:38 0 0 5007412 29 0 63.463 sbtest.sbtest5
    15.     Checksumming sbtest.sbtest6: 58% 00:21 remain
    16.     07-08T22:24:38 0 0 5007473 29 0 59.838 sbtest.sbtest6
    17.     Checksumming sbtest.sbtest7: 53% 00:27 remain
    18.     07-08T22:25:44 0 0 5007216 29 0 66.526 sbtest.sbtest7
    19.     Checksumming sbtest.sbtest8: 50% 00:29 remain
    20.     07-08T22:26:47 0 0 5007273 28 0 62.753 sbtest.sbtest8
    21.     '# 如果DIFFS列出現有不為0值時，就表示主備資料不一致，可以執行如下語句執行同步，同步之後再次執行pt-table-checksum校驗直到DIFFS列不會出現0值為止'
    22.     pt-table-sync --replicate=xiaoboluo.checksums --databases sbtest h=localhost,u=admin,p=letsg0,P=3306 --execute
    • 為什麼計算公式中會有一個減去last_received_GTID呢？根據官方文件描述，在5.7.5版本之前是不會減去last_received_GTID的，但在5.7.5之後會減去last_received_GTID，因為。。IO執行緒正在持續不斷地讀取主庫binlog時，是以event為單位進行讀取的，而一個事務包含了一個event組，所以突然執行stop slave或者其他異常行為時，可能導致一個事務只讀取了部分event，如果不減去這個binlog讀取不完整的GTID，有可能導致SQL執行緒複製報錯終止。下圖是官方對於這個計算公式的解釋：

  • 現在，我們來重現復現步驟吧

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

相關文章