記一次 MySQL 主從同步異常的排查記錄，百轉(zhuǎn)千回！

作者：悟空聊架構(gòu) 2023-04-13 12:00:00

relay log 損壞了，導(dǎo)致從庫(kù)的 SQL 線程解析 relay log 時(shí)出現(xiàn)異常。從庫(kù)恢復(fù)方式是通過(guò)手動(dòng)設(shè)置當(dāng)時(shí)出錯(cuò)的 GTID 的下一個(gè)值，讓從庫(kù)不從主庫(kù)同步這個(gè) GTID，最后從庫(kù)就能正常同步這個(gè) GTID 之后的 binlog 了，后續(xù) SQL 線程也能正常解析 relay log 了。

你好，我是悟空。

本文主要內(nèi)容如下：

一、現(xiàn)象

最近項(xiàng)目的測(cè)試環(huán)境遇到一個(gè)主備同步的問(wèn)題：

備庫(kù)的同步線程停止了，無(wú)法同步主庫(kù)的數(shù)據(jù)更改。

備庫(kù)報(bào)錯(cuò)如下：

從庫(kù)同步報(bào)錯(cuò)信息

完整的錯(cuò)誤信息：

Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave.

上面的報(bào)錯(cuò)信息是什么意思呢？

翻譯一下就是主庫(kù)的 binlog 或者從庫(kù)的 relay log 損壞了，造成這個(gè)問(wèn)題的原因：

可能是網(wǎng)絡(luò)問(wèn)題。
也可能是主庫(kù)或備庫(kù)的代碼 bug。

首先我們還是得復(fù)習(xí)下主從同步的原理才能更好地分析原因。

二、主從同步的原理

主從同步的原理

從庫(kù)會(huì)生成兩個(gè)線程，一個(gè) I/O 線程，名字叫做 Slave_IO_Running，另外一個(gè)是 SQL 線程，名字叫做 Slave_SQL_Running;
從庫(kù)的 I/O 線程會(huì)去請(qǐng)求主庫(kù)的 binlog 日志文件，并將得到的 binlog 日志文件寫(xiě)到本地的 relay log (中繼日志)文件中;
主庫(kù)會(huì)生成一個(gè) dump 線程，用來(lái)給從庫(kù) I/O 線程傳 binlog;
從庫(kù) SQL 線程，會(huì)讀取 relay log 文件中的日志，并解析成 SQL 語(yǔ)句逐一執(zhí)行。

三、排查思路

3.1 分析從庫(kù)的同步狀態(tài)

我們可以打印下從庫(kù)的同步狀態(tài)，看到如下幾個(gè)關(guān)鍵信息：

分析從庫(kù)的同步狀態(tài)

Master_Log_File: mysql-bin.000956，代表從庫(kù)讀到的主庫(kù)的 binlog file，

Read_Master_Log_Pos: 528071913，代表從庫(kù)讀到的主庫(kù)的 binlog file 的日志偏移量

Relay_Log_File: relay-bin.000094，代表從庫(kù)執(zhí)行到了哪一個(gè) relay log

Relay_Log_Pos: 123408769，代表從庫(kù)執(zhí)行的 relay log file 的日志偏移量

Relay_Master_Log_File: mysql-bin.000955，代表從庫(kù)已經(jīng)重放到了主庫(kù)的哪個(gè) binlog file。

Exec_Master_Log_Pos: 123408556，代表從庫(kù)已經(jīng)重放到了主庫(kù) binlog file 的偏移量。

Slave_IO_Running: Yes，說(shuō)明 I/O 線程正在運(yùn)行，可以正常獲取 binlog 并生成 relay log。

Slave_SQL_Running: No，說(shuō)明 SQL 線程已經(jīng)停止運(yùn)行，不能正常解析 relay log，也就不能執(zhí)行主庫(kù)上已經(jīng)執(zhí)行的命令。

Master_Log_File? 和 Read_Master_Log_Pos 這兩個(gè)參數(shù)合起來(lái)表示的是讀到的主庫(kù)的最新位點(diǎn)。

Relay_Master_Log_File? 和 Exec_Master_Log_Pos，這兩個(gè)參數(shù)合起來(lái)表示的是從庫(kù)執(zhí)行的最新位點(diǎn)。

