《MySQL復制異常大掃盲：快速溯源與排查錯誤全解》要點：
本文介紹了MySQL復制異常大掃盲：快速溯源與排查錯誤全解，希望對您有用。如果有疑問，可以聯系我們。

作者介紹

王松磊,現任職于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不會因為復制而發生改變,即主庫的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社群

轉載請注明本頁網址：
http://www.fzlkiss.com/jiaocheng/2723.html