作者介紹

王鬆磊，現任職於UCloud，從事MySQL資料庫核心研發工作，主要負責UCloud雲資料庫UDB的核心故障排查工作以及資料庫新特性的研發工作。

複製作為MySQL原生的資料同步功能，在MySQL高可用架構中起著至關重要的作用。本文梳理了MySQL高可用產品UDB在日常運維中遇到的複製問題，並總結了當複製發生異常時，排查複製異常的方法。

一、錯誤排查

1、收集複製資訊

在複製發生異常時，我們首先要收集複製相關的資訊以及錯誤相關的資訊，主要通過如下手段收集。

（1）檢視show slave status

執行命令”show slave status”檢視複製相關資訊。主要關注以下幾條資訊：

Master_Log_File: mysql-bin.000063

Read_Master_Log_Pos: 282657539

IO執行緒讀取到的主庫的binlog檔名和該binlog中的位置。這兩個欄位代表複製過程中binlog由主庫傳輸到備庫的進度。

Relay_Log_File: mysql-relay.000002

Relay_Log_Pos: 313885

SQL執行緒執行到的relay log的檔名和該relay log中的位置。

Relay_Master_Log_File: mysql-bin.000002

Exec_Master_Log_Pos: 316585

SQL執行緒執行到的relay log對應的主庫中的binlog檔名和該binlog的位置。

這四個欄位代表複製過程中，主庫的資料在備庫上重放的進度。

Slave_IO_Running: Yes

Slave_SQL_Running: No

當前發生問題的是哪個執行緒，IO執行緒或者時SQL執行緒。

Retrieved_Gtid_Set: ed7c5ee4-762d-11e6-ab9e-6c92bf24c36a:14-3920163

Executed_Gtid_Set: 04ffb4f5-762e-11e6-81e4-6c92bf26c5c2:1

這兩個欄位在開啟GTID後才有意義。分別代表IO執行緒接收到的binlog中的事務對應的GTID和SQL執行緒執行過的事務對應的GTID。

這裡的GTID不會因為複製而發生改變

Last_Errno/Last_IO_Errno/Last_SQL_Errno

Laset_Error/Last_IO_Error/Last_SQL_Error

IO/SQL執行緒發生的錯誤的相關描述。

（2）檢視錯誤日誌

錯誤日誌記錄了mysqld發生的錯誤資訊，即複製的錯誤資訊，同時也會記錄複製的開始和停止的相關資訊，記錄位置可以通過如下方式檢視：

在error log中，主要關注如下的資訊。

開始複製（start slave）

在從庫啟動複製時，error log中會記錄複製起始位置，包括IO執行緒讀取主庫端binlog的起始位置和SQL執行緒執行的relay log的起始位置。同時error log中還會記錄開始複製的具體時間。

停止複製（stop slave）

在從庫停止複製時，error log會記錄IO執行緒停止時讀取到的主庫的binlog的位置，以及停止複製的時間。

複製錯誤資訊

複製錯誤資訊的描述會在show slave status中的last_error中展現，但是如果錯誤資訊較長的話（尤其是在多執行緒複製的情況下），show slave status並不能完全的顯示錯誤的全部資訊，需要檢視錯誤日誌才能檢視到完整的錯誤資訊。比如

上述錯誤資訊並不是一個完整的錯誤資訊描述，可以在error log中看到更完成的資訊描述，以及發生錯誤的時間。

（3）檢視二進位制日誌檔案

這裡的二進位制日誌檔案包括主庫的binlog、從庫的relay log、從庫的binlog。

• 主庫的binlog是指主庫執行過的事務記錄的binlog日誌。
• 從庫的relay log是指從庫接收到的主庫的binlog日誌。
• 從庫的binlog是指從庫SQL執行緒復現relay log後記錄的日誌（log-slave-updates開啟）以及從庫執行過的事務記錄的binlog日誌。

