沃趣科技  羅小波

---

1、復(fù)現(xiàn)與簡(jiǎn)單分析
2、重新復(fù)現(xiàn)、詳細(xì)分析與驗(yàn)證
2.1. 重新復(fù)現(xiàn)與詳細(xì)分析
2.1.1. stop slave
2.1.2. change master to master_auto_position=0
2.1.3. start slave
2.2. 解決方法驗(yàn)證
3、總結(jié)
今天咱們同事說(shuō)碰到一個(gè)古怪的問(wèn)題，說(shuō)MySQL 5.7.18上，主從復(fù)制結(jié)構(gòu)中，從庫(kù)在使用change master語(yǔ)句切換master_auto_position=1為0時(shí)，SQL線程報(bào)錯(cuò)了([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)，然后，出于嘗試修復(fù)，又改成了1，重新啟動(dòng)復(fù)制就恢復(fù)正常了，然后再改成0重新啟動(dòng)復(fù)制，這個(gè)時(shí)候發(fā)生數(shù)據(jù)丟失了，再反復(fù)切換幾次之后，MySQL crash了。。，當(dāng)時(shí)我聽(tīng)到這個(gè)問(wèn)題的第一反應(yīng)就是：一臉懵逼（因?yàn)?782錯(cuò)誤通常是發(fā)生復(fù)制架構(gòu)啟用GTID復(fù)制之后，從庫(kù)IO線程讀取到主庫(kù)的ANONYMOUS 事務(wù)時(shí)報(bào)錯(cuò)）。。然后，發(fā)了一陣呆之后，想到了一些可能導(dǎo)致這個(gè)問(wèn)題的原因，下文我們通過(guò)"復(fù)現(xiàn)與簡(jiǎn)單分析"、"重新復(fù)現(xiàn)、詳細(xì)分析與驗(yàn)證"、"總結(jié)"三個(gè)步驟來(lái)對(duì)這個(gè)問(wèn)題的前因后果進(jìn)行一次透析，大家請(qǐng)跟隨我往下看。
先列出硬件配置、操作系統(tǒng)和數(shù)據(jù)庫(kù)環(huán)境信息

環(huán)境信息

主要從事網(wǎng)頁(yè)設(shè)計(jì)、PC網(wǎng)站建設(shè)（電腦版網(wǎng)站建設(shè)）、wap網(wǎng)站建設(shè)（手機(jī)版網(wǎng)站建設(shè)）、成都響應(yīng)式網(wǎng)站建設(shè)、程序開(kāi)發(fā)、微網(wǎng)站、小程序制作等，憑借多年來(lái)在互聯(lián)網(wǎng)的打拼，我們?cè)诨ヂ?lián)網(wǎng)網(wǎng)站建設(shè)行業(yè)積累了豐富的成都網(wǎng)站制作、成都網(wǎng)站建設(shè)、網(wǎng)絡(luò)營(yíng)銷(xiāo)經(jīng)驗(yàn)，集策劃、開(kāi)發(fā)、設(shè)計(jì)、營(yíng)銷(xiāo)、管理等多方位專(zhuān)業(yè)化運(yùn)作于一體，具備承接不同規(guī)模與類(lèi)型的建設(shè)項(xiàng)目的能力。

操作系統(tǒng)：CentOS Linux release 7.2.1511 (Core)
sysbench版本：sysbench-0.5-3.el6.x86_64
* 使用sysbench造數(shù)8張500W數(shù)據(jù)的表
percona-toolkit版本：percona-toolkit-3.0.3-1.el7.x86_64
percona-xtrabackup版本：percona-xtrabackup-24-2.4.4-1.el7.x86_64
數(shù)據(jù)庫(kù)版本：MySQL 5.7.18
數(shù)據(jù)庫(kù)配置關(guān)鍵參數(shù)：

• * 主庫(kù)：雙一，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 
• * 從庫(kù)：雙一，雙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

主機(jī)配置硬件配置：