如果紅色框起來(lái)的兩個(gè)參數(shù)：Master_Log_File? 和 Relay_Master_Log_File 相等，則說(shuō)明從庫(kù)讀到的最新文件和主庫(kù)上生成的文件相同，這里前者是 mysql-bin.000956，后者是 mysql-bin.000955，說(shuō)明兩者不相同，存在主從不同步。

如果藍(lán)色框起來(lái)的兩個(gè)參數(shù) Read_Master_Log_Pos? 和 Exec_Master_Log_Pos 相等，則說(shuō)明從庫(kù)讀到的日志文件的位置和從庫(kù)上執(zhí)行日志文件的位置相同，這里不相等，說(shuō)明主從不同步。

當(dāng)上面兩組參數(shù)都相等時(shí)，則說(shuō)明主從同步正常，且沒(méi)有延遲。只要有任意一組不相等，則說(shuō)明主從不同步，可能是從庫(kù)停止同步了，或者從庫(kù)存在同步延遲。由于上面的 SQL 線程已經(jīng)停止了，說(shuō)明是從庫(kù)同步出現(xiàn)問(wèn)題了。

從庫(kù)同步出現(xiàn)的問(wèn)題在最開(kāi)始的報(bào)錯(cuò)信息里面已經(jīng)提到了，可能是網(wǎng)絡(luò)問(wèn)題導(dǎo)致，還有可能是 binlog 或 relay log 損壞。

3.2 重啟萬(wàn)能大法

先通過(guò)重啟來(lái)恢復(fù)從庫(kù)的 SQL 線程試試看？重啟方式就是兩種：

方式一：從庫(kù)重新開(kāi)啟同步。就是執(zhí)行 stop slave; 和 start slave; 命令。
方式二：重啟從庫(kù)實(shí)例。就是重啟 mysql 實(shí)例或 mysql 容器。

這兩種方式試了后，都不能恢復(fù)從庫(kù)的 SQL 線程。

3.3 查看 binlog

再來(lái)看下 binlog 是否有損壞，在主庫(kù)上通過(guò)這個(gè)命令打開(kāi) mysql-bin.000955 文件。

mysqlbinlog /var/lib/mysql/log/mysql-bin.000955

沒(méi)有報(bào)錯(cuò)信息，如下圖所示：

binlog 日志

3.4 查看 relay log

看到從庫(kù)同步的 Relay_Log_File 到 relay-bin.00094 就停止同步了，如下圖所示，可能是這個(gè)文件損壞了。

relay log 日志

在從庫(kù)上通過(guò) mysqlbinlog 命令打開(kāi)這個(gè)文件

mysqlbinlog /var/lib/mysql/log/relay-bin.000094

可以看到有個(gè)報(bào)錯(cuò)信息：

ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 7644, event_type: 31
ERROR: Could not read entry at offset 243899899: Error in log format or read error.

這段文字翻譯過(guò)來(lái)就是讀取錯(cuò)誤，數(shù)據(jù)長(zhǎng)度 7644，在讀取偏移量為 243899899 的日志時(shí)發(fā)生了錯(cuò)誤，可能是日志文件格式錯(cuò)誤或是讀取文件錯(cuò)誤。

relay log 報(bào)錯(cuò)信息

3.5 找原因

3.5.1 猜測(cè)事務(wù)日志太大

根據(jù)這個(gè)報(bào)錯(cuò)信息可以知道這個(gè)事務(wù)日志數(shù)據(jù)太長(zhǎng)了，data_len: 7644，而導(dǎo)致讀取錯(cuò)誤。

而且上面還有很多 Update_rows 的操作。

猜測(cè)：會(huì)不會(huì)是主庫(kù)執(zhí)行了一個(gè)大事務(wù)，造成該事務(wù)生成的一條 binlog 日志太大了，從庫(kù)生成的對(duì)應(yīng)的一條 relay log 日志也很大， SQL 線程去解析這條 relay log 日志解析報(bào)錯(cuò)。

3.5.2 驗(yàn)證

到主庫(kù)上查看下 binlog 日志里面有沒(méi)有在那個(gè)時(shí)間點(diǎn)做特殊操作。

感覺(jué)快找到原因了。執(zhí)行以下命令來(lái)查看

mysqlbinlog File --stop-datetime=T --start-datetime=T