二進位制日誌檔案中記錄的日誌是以event為單位進行記錄，比如一個DML語句通常由4-5個event組成，一個DDL語句通常由2個event組成。

二進位制日誌檔案可以通過命令“show binlog events”或者工具mysqlbinlog來將binlog日誌轉換為可識別的格式。

show binlog events格式如下：

上圖顯示的為ROW格式的binlog中記錄的內容，其中包含了一個DML語句和一條DDL語句。DML語句包含了GTID、QUERY、TABLE_MAP、WRITE_ROW、XID五個event，DDL語句包含了GTID、QUERY兩個event。

mysqlbinlog工具同樣可以解析binlog，提供與show binlog event類似的event資訊，以其中一個event為例來說明：

• Event的時間為主庫執行事務的時間，無論從庫的relay log和binlog，時間均為主庫執行事務的時間
• Event的server_id記錄的是執行該事務的資料庫的server_id，可以用來區分這條事務是主庫還是從庫執行的
• Event 的end_log_pos從庫的relay log中的end_log_pos為對應的主庫中的binlog的該event的真實檔案位置主庫和從庫的binlog中的end_log_pos為該binlog的檔案真實位置
• EVENT的at xxxat xxx代表該event在檔案中的真實位置

對於以上的二進位制日誌檔案的內容，我們需要關注的資訊包括：

1. Previous_gtids events記錄了當前binlog之前執行過的所有的gtid資訊，用來定位具體的gtid。
2. GTID event中對應的GTID，與事務是一一對應的，表名該事務是由主庫執行還是由重庫執行的。
3. 當錯誤發生時，事務執行的時間，事務的執行具體語句。
4. 主庫執行資料庫操作後，將相關日誌記錄到主庫的binlog中。備庫的IO執行緒接收到主庫傳輸的binlog日誌後，將這些日誌記錄到relay log中，如果備庫開啟了log_slave_updates選項，那麼SQL執行緒在重放relay log的過程中，會記錄相關binlog日誌。這三個二進位制檔案日誌，執行內容上應該是相同的。

（4）檢視其他變數

檢視其他複製相關的系統變數或者狀態，如：

• 執行“show variables like‘gtid_mode’”檢視gtid是否開啟；
• 執行“show status like ‘Rpl_semi_sync_master_status’”檢視半同步複製的狀態。

這裡不再一一列舉。

二、排查錯誤

在收集到以上覆制資訊後，主要通過如下手段排查複製錯誤：

1、檢視show slave status

• 檢視發生錯誤的是哪個執行緒（IO執行緒或者SQL執行緒），檢視錯誤原因；
• 如果是IO執行緒發生錯誤，記錄發生錯誤時接收到的binlog的檔名和位置（如果開啟了GTID則記錄GTID）；
• 如果是SQL執行緒發生錯誤，記錄發生錯誤時執行到的relay log的檔名和位置（如果開啟了GTID則記錄GTID）。

2、檢視錯誤日誌

進一步確認發生錯誤的原因，部分原因只會記錄在錯誤日誌中，不會在show slave status中展示。比如空間不足導致IO執行緒出錯、比如網路中斷導致IO執行緒異常等等。

檢視是否是由於其他使用者正常關閉複製或者kill複製相關的執行緒導致複製不可用。

檢視發生錯誤時，是否為剛剛啟動複製、發生錯誤的語句是否為第一條複製執行的語句。如果為第一條語句，則需要考慮是否由於搭建複製錯誤的原因導致複製異常，是否由於意外宕機等其他因素導致複製相關二進位制日誌檔案不正確。

對比主庫和備庫的錯誤日誌，檢視是否均發生了同樣的複製錯誤，是否主庫做了特殊的錯誤處理。

3、對比二進位制日誌檔案

對比備庫正在接收的binlog與主庫正在執行的binlog是否存在衝突（備庫接收的binlog的檔案和位置要大於主庫執行的）。

如果開啟了GTID，檢視備庫是否本身執行了資料庫操作產生了GTID，檢視備庫執行過的GTID是否要多於主庫，備庫是否執行過其他主機的GTID。