• * CPU：4 vcpus 
• * 內(nèi)存：8G 
• * 磁盤(pán)：50G SSD 
• * 網(wǎng)卡：Speed: 100Mb/s

IP：

• * 主庫(kù)：10.10.20.14 
• * 從庫(kù)：10.10.20.15

鄭重聲明：本文僅供學(xué)習(xí)交流，請(qǐng)勿在生產(chǎn)環(huán)境試車(chē)?。?br />

1、復(fù)現(xiàn)與簡(jiǎn)單分析

首先，我們使用主庫(kù)中造好數(shù)的備份，與從庫(kù)搭建主從復(fù)制結(jié)構(gòu)（sysbench造數(shù)和搭建主備復(fù)制步驟省略），從庫(kù)初始搭建時(shí)使用master_auto_position=1啟動(dòng)復(fù)制
主庫(kù)使用如下sysbench語(yǔ)句加壓

• 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

現(xiàn)在，我們準(zhǔn)備把從庫(kù)切換master_auto_position=0
先在從庫(kù)上執(zhí)行一下show slave status\G;語(yǔ)句查看一下復(fù)制狀態(tài)，從下面的結(jié)果中可以看到，一切正常

• 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)

執(zhí)行master_auto_position=0
從上面的結(jié)果中可以看到，SQL線程報(bào)錯(cuò)了，從Last_SQL_Error字段顯示的信息中我們可以得知，是某個(gè)workers線程報(bào)錯(cuò)了，讓查詢錯(cuò)誤日志或者performance_schema.replication_applier_status_by_worker table表（為了防止備庫(kù)繼續(xù)落后于主庫(kù)，現(xiàn)在，我們把sysbench先停止）
現(xiàn)在，我們來(lái)查詢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)

發(fā)生什么了？主庫(kù)的gtid_mode參數(shù)只有在設(shè)置為OFF和OFF_PERMISSIVE的時(shí)候，才會(huì)產(chǎn)生ANONYMOUS 事務(wù)并寫(xiě)入binlog中，而此時(shí)主庫(kù)的gtid_mode配置參數(shù)是絕對(duì)沒(méi)有人動(dòng)過(guò)的，而且在執(zhí)行上述操作之前，從庫(kù)以GTID復(fù)制模式一直都工作得很正常，另外，通常這個(gè)錯(cuò)誤是發(fā)生在IO線程讀取主庫(kù)的binlog時(shí)發(fā)生，SQL線程報(bào)這個(gè)錯(cuò)誤還是頭一次見(jiàn)。。尷尬。保險(xiǎn)起見(jiàn)，還是到主庫(kù)查看一下gtid_mode的值
從上面的結(jié)果中可以看到，主庫(kù)的gtid_mode參數(shù)并被修改過(guò)，既然SQL線程報(bào)了1782錯(cuò)誤，那么我們就解析一下relay log，找到Exec_Master_Log_Pos: 120336889（協(xié)調(diào)器線程停止的位置）和worker線程報(bào)錯(cuò)的位置120336968（報(bào)錯(cuò)的worker線程停止的位置），到底是不是ANONYMOUS 事務(wù)（注意，這個(gè)pos是主庫(kù)的binlog pos，不是relay log的pos，不能使用--start-position選項(xiàng)）
從上面的信息中可以看到，Previous-GTIDs的event中原本應(yīng)該記錄一個(gè)GTID SET的內(nèi)容（類(lèi)似：b57c75c2-6205-11e7-8d9f-525400a4b2e1:337711-412882），現(xiàn)在卻變成了" [empty]"，而后續(xù)緊接著的日志中，Query event之前原本應(yīng)該有個(gè)GTID event用于記錄GTID SET的，現(xiàn)在卻缺失了！??！神馬情況？
既然relay log中記錄的一個(gè)事務(wù)的binlog event組發(fā)生了丟失，那么我們就去主庫(kù)的binlog中解析一把看看（解析 Relay_Master_Log_File: mysql-bin.000036,），從下面的信息中我們可以看到主庫(kù)的binlog中120336968這個(gè)位置對(duì)應(yīng)的事務(wù)完整的events組，其中GTID是"b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946"
冷靜分析一下，從庫(kù)中的relay log為什么缺失了？等等，在回頭看看執(zhí)行操作前后的show slave status信息，發(fā)現(xiàn)stop slave;change master to master_auto_position=0;start slave;之后的GTID相關(guān)信息的差異如下：
有問(wèn)題！！我只是操作stop slave;change master to master_auto_position=0;start slave; 然而現(xiàn)在從我們能夠看到的信息中有如下蹊蹺的地方：兩次show slave status輸出信息中Retrieved_Gtid_Set的值完全沒(méi)有交集，前者GTID事務(wù)號(hào)是699054-731881，后者是732947-739082
Retrieved_Gtid_Set中最小的GTID比Executed_Gtid_Set最大的GTID還大22072個(gè)事務(wù)號(hào)
通過(guò)前面查看從庫(kù)的relay log中，報(bào)錯(cuò)的位置事務(wù)GTID事務(wù)號(hào)是b57c75c2-6205-11e7-8d9f-525400a4b2e1:732946，正好+1之后正好是報(bào)錯(cuò)時(shí)show slave status的Retrieved_Gtid_Set起始值，也就是說(shuō)：就是由于這個(gè)事務(wù)（732946）的GTID EVENT缺失，同時(shí)由于relay log切換時(shí)，記錄GTID SET的Previous-GTIDs event記錄是[empty]，所以Retrieved_Gtid_Set最終計(jì)算起始值就從下一個(gè)事務(wù)，也就是 b57c75c2-6205-11e7-8d9f-525400a4b2e1:732947開(kāi)始計(jì)算了，那缺失的日志去哪里了？
我們解析一下mysql-relay-bin.000001，從下面的結(jié)果中可以看到，這個(gè)relay log中沒(méi)有任何數(shù)據(jù)相關(guān)的內(nèi)容。那丟失的日志去哪里了？