stop-datetime 指定為讀取 relay log 報(bào)錯(cuò)的時(shí)刻 2023-04-04 16:47:16，

start-datetime 指定為讀取 relay log 報(bào)錯(cuò)的時(shí)刻 2023-04-04 16:47:30。

發(fā)現(xiàn)并沒(méi)有找到 Update_rows 的操作。繼續(xù)把時(shí)間往后加一點(diǎn)，經(jīng)過(guò)多次嘗試，把時(shí)間鎖定在了 2023-04-04 17:00:30~17:00:31。這 1s 內(nèi)能找到 2023-04-04 16:47:16 的操作日志。

日志如下，這個(gè)命令會(huì)打印 N 多日志，直接把屏幕打滿了！！

難道真的 binlog 對(duì)應(yīng)的這條事務(wù)日志太大了嗎？？？

存疑： 2023-04-04 16:47:16 時(shí)刻對(duì)數(shù)據(jù)庫(kù)中的表做了某個(gè)大事務(wù)的操作，造成該事務(wù)對(duì)應(yīng)的這條 binlog 日志很大很大。生成的 relay log 也很大，SQL 線程解析 relay log 報(bào)錯(cuò)。

3.6 這是真相嗎？

問(wèn)了下熟悉這張表的同事，有沒(méi)有在這個(gè)時(shí)刻做什么大事務(wù)操作。

同事看了下代碼，發(fā)現(xiàn)有個(gè)批量插入的操作，一次執(zhí)行 400 條，難道是 400 條太多了？？？這不應(yīng)該是真正的原因，400 條也不多。

不經(jīng)意間問(wèn)了下這張表的數(shù)據(jù)量有多大，該同事在 4月4號(hào) 16:45:25 做了一個(gè)手動(dòng)備份 xx_dance 表的操作，這張表有 25 萬(wàn)條數(shù)據(jù)。

備份表 xx_dance_0404 的信息

這個(gè)備份操作是在一個(gè)事務(wù)里面執(zhí)行的，生成的一條 binlog 日志很大。

這里只是一個(gè)猜測(cè)，還未得到驗(yàn)證，文末會(huì)說(shuō)明真正的原因。

如果真的是這樣，那我可以先恢復(fù)從庫(kù)的同步，備份表的操作在從庫(kù)上其實(shí)不需要。

3.7 GTID

不知道細(xì)心的你是否有發(fā)現(xiàn)上面的 binlog 里面有一個(gè)GTID，

'c5d74746-d7ec-11ec-bf8f-0242ac110002:8634832

binlog 中 GTID

記住 GTID 中的數(shù)字 8634832，后面恢復(fù)從庫(kù)同步時(shí)要用到。

我們?cè)賮?lái)看下從庫(kù)的狀態(tài)，發(fā)現(xiàn)也有一個(gè) GTID，如下圖所示，值為 8634831，正好相差 1，感覺(jué)這兩個(gè) GTID 值之間有不可告人的秘密。

從庫(kù)的狀態(tài)，GTID 集合

那么從庫(kù) SQL 線程停止運(yùn)行的原因就是卡在 8634832 這里了，我們可否跳過(guò)這個(gè) GTID 呢？這里就需要了解 GTID 的原理了。

你可能對(duì) GTID 的原理很感興趣，可以查看之前悟空寫(xiě)的一篇文章：

MySQL 主從模式采用 GTID 的實(shí)踐

四、GTID 同步方式的原理

這里還是把主從同步采用 GTID 方式的流程拿出來(lái)看下，幫助大家快速回顧下，熟悉的同學(xué)可以跳過(guò)本節(jié)內(nèi)容。

GTID 方案：主庫(kù)計(jì)算主庫(kù) GTID 集合和從庫(kù) GTID 的集合的差集，然后主庫(kù)推送差集 binlog 給從庫(kù)。

當(dāng)從庫(kù)設(shè)置完同步參數(shù)后，假定主庫(kù) A 的GTID 集合記為集合 x，從庫(kù) B 的 GTID 集合記為 y。

從庫(kù)同步的邏輯如下：

GTID 同步方式的原理