根據發生錯誤時的binlog的檔案和位置（或者GTID），解析主庫和備庫的二進位制檔案，對比相同的檔案和位置（或者相同的GTID）時日誌中記錄的操作是否相同。

檢視備庫的二進位制檔案，備庫是否執行過與主庫衝突的操作。

總結

對於處於正常狀態的複製，應處於以下狀態：

• 檢視複製狀態應該是正常狀態，如show slave status顯示IO執行緒和SQL執行緒的執行狀態均為YES，如半同步複製中show status like “rpl%”顯示的半同步複製狀態為ON。
• 主庫和備庫均沒有複製相關的錯誤資訊報出。
• 主庫和備庫的二進位制日誌檔案中記錄的資料庫操作內容應一致，主庫和備庫中的資料內容應保持一致。

通過對比分析上述資訊，檢視異常的狀態或者日誌，可以為我們排查複製相關的錯誤提供更多的幫助。

三、版本和配置

總體來說，版本和配置的不同，只是會造成各種資訊的顯示格式不同，並不會對上述的方法造成過多的影響。

1、版本

上述資訊收集和分析的舉例均是在mysql-5.7版本上進行的舉例，不同的大版本在資訊的內容或者資訊的存放方式上可能存在一定的差異。

mysql-5.6版本與mysql-5.7版本在複製相關資訊上存在以下差異：

日誌：

在mysql-5.6在停止複製時，error log會有錯誤的資訊記錄：

GTID：

mysql-5.6的gtid_executed以global system variables的方式的展現，mysql-5.7是以mysql.gtid_executed表的方式展現。

BINLOG：

mysql-5.6版本在使用自增ID時，會使用如下event來記錄自增ID。

#170419 11:27:12 server id 30061  end_log_pos 494 CRC32 0x7a9f75c6      Intvar

SET INSERT_ID=1/*!*/;

2、配置

主要體現差異的配置包括gtid_mode和binlog_format。

（1）gtid_mode

當gtid開啟時，gtid作為判斷事務是由誰執行，是否執行過、事務接收和執行進度的判斷標準。同時可以通過show slave status可以直觀的看出gtid的接收、執行的情況。

當gtid關閉時，file和pos作為接收和執行的判斷標準，server_id作為事務由誰執行的標準。但是事務對應的所有的server_id並沒有完全的展現出來，所以對於我們排查問題，造成一定的困難。

（2）binlog_format

binlog_format影響的是記錄到binlog中的日誌內容的格式，以同一條INSERT語句為例，statement格式記錄到binlog中的格式如下（只顯示差異部分）：

row格式記錄到binlog中的格式如下：

四、常見覆制錯誤原因及分析過程

在收集到上述複製相關資訊和錯誤資訊後，我們需要根據實際的錯誤資訊進行分析，這裡羅列了幾種常見的複製錯誤，我們可以通過部分或者全部在上述章節收集的相關資訊，分析出複製錯誤發生原因。

1、從庫執行語句與主庫衝突

（1）錯誤原因

從庫執行DML語句或者DDL語句後，主庫和從庫會出現資料不一致的情況。從而導致主庫執行的語句在從庫沒有辦法正常執行。

（2）錯誤資訊

由於從庫執行與主庫衝突的語句而導致複製錯誤，常見的錯誤資訊如下：

建立庫或者表失敗

插入語句主鍵衝突

刪除語句找不到對應的語句

由於這是比較常見的原因，所有導致主從衝突的操作均會導致複製出錯，這裡不再一一列舉。

（3）原因分析過程

這裡以由於資料庫存在而導致建立資料庫出錯為例來分析原因。

檢視error log

Error log中顯示的詳細錯誤資訊如下：

顯示在執行GTID 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6時失敗。錯誤原因為資料庫已經存在，無法建立。

檢視show slave status

當錯誤發生後，檢視show slave status顯示的資訊時，會發現如下資訊：