• 分析到這里，視乎也沒(méi)轍了。等等，一定是遺漏了什么細(xì)節(jié)，我們先去官方翻一翻我們剛剛做的幾個(gè)動(dòng)作stop slave;change master to master_auto_postion=0;start slave;時(shí)，mysql server后臺(tái)會(huì)做一些什么事情

• 功夫不負(fù)有心人，翻到了如下關(guān)鍵說(shuō)明，大意是說(shuō)，在基于GTID復(fù)制模式下轉(zhuǎn)換為基于文件復(fù)制協(xié)議時(shí)，可以使用change master to master_auto_position=0語(yǔ)句，并且要指定MASTER_LOG_FILE和MASTER_LOG_POS選項(xiàng)（經(jīng)驗(yàn)證，如果不指定MASTER_LOG_FILE和MASTER_LOG_POS選項(xiàng)，則執(zhí)行change master語(yǔ)句時(shí)，那么SQL線程位置以IO線程位置為準(zhǔn)，如果指定了MASTER_LOG_FILE和MASTER_LOG_POS選項(xiàng)，則IO線程位置以SQL線程位置為準(zhǔn)），在5.7.4版本之后，使用change master to …語(yǔ)句時(shí)，如果IO和SQL線程都處于停止?fàn)顟B(tài)，那么將會(huì)刪除所有的relay log文件，除非你同時(shí)指定了RELAY_LOG_FILE和RELAY_LOG_POS選項(xiàng)（經(jīng)驗(yàn)證，只要不指定RELAY_LOG_FILE和RELAY_LOG_POS選項(xiàng)就會(huì)刪除當(dāng)前所有的relay log，無(wú)論其他選項(xiàng)如何指定）：
  
  

