背景

在大型MySQL集群增加了新的庫，運行正常(沒有開啟GTID)。幾天后將新加入的庫開啟GTID。

MySQL版本：5.7.19

故障現象

變更后，當業務壓力開始上升，發現其中一個節點以大概半小時的頻率，業務會間斷性地發生阻塞。

分析過程

1.觀察故障現象

根據業務研發同事描述，大概每半小時發生一次故障。等到故障發生時，觀測到以下現象：

a.show processlist發現有4000左右正在執行的insert，執行時間在10～300s

b.?show global variables like 'thread_running'?無響應

c. top觀察CPU只使用到1個核，內存正常，iowait值3%左右

d.?iostat觀察到700M/s read，隨后使用iotop觀察有一個MySQL線程700M/s read

2.定位700M/s read線程

顯然700M/s的讀IO極不正常，問題突破點就在這里，接下來我們要找到數據庫在做什么導致了這么高的讀IO。

iotop可查找到問題線程TID，通過performance_schema.threads查找到對應的MySQL內部真實線程：

(以下截圖均為測試環境復現截圖，虛擬機IO差很多只有97M/s)

查得MySQL中線程正在做一個insert，且只插入一行數據。

第一反應是insert為什么會造成700M/s的讀IO，并且會持續3-5分鐘之久？分析insert語句，只插入1行數據，更加不可理解。幾次故障觀察到同一現象。

3.分析binlog

猜測：這是一個大事務，事務包含了大量insert語句。

解析binlog，使用insert語句中的唯一ID過濾binlog，發現：

a. 這個insert所在事務只有1條insert；

b. 這個insert所在事務位于binlog最末尾。

得到結論：insert語句正常，并非大事務。那是什么原因？“insert所在事務位于binlog最末尾”好像有點意思。

繼續解析binlog，發現幾次故障時的insert所在事務也是位于binlog最末尾。

這不是巧合，應該與binlog rotate有關！好像發現了什么！

4.確認故障與binlog rotate相關聯

前面提到每次故障發生，MySQL的thread_running會飆升至4000左右，并且無響應。

通過這個信息，我們打開監控圖表，對照binlog的刷新時間點，基本吻合。

到這里，我們基本可以認為故障與binlog rotate是相關聯的。接下來就是驗證了。

5.復現與驗證

情況緊急，接下來的操作需要在從庫(因為從庫也發生過故障導致了主從切換)驗證，從庫執行flush logs手工刷新binlog，并使用strace觀測MySQL到底做了什么導致了700M/s的讀IO。

a. 開啟strace，strace -o /tmp/strace_output.txt -T -tt -f -e trace=read,open -p 'mysql_pid'

b. 從庫flush logs；

c. iotop觀察到有一個700M/s讀的線程，問題復現！

d. 關閉strace

6.原因定位

(以下截圖均為測試環境復現截圖，虛擬機IO差很多只有97M/s)

上一步復現了故障，并且獲取strace信息，接下來進行分析：

看到strace信息中大量重復的文件句柄號：

統計strace信息中 文件句柄72 的總行數，占strace信息總行數的90%以上，由此可大致判斷：對文件句柄72存在大量讀操作：

查看MySQL進程下的文件句柄，發現 文件句柄72 對應文件為binlog：

再分析strace信息中open函數，發現open的文件都是binlog，且在按順序打開binlog文件！離真相越來越近了：)

這時我們腦海里會出現一個問題：為什么binlog刷新時會從頭至尾掃描binlog？

掃描腦子里的知識庫：binlog_gtid_simple_recovery

以下是MySQL官方手冊解釋：

結合源碼歸納后可以理解為：

當MySQL重啟，且當MySQL重啟，且binlog_gtid_simple_recovery=false：

更新gtid_executed，從最新的binlog開始掃描，直到找到第一個有Previous_gtids_log_event的binlog為止；

更新gtid_purged，從最舊的binlog開始掃描，直到找到第一個有Previous_gtids_log_event的binlog為止；

當MySQL重啟，且binlog_gtid_simple_recovery=true：

更新gtid_executed，只掃描最新的那個binlog，如果這個binlog不包含gtid，直接將GLOBAL.GTID_EXECUTED設置為空；

更新gtid_purged，只掃描最舊的那個binlog，如果這個binlog不包含gtid，直接將GLOBAL.GTID_PURGED設置為空；

當刪除binlog，且binlog_gtid_simple_recovery=false：

更新gtid_purged，從最舊的binlog開始掃描，直到找到第一個有Previous_gtids_log_event的binlog為止；

當刪除binlog，且binlog_gtid_simple_recovery=true：

更新gtid_purged，只掃描最舊的那個binlog，如果這個binlog不包含gtid，直接將GLOBAL.GTID_PURGED設置為空；

另外還有一種情況就是relay_log_recovery=0的情況，掃描relay_log以更新all_gtids?(Retrieved_Gtid_Set)

故障MySQL設置是

故障MySQL設置是binlog_gtid_simple_recovery=false，并且變更前是沒有開啟GTID的，意味著有一百多個binlog沒有記錄GTID，所以大量的讀IO發生在掃描這一百多個binlog，符合故障現象。

再等等，好像有什么不對？我們的故障現場是binlog rotate(包括手工flush logs)，和手冊上描述的“MySQL重啟”、“binlog被刪除”不是一回事啊！

排除法：故障時MySQL并沒有重啟，那就是“binlog被刪除”導致的了。

解到這里只剩最后一個問題了：binlog rotate(和手工flush logs)會導致binlog被刪除嗎？

答案是：expire_logs_days

再看下官方手冊：

翻譯一下就是：當開啟了expire_logs_days，MySQL會自動刪除binlog，觸發條件是“啟動”和“binlog的刷新”。

再次驗證，在數據庫中執行purge binary logs to 'mysql-bin.xxx'，觀察strace，iotop能夠穩定復現故障現象。

結論

MySQL由非GTID模式到開啟GTID，之前的binlog(一百多個)都沒有記錄GTID。

開啟GTID后，受參數expire_logs_days=5影響，每次binlog rotate時會觸發binlog的自動刪除，當binlog被刪除時：

由于參數binlog_gtid_simple_recovery=false，MySQL會從頭至尾掃描binlog直到找到第一個有Previous_gtids_log_event的binlog為止。最終造成了數據庫阻塞。

解決方案

刪除沒有記錄GTID的binlog，因為purge binary logs to 'xxx'命令會觸發binlog掃描，所以這里只能使用rm方式進行刪除，刪除后將mysql-bin.index文件中對應的行刪除，注意不留空行。

如何避免

最好是創建數據庫時直接啟用GTID，GTID的好處誰用誰知道；

當MySQL由非GTID模式升級為開啟GTID時：

1. 設置參數binlog_gtid_simple_recovery=true；

2. 重啟MySQL后，備份binlog，執行reset master；

3. 運行后不要切換GTID模式，以免造成GTID的紊亂。

創作挑戰賽新人創作獎勵來咯，堅持創作打卡瓜分現金大獎

總結

以上是生活随笔為你收集整理的mysql binlog rotate_binlog rotate引发的MySQL阻塞事件的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。