在Executed_Gtid_Set顯示的資訊中，除了Master的UUID對應的GTID外，還存在另外一個GTID，我們可以檢視從庫的GTID，執行如下語句：

發現另外的GTID是由從庫執行而產生的。

檢視從庫binlog日誌

從庫binlog日誌記錄的是SQL執行緒復現的主機的binlog資訊或者時從庫本身執行的事務的binlog日誌。這些事務是可以通過server_id或者GTID來區分。

這裡以建立資料庫失敗為例，在從庫binlog中，查詢3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1對應的事務，發現如下資訊：

檢視從庫relay log日誌

從庫relay log日誌記錄的是IO執行緒從主庫接收到的binlog日誌資訊，我們檢視執行失敗的GTID對應的事務資訊：

總結

最終可以確認是由於從庫執行了建立資料庫語句後，SQL執行緒再次執行建立資料庫的語句時發生複製失敗的情況。

2、主庫的binlog丟失

（1）錯誤原因

複製過程中，由於從庫需要讀取的主庫的binlog丟失，從而導致複製發生異常。導致主庫binlog丟失的主要原因如下：

• 主庫執行reset master命令
• 主庫執行purge binary/master logs命令
• 主庫設定了expire_logs_days，自動刪除了binlog
• 主庫的binlog被誤刪除

（2）錯誤資訊

如果發生找不到主機binlog的情況，從庫error log會報出如下錯誤：

（3）原因分析過程

檢視error log

Error log中顯示的詳細錯誤資訊如下：

錯誤資訊顯示無法找到對應的binlog檔案。

檢視主庫binlog日誌

檢視主庫的binlog日誌檔案列表，可能會發現主庫的binlog變成重新開始記錄：

或者需要複製的binlog已經被刪除：

總結

如果binlog重新開始記錄，通常是由於主庫執行了reset master命令，導致所有的binlog被刪除。

如果binlog任然在繼續記錄，只是從庫需要的binlog被刪除，通常是由於主庫手動執行了purge binary logs命令，或者日誌的保留時間超過了expire_logs_days設定的時間。

3、從庫沒有執行主庫複製的語句

由於GTID的特性，SQL執行緒不會去執行相同的GTID對應的事務，即如果SQL執行緒發現從relay log中讀取到的事務對應的GTID已經存在於從庫的GTID_EXECUTED中，那麼SQL執行緒便不會存在。

（1）錯誤原因

複製過程中，用於主庫執行的事務對應的GTID已經存在於從庫的GTID_EXECUTED中，那麼從庫便不會執行這些事務，從而導致主庫和從庫的資料不一致。通常有如下情況：

• 主機執行了reset master（從庫當前讀取主機的第一個binlog，並不會因為reset master而導致找不到檔案）
• 重做主從，從庫沒有清除從庫的binlog

（2）錯誤資訊

在從庫忽略主機執行的事務的過程中，從庫複製不會報出任何錯誤，所以這種複製的異常容易被忽略，沒有辦法及時的發現。

由於主庫和從庫的資料庫不一致，後續的DML和DDL操作可能會發生執行失敗的錯誤。

（3）原因分析過程

這裡我們以插入語句找不到對應的表為例。

檢視error log

Error log中記錄錯誤資訊：

檢視show slave status

show slave status顯示的資訊全部正常，無從庫執行事務的binlog產生。這裡不排除從庫關閉binlog執行drop table操作的可能。

查看錶

分別在主機和從庫執行命令show create table mydb.mytbl4，發現從庫上並未不存在mydb.mytbl4。

（4）解析binlog日誌

解析主機binlog日誌，檢視建表的事務日誌：

解析從庫的binlog日誌，查詢是否存在建表的事務日誌：

這時我們發現對於相同的GTID，從庫和主機執行的語句是不相同的。

（5）總結

通過上述分析，我們推斷是從庫並沒有執行建表語句，從而導致主庫資料不一致。

（6）說明