• 也就是說(shuō)，我們使用change master 語(yǔ)句的時(shí)候，只使用master_auto_position選項(xiàng)而不指定MASTER_LOG_FILE和MASTER_LOG_POS選項(xiàng)本身就是一種不規(guī)范的行為，再加上沒(méi)有指定RELAY_LOG_FILE和RELAY_LOG_POS選項(xiàng)，導(dǎo)致relay log被清理了，我們知道，在前面執(zhí)行stop slave;語(yǔ)句時(shí)，我們可以看到還有復(fù)制延遲的（Seconds_Behind_Master: 47），也就是說(shuō)，這部分復(fù)制延遲的relay log被清理可能就是導(dǎo)致worker線程發(fā)生錯(cuò)誤的原因（缺失的GTID EVENT就記錄在被清理的relay log中）

• 現(xiàn)在，原因我們應(yīng)該找到了，但是還需要進(jìn)一步確認(rèn)，但根據(jù)目前的犯罪現(xiàn)場(chǎng)，已經(jīng)調(diào)查不下去了，我們需要把復(fù)制先恢復(fù)之后，重新復(fù)現(xiàn)并在每一個(gè)步驟查看盡可能全面的信息以進(jìn)行診斷。

• 要恢復(fù)復(fù)制環(huán)境，我們可以把master_auto_position設(shè)置為1，根據(jù)GTID復(fù)制協(xié)議，設(shè)置為1啟動(dòng)復(fù)制時(shí)，會(huì)根據(jù)公式"UNION(@@global.gtid_executed, Retrieved_gtid_set - last_received_GTID)"自動(dòng)計(jì)算IO線程重新向主庫(kù)請(qǐng)求binlog的GTID SET，告訴主庫(kù)自己當(dāng)前已經(jīng)執(zhí)行了哪些事務(wù)，主庫(kù)會(huì)把從庫(kù)缺失的事務(wù)發(fā)送給從庫(kù)。所以理論上只需要把master_auto_position設(shè)置為1啟動(dòng)的復(fù)制就可以恢復(fù)正常。

  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)

  
  

• 從上面的結(jié)果中，我們可以看到，從庫(kù)的復(fù)制恢復(fù)正常，現(xiàn)在，我們需要做的就是等待從庫(kù)的SQL線程追上IO線程，然后使用pt工具做一次主從數(shù)據(jù)校驗(yàn)，從下面的結(jié)果中可以看到，測(cè)試庫(kù)sbtest在主從庫(kù)中數(shù)據(jù)一致，沒(méi)有差異
• 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列出現(xiàn)有不為0值時(shí)，就表示主備數(shù)據(jù)不一致，可以執(zhí)行如下語(yǔ)句執(zhí)行同步，同步之后再次執(zhí)行pt-table-checksum校驗(yàn)直到DIFFS列不會(huì)出現(xiàn)0值為止'
      
  22.     pt-table-sync --replicate=xiaoboluo.checksums --databases sbtest h=localhost,u=admin,p=letsg0,P=3306 --execute

• • 為什么計(jì)算公式中會(huì)有一個(gè)減去last_received_GTID呢？根據(jù)官方文檔描述，在5.7.5版本之前是不會(huì)減去last_received_GTID的，但在5.7.5之后會(huì)減去last_received_GTID，因?yàn)?。。IO線程正在持續(xù)不斷地讀取主庫(kù)binlog時(shí)，是以event為單位進(jìn)行讀取的，而一個(gè)事務(wù)包含了一個(gè)event組，所以突然執(zhí)行stop slave或者其他異常行為時(shí)，可能導(dǎo)致一個(gè)事務(wù)只讀取了部分event，如果不減去這個(gè)binlog讀取不完整的GTID，有可能導(dǎo)致SQL線程復(fù)制報(bào)錯(cuò)終止。下圖是官方對(duì)于這個(gè)計(jì)算公式的解釋?zhuān)?
    
    

• 現(xiàn)在，我們來(lái)重現(xiàn)復(fù)現(xiàn)步驟吧

文章題目：MySQL5.7復(fù)制配置不規(guī)范修改導(dǎo)致的坑（一）
本文路徑：http://weahome.cn/article/gpdjhj.html