從庫(kù) B 指定主庫(kù) A，基于主備協(xié)議簡(jiǎn)歷連接。
從庫(kù) B 把集合 y 發(fā)給主庫(kù) A。
主庫(kù) A 計(jì)算出集合 x 和集合 y 的差集，也就是集合 x 中存在，集合 y 中不存在的 GTID 集合。比如集合 x 是 1~100，集合 y 是 1~90，那么這個(gè)差集就是 91~100。這里會(huì)判斷集合 x 是不是包含有集合 y 的所有 GTID，如果不是則說(shuō)明主庫(kù) A 刪除了從庫(kù) B 需要的 binlog，主庫(kù) A 直接返回錯(cuò)誤。
主庫(kù) A 從自己的 binlog 文件里面，找到第一個(gè)不在集合 y 中的事務(wù) GTID，也就是找到了 91。
主庫(kù) A 從 GTID = 91 的事務(wù)開(kāi)始，往后讀 binlog 文件，按順序取 binlog，然后發(fā)給 B。
從庫(kù) B 的 I/O 線程讀取 binlog 文件生成 relay log，SQL 線程解析 relay log，然后執(zhí)行 SQL 語(yǔ)句。

GTID 同步方案和位點(diǎn)同步的方案區(qū)別是：

位點(diǎn)同步方案是通過(guò)人工在從庫(kù)上指定哪個(gè)位點(diǎn)，主庫(kù)就發(fā)哪個(gè)位點(diǎn)，不做日志的完整性判斷。
而 GTID 方案是通過(guò)主庫(kù)來(lái)自動(dòng)計(jì)算位點(diǎn)的，不需要人工去設(shè)置位點(diǎn)，對(duì)運(yùn)維人員友好。

五、恢復(fù)從庫(kù)的同步

5.1 查看從庫(kù)執(zhí)行 GTID 的進(jìn)度

在從庫(kù)上執(zhí)行 show slave status \G來(lái)查看 GTID 集合。

Retrieved_Gtid_Set 表示從庫(kù)收到的所有日志的 GTID 集合。

Executed_Gtid_Set 表示從庫(kù)已經(jīng)執(zhí)行完成的 GTID 集合。

如果 Executed_Gtid_Set 集合是包含 Retrieved_Gtid_Set，則表示從庫(kù)接收到的日志已經(jīng)同步完成。

這里 Executed_Gtid_Set 的集合為 1-8634831，而 Retrieved_Gtid_Set 為 1-9101426，說(shuō)明從庫(kù)有些 GTID 是沒(méi)有執(zhí)行的。從庫(kù)已經(jīng)執(zhí)行到了 8634831，下一個(gè)要執(zhí)行的 GTID 為 8634832。

因?yàn)槲覀儾捎玫耐椒绞绞?GTID 方式，所以只要讓從庫(kù)跳過(guò)這個(gè) GTID ，從下一個(gè) GTID 開(kāi)始同步就行。

帶來(lái)的問(wèn)題就是這個(gè) GTID 對(duì)應(yīng)的事務(wù)沒(méi)有執(zhí)行。因?yàn)閳?bào)錯(cuò)的操作是從庫(kù)備份一張大表，所以從庫(kù)跳過(guò)這個(gè)備份操作也是可以接受的。

5.2 手動(dòng)設(shè)置 GTID

來(lái)，手動(dòng)設(shè)置一把 GTID 試下。

5.2.1 重置從庫(kù)進(jìn)度

首先重置下從庫(kù)同步的進(jìn)度 reset slave，這條命令會(huì)把所有的 relog 給清理掉，重新啟用一個(gè)新的 relay log文件。

stop slave;
reset slave;

重新開(kāi)啟同步后，主庫(kù)會(huì)計(jì)算主庫(kù) GTID 集合和從庫(kù) GTID 的集合的差集，然后主庫(kù)推送差集 binlog 給從庫(kù)。

5.2.1 設(shè)置 GTID 為一個(gè)值

執(zhí)行以下命令設(shè)置 GTID 為下一個(gè)值。

set gtid_next='c5d74746-d7ec-11ec-bf8f-0242ac110002:8634832';
begin;
commit;
set gtid_next=automatic;
start slave;

gtid_next 表示設(shè)置下一個(gè) GTID = 8634832，這個(gè)值是在原來(lái)的 8634831 加 1。后面的 begin 和 commit 是提交了一個(gè)空事務(wù)，把這個(gè) GTID 加到從庫(kù)的 GTID 集合中。那么從庫(kù)的 GTID 集合就變成了