這種情況在mysql-5.7版本會在複製時有更嚴格的校驗，如果主機發送GTID要少於從庫的GTID，那麼會報告出如下的錯誤：

但是即使在5.7版本，如果啟動複製的時（錯誤後重新啟動），主庫執行的GTID超過了從庫，仍然會報出同樣的錯誤。

4、主庫執行了不進行復制的語句

（1）錯誤原因

主庫上執行的操作並不會寫入binlog。這裡不考慮主庫主動關閉binlog的情況。

（2）錯誤資訊

由於主庫和從庫的資料不一致，從而導致主庫執行的操作複製到從庫後，發生從庫執行失敗的情況。如：

建立FEDERATED引擎的表失敗

（3）原因分析過程

這裡以使用CONNECTION建立FEDERATED引擎的表為例。

檢視error log

Error log中記錄錯誤資訊：

檢視主庫和從庫的server表

主庫中server表中存在名字為s的記錄：

從庫中不存在名字為s的記錄：

檢視CREATE SERVER文件說明

文件中記錄，create server語句並不會記錄到binlog中。所以導致了主庫和從庫的資料不一致。複製無法正常進行。

總結

對於不記入binlog的操作，需要主庫和從庫同時執行，以防發生主庫和從庫不一致的情況。

5、從庫重複執行relay log的語句（非GTID，非多執行緒複製）

當變數relay_log_info_repository設定為FILE時，從庫的SQL執行緒每次執行完一個事務後，會把對應的檔案和位置資訊更新到檔案relay_log.info中。用於在從庫重啟時，SQL能夠從正確的位置繼續進行復制。

（1）錯誤原因

如果物理機發生宕機或者從庫發生意外中斷，那麼可能發生SQL執行緒已經執行過了某一個relay log中的事務，但是這個事務對應檔案和位置資訊並沒有及時更新到relay_log.info中的情況。在從庫發生重啟之後，會將執行過的事務重新再次執行。

（2）錯誤資訊

重複執行的事務包括任何記錄到relay log中的事務，可能出現的錯誤資訊包括：

建立庫或者表失敗：

插入語句主鍵衝突：

刪除語句找不到對應的語句：

由於各種型別的事務均可能執行，這裡不再一一列舉。

（3）原因分析過程

這裡以插入語句主鍵衝突為例。

檢視error log

Error log中記錄以下報錯資訊：

可以看到是SQL執行緒在啟動後執行的第一個事務就發生主鍵衝突的錯誤。

檢視show slave status

show slave status顯示的資訊全部正常，無從庫執行事務的binlog產生。

查看錶mydb.k2

表中已經存在了這條記錄。

檢視從庫的relay log和binlog

檢視從庫的relay log，從複製的起始位置./relaylog002.000002：616檢視

檢視從庫的binlog：

總結

通過分析上述binlog內容，relay log中並沒有記錄相同的insert語句，而從庫的binlog顯示已經執行過該語句，當從庫重啟後，試圖再次執行相同的insert語句，從而導致插入語句的主鍵衝突。

說明

如果複製使用GTID，那麼GTID的特性會使從庫不執行相同的語句。

如果在5.7版本複製使用多執行緒複製，那麼mts_recovery會修復這個問題。

只有在非多執行緒複製、非GTID複製的情況下才可能出現這個錯誤。

五、總結

如果複製發生了錯誤，通過收集上述的複製相關資訊和錯誤相關資訊，分析這些資訊中與正常複製異常的地方，便可為排查複製錯誤提供更多的可以用來排除異常的資訊。

當然複製的錯誤是多種多樣的，並不是所有的錯誤都可以排查到具體的產生原因。很多複製錯誤是較難或者無法進行排查的，比如主庫或者從庫的binlog日誌檔案已經丟失、比如關閉binlog後執行某些操作導致複製不一致，再比如某些核心BUG導致MySQL的複製邏輯本身發生了異常等。

文章來自微信公眾號：DBAplus社群