'c5d74746-d7ec-11ec-bf8f-0242ac110002:1-8634832';

5.2.2 查看當(dāng)前 GTID 集合

我們可以通過(guò) show master status\G 命令來(lái)查看從庫(kù)的 GTID 集合。下方截圖是執(zhí)行上述命令之前的。GTID集合為 1-8634831。另外 GTID 集合為 1 和 GTID 集合為 1-4 的可以忽略，因?yàn)樗鼈兦懊娴?Master_UUID 不是當(dāng)前主庫(kù)的 uuid。

show master status\G 的結(jié)果

也可以通過(guò) show slave status\G 命令來(lái)查看 GTID 集合，結(jié)果也是一樣的。

5.3 開(kāi)啟從庫(kù)同步

再次啟動(dòng)從庫(kù)的同步（start slave 命令)，I/O 線程和 SQL 線程的狀態(tài)都為 YES，說(shuō)明啟動(dòng)成功了。

而且查看從庫(kù)的同步狀態(tài)時(shí)，觀察到從庫(kù)的同步是存在延遲的。通過(guò)觀察這個(gè)字段 Seconds_Behind_Master 在不斷減小，說(shuō)明主從同步的延遲越來(lái)越小了。

兩個(gè)線程都是正常運(yùn)行，主從同步延遲越來(lái)越小

過(guò)一段時(shí)間后，執(zhí)行的 GTID 等于收到的 GTID 集合，Seconds_Behind_Master = 0，說(shuō)明主從完全同步了。

六、原因

上面的推測(cè)：備份大表造成 binlog 的一條日志太大，relay log 也跟著變大，SQL 線程無(wú)法正常解析。

但這是真相嗎？

雖然從庫(kù)重新開(kāi)啟了同步，且跳過(guò)了這條日志，但帶來(lái)的是從庫(kù)上就不會(huì)出現(xiàn)這個(gè)備用表 xx_dance_0404 。

但出現(xiàn)了兩個(gè)奇怪的問(wèn)題：

問(wèn)題 1：從庫(kù)開(kāi)啟同步后，居然出現(xiàn)了這個(gè)備份表 xx_dance_0404。不是跳過(guò)這個(gè)備份操作了嗎？目前沒(méi)想到原因。

問(wèn)題 2：為了重現(xiàn)這個(gè)問(wèn)題，我到主庫(kù)上做了一個(gè)備份表的操作，表名為 xx_dance_0412，從庫(kù)也同步了這個(gè)新的備份表 xx_dance_0412。而且 binlog 出現(xiàn)的日志現(xiàn)象也是一樣的，對(duì)應(yīng)的這條 binlog 日志也很大，但是從庫(kù)同步正常。我又備份了一張 300 萬(wàn)的大表，依然沒(méi)重現(xiàn)。

通過(guò)問(wèn)題 2 可以說(shuō)明上面的推測(cè)是錯(cuò)誤的，備份大表并不會(huì)影響主從同步。

那么 relay log 報(bào)錯(cuò)的原因是什么？

只有一個(gè)原因了，relay log 文件真的是損壞的，從庫(kù)的狀態(tài)上也說(shuō)明了原因，relay log is corrupted（損壞）。SQL 線程去解析 relay log 時(shí)報(bào)錯(cuò)了，導(dǎo)致 SQL 線程停止，從庫(kù)不能正常執(zhí)行同步。

小結(jié)：relay log 損壞了，導(dǎo)致從庫(kù)的 SQL 線程解析 relay log 時(shí)出現(xiàn)異常。從庫(kù)恢復(fù)方式是通過(guò)手動(dòng)設(shè)置當(dāng)時(shí)出錯(cuò)的 GTID 的下一個(gè)值，讓從庫(kù)不從主庫(kù)同步這個(gè) GTID，最后從庫(kù)就能正常同步這個(gè) GTID 之后的 binlog 了，后續(xù) SQL 線程也能正常解析 relay log 了。

關(guān)于我

InfoQ 簽約作者、藍(lán)橋簽約作者、阿里云專(zhuān)家博主、51CTO 紅人。

責(zé)任編輯：武曉燕來(lái)源：悟空聊架構(gòu)