作者介紹

王竹峰， 去哪兒網(wǎng)數(shù)據(jù)庫總監(jiān)。擅長數(shù)據(jù)庫開發(fā)、數(shù)據(jù)庫管理及維護，一直致力于 MySQL 數(shù)據(jù)庫源碼的研究與探索，對數(shù)據(jù)庫原理及實現(xiàn)有深刻的理解。曾就職于達夢數(shù)據(jù)庫，從事多年數(shù)據(jù)庫內(nèi)核開發(fā)工作，是 Inception 開源項目及《MySQL運維內(nèi)參》的作者，MySQL 方向的Oracle ACE 。

一、背景

最近組內(nèi)同學遇到一個問題，說數(shù)據(jù)庫被業(yè)務打死了，無響應，只好用 kill -9 pid 殺掉，然后重啟，幸好此時的數(shù)據(jù)庫角色是從庫，影響不大。同學自述，在殺掉重啟的時候，心里默念，千萬別啟不來啊，這個庫的數(shù)據(jù)量有點大，快要達到 4T 了。做運維的人都知道，事情就不能念叨，一念叨，這事兒就準發(fā)生。這次也不例外，確實是出現(xiàn)了?，F(xiàn)象是長時間啟動不了，基本卡死狀態(tài)。error log 信息如下：

通過查看 Note 級別的啟動日志發(fā)現(xiàn)，在報了最后一條之后，就再也沒有新的日志出現(xiàn)了。很久也不會再動。

二、分析

1、TOP命令

首先通過 top 命令來確定一下當前實例是不是還在活動：

PID 為 84448 ，發(fā)現(xiàn) CPU 占用率是 0 ，說明當前實例已經(jīng)卡死了，沒有在跑了。當然也不是死循環(huán)（因為死循環(huán)的話，CPU肯定是打滿的）。

2、堆棧

接下來就要看堆棧了，這個在查問題的時候，是一個非常好的工具。堆棧結果如下：

從堆棧可以看出，IO 線程完全不工作，都處于 idle 狀態(tài)，啟動線程，即包括 mysqld_main 函數(shù)的堆棧，也處于 nanosleep 狀態(tài)，最主要的兩組線程，已經(jīng)說明了，當前實例啥也不做，完全是 idle 狀態(tài)，與我們在上面用 TOP 來判斷的結果是一樣的。

三、進一步分析

從上面的現(xiàn)象來判斷的話，很難找到具體原因，因為很難判斷當前線程為什么這么死等，當然，從啟動線程基本可以確定的是，是啟動時想做一次檢查點，但在刷盤的時候一直等不到刷完，基本只能是這樣。那我們可以試想一下，等待刷盤，一直等不到，那刷盤線程在做什么呢？這個也很好確定，知道源碼的同學，應該了解，刷盤線程是buf_flush_page_cleaner_coordinator，在上面堆棧截圖中有，我們再來看一次。

很明顯，這個線程也處于等待狀態(tài)，那這樣就可以大概推斷，應該是 innodb 內(nèi)部出現(xiàn)了亂子，刷盤線程認為沒有東西可以刷，所以處于 idle 狀態(tài)，而啟動線程認為有東西需要刷的，所以一直在等，信息沒有對齊，所以死等了。

那單純從上面的這些信息，還能繼續(xù)往下分析嗎？也許可以再進步一點點。我們發(fā)現(xiàn)，上面的錯誤日志中，有一行這樣的信息：

2021-08-27T16:50:24.433063+08:00 0 [Note] InnoDB: Completing truncate for table with id (93752) residing in file-per-table tablespace with id (12742)

這個信息比較少出現(xiàn)的，大概是表示某一個表在重啟之前做過 truncate，而在重啟的時候，需要把這個表redo一次 truncate 。而我們再反過來看啟動的堆棧，發(fā)現(xiàn)調(diào)用buf_flush_wait_flushed的，正是truncate_t::fixup_tables_in_non_system_tablespace ，發(fā)現(xiàn)這也是 truncate ，好像能對得上，所以此時可以猜測，是不是與 truncate 有關系。

在咨詢業(yè)務之后，發(fā)現(xiàn)在這個實例的生前，確實多次做過數(shù)據(jù)的 load 與 truncate ，然后知道這個業(yè)務的行為，有幫助么？試想從上面的現(xiàn)象，我們還能再往下分析嗎？此時我認為不可以了。

那怎么辦？我認為只能上源碼了。

四、源碼分析

我們用源碼分析，首先需要解開的是，為什么信息不對稱，即刷盤線程認為沒有頁面需要刷了，而啟動線程認為需要刷盤呢？用源碼分析，一個很重要的入手點，就是先編譯一個相同版本的 Debug mysqld ，然后啟動復現(xiàn)這個問題，因為這個問題是必現(xiàn)的，所以查找起來容易很多。

等到復現(xiàn)之后，我們把上面的堆棧再看一次：

有沒有發(fā)現(xiàn)有很大的不同，信息多了很多，可以具體地看到每一個函數(shù)對應的文件，行數(shù)等等，上面展示的是刷盤線程buf_flush_page_cleaner_coordinator的狀態(tài)，代碼版本是Percona 5.7.26，可以看出 os_event 的等待位置是在 buf0flu.cc 的 3212 這行，我們拿到對應的代碼，看看這行是在做什么。

可以看到，3212 行的代碼是 os_event_wait(buf_flush_event)。這行之上，是刷盤線程的開始位置，熟悉代碼的同學都知道，這個位置是用來把innodb恢復過程中，REDO重放產(chǎn)生的臟頁刷到文件中去的，而在這行之后，即從下面我們所看到的一行代碼 while  (srv_shutdown_state == SRV_SHUTDOWN_NONE){開始，才是真正地刷掉我們數(shù)據(jù)庫正常運行過程中產(chǎn)生的所有臟頁的，innodb 是把啟動過程中和啟動之后正常運行所產(chǎn)生的臟頁分階段刷掉的。

知道這個之后，我們就可以知道，3212 這行，是兩個階段的分界線，也就是說，刷盤線程認為數(shù)據(jù)庫的 REDO 已經(jīng)做完了，而還沒有啟動完成，所以正常的刷盤還不能開始做，所以就靜靜地等待在這里。

我們此時再回過頭來看啟動線程所處的位置，堆棧如下：

熟悉代碼的同學知道，innobase_start_or_create_for_mysql是innodb啟動的關鍵函數(shù)，在這里調(diào)用了truncate_t::fixup_tables_in_non_system_tablespace，這個函數(shù)從名字上就能推斷出來是干什么的，與日志中最后一行非常相關，我們可以順便看看日志在哪里打印出來的，代碼如下：

一目了然，即自從日志文件打印這行之后，這個啟動就卡死在這里了。非常明確，通過代碼驗證了我們的推測。

那我們現(xiàn)在需要考慮的問題是，為什么在這個位置，innodb認為是需要刷盤的呢？我們再看代碼：

這里是函數(shù) truncate_t::fixup_tables_in_non_system_tablespace 最后的位置，在這里我們能看到對函數(shù) log_make_checkpoint_at 的調(diào)用，這個我們能在堆棧中看到，其實他就是卡在了里面。這里還是那個問題，為什么需要刷盤？因為在這個 fixup 過程中，做了很多修改操作，修改的內(nèi)容可以參考函數(shù) row_truncate_update_sys_tables_during_fix_up 的實現(xiàn)，在上圖中有，里面做了大量的修改，以及 SQL 語句的執(zhí)行，肯定會產(chǎn)生很多臟頁。所以 innodb 需要將其刷盤。

但為什么刷盤線程不刷了呢？很明顯，上面已經(jīng)解釋過了，他已經(jīng)執(zhí)行完了 redo 重放產(chǎn)生的臟頁，所以已經(jīng)處于 idle 狀態(tài)了，他認為在數(shù)據(jù)庫啟動之前，他不會再刷盤了，除非 buf_flush_event 事件被 set 一次。那我們的好奇來了， buf_flush_event 正常情況下，是什么時候被 set 的呢？再看代碼，總共有兩個地方，先看第一個：

從上圖可以看到，他是在 srv0start.cc 的 2892 行被 set 的，如果執(zhí)行了這行，那刷盤線程就會繼續(xù)向下執(zhí)行了，就說明 innodb 啟動完成可以正常工作了，而我們現(xiàn)在再看truncate_t::fixup_tables_in_non_system_tablespace()是什么時候調(diào)用的呢？從堆?？梢钥闯鰜?，就是 srv0start.cc:2644 行位置，即是在 buf_flush_event 被 Set 之前的位置，也就是說，innodb 認為 fixup 執(zhí)行所產(chǎn)生的臟頁，還算做是 REDO 重放所產(chǎn)生的（姑且這么認為），那疑問來了，既然這樣，刷盤線程怎么就提前退出了呢？我們再通過代碼來看，刷盤線程針對 REDO 重放所產(chǎn)生的臟頁刷盤工作，在什么情況下會退出：

可以看到，這個循環(huán)退出條件之一，就是recv_sys->heap == NULL，也就是說，只要recv_sys->heap == NULL了，刷盤操作就退出了，我們再看recv_sys→heap是什么時候被設置為NULL的：

不難發(fā)現(xiàn)，recv_sys→heap是在recv_sys_debug_free 中設置為NULL的，那現(xiàn)在問題就變?yōu)?recv_recovery_from_checkpoint_finish 是在什么時候調(diào)用的了，熟悉代碼的同學應該對這個很清楚，這正是完成 REDO 重放的一個重要函數(shù)，我們搜索發(fā)現(xiàn)：

可以看到，recv_recovery_from_checkpoint_finish 的調(diào)用位置，在 2618 行，是在 fixup_tables_in_non_system_tablespace 被調(diào)用之前，細心的同學可能也會從上圖中發(fā)現(xiàn)，還有一個相似的函數(shù)truncate_t::fixup_tables_in_system_tablespace()，從名字可以看到，這是針對系統(tǒng)表的?？傊还芟到y(tǒng)表，還是 NON 系統(tǒng)表，都是在 recv_recovery_from_checkpoint_finish 后面被調(diào)用，因為之前分析了，只要 recv_recovery_from_checkpoint_finish 調(diào)用了，刷盤線程就認為 innodb 再產(chǎn)生的臟頁就是正常運行的臟頁了，就不負責刷盤了，就會走到等待 buf_flush_event 的位置，而啟動線程不這么認為，在重放完成之后，又產(chǎn)生了新的臟頁，同時他認為，這里所產(chǎn)生的臟頁必須要刷完，此時 buf_flush_event 又沒有被 Set ，所以啟動線程只能死等了。是的，會一直等下去。

我們現(xiàn)在再看 buf_flush_event 被 Set 的第二個位置，即是 buf_flush_request_force ，而這個函數(shù)被調(diào)用的位置，我們就比較熟悉了，請看：

同時發(fā)現(xiàn)，在 buf_flush_request_force 下面，就是我們當前陷入死循環(huán)的函數(shù)，也就是說， InnoDB 也認為 fixup 產(chǎn)生的臟頁應該由啟動之后的刷盤線程來刷掉，即只有等待到事件 buf_flush_event 之后才去做刷盤。所以上面在進入等待狀態(tài) buf_flush_wait_flushed 之前，先做一次 buf_flush_event 的 Set 操作，讓刷盤線程繼續(xù)向下執(zhí)行，進入到正常刷盤狀態(tài)。

然而，當前啟動線程，已經(jīng)處于等待狀態(tài)了，為什么刷盤線程還處于等待事件 buf_flush_event 的狀態(tài)呢？細心的同學應該已經(jīng)注意到了，在上圖中，buf_flush_request_force 的調(diào)用是有條件的，有一個參數(shù) srv_flush_sync ，此時我看了一下當前參數(shù)的值，他是 0 ，這樣就可以解釋了，正是因為這個參數(shù)，導致這個機制失效了，這里的 buf_flush_event 的 Set 失效了，就需要依靠上面第一種情況所說的 Set 了，而此時已經(jīng)明白，永遠不會執(zhí)行到那里去了，會一直等下去。

那現(xiàn)在應該清楚了，本身針對這個問題，流程整體上是沒有問題的，只不過有參數(shù) srv_flush_sync ，導致邏輯上面存在了漏洞，那我們?nèi)绾伪苊膺@樣的問題，很顯然，能用參數(shù)控制的辦法避免問題，是最友好不過的了，我們只需要把參數(shù) srv_flush_sync （其實就是 InnoDB 參數(shù)  innodb_flush_sync）設置為 ON 即可。

buf_flush_wait_flushed函數(shù)狀態(tài)

問題清楚之后，我們再回過頭來，看看在buf_flush_wait_flushed函數(shù)死等的位置，狀態(tài)是什么樣子的，如下圖所示：

從圖中可以看到有很多臟頁，并且 oldest 都是小于任何一個 buffer instance 里面的 newest lsn 的，感興趣的同學可以對照源代碼看看，循環(huán)退出的條件是 oldest 要大于每一個 instance_newest ，而oldset是一直不變的，一直是 103036344355008，比每一個都小，那為什么一直等不到 oldest 的變大呢？就是因為 buf_flush_page_cleaner_coordinator 線程沒有正常工作。

而這里也需要糾正在上面我的一個判斷，即在 TOP 中看到 CPU 很閑，占用率是 0，所以認為不是死循環(huán)，這里是不準確的，因為我們看代碼會發(fā)現(xiàn)，在 buf_flush_wait_flushed 函數(shù)中的等待，也是死循環(huán)，只不過有一行代碼為：

注釋都說了， sleep 然后 retry ，而 buf_flush_wait_flushed_sleep_time 是多少呢？從代碼中看到，是硬編碼寫死的，為 10000 microseconds ，那很明顯，以這樣的頻率做死循環(huán)，確實不至于讓 CPU 忙起來。

五、解決方法

問題現(xiàn)在已經(jīng)清楚了，那如何解決呢？數(shù)據(jù)不會變，在實例生前做了 truncate ，這個改不了，一種最簡單的辦法就是，我們把數(shù)據(jù)重做了就好了，這確實是的，很簡單，但想想，4T 的數(shù)據(jù)，這個時間成本太高了，DBA 已經(jīng)很煩做這樣的事情了。

1、解決方法一

那有沒有更簡單，快捷的辦法呢？這是有的，既然我們已經(jīng)編譯好了一個debug版本，并且上面也看到了， buf_flush_wait_flushed 函數(shù)已經(jīng)是死循環(huán)了，也知道是因為 new_oldest 參數(shù)傳入的 LSN_MAX 值導致循環(huán)結束的條件不能滿足，所以死循環(huán)，那我們?nèi)绻梢宰屵@個循環(huán)提前結束，條件滿足了，不就可以了嗎？

用 GDB 可以實現(xiàn)這樣的功能，直接實戰(zhàn)圖：

看到這里，感覺就像是駕駛特斯拉，一踩“油門”，deng 一下就被彈出去一樣，數(shù)據(jù)庫瞬間快速正常運轉(zhuǎn)起來，死循環(huán)一下子就破了，馬上啟動完成。

2、解決方法二

還有一種解決辦法，就是不依賴當前這次啟動過程，而是直接重啟一次，重啟之前將參數(shù) innodb_flush_sync 修改為 ON ，這樣啟動就沒有任何問題了，成功地避免了這樣的問題。

3、解決方法三

具體到這個問題，如果能確定是 truncate 本身操作，而不是其它內(nèi)部原因，可以將 data 目錄下面，對應的 *_trunc.log 文件都刪掉，這樣數(shù)據(jù)庫啟動的時候就不會加載相關信息了，也就不會有問題了，當然，這種辦法要謹慎使用，因為畢竟是在做物理上面的數(shù)據(jù)破壞的，并且有了上面能用參數(shù)控制來避免問題的辦法，其它解決問題的辦法就可以不屑一顧了。

本人因為選擇了 gdb 的辦法來解決此問題，所以其它兩種辦法都沒有機會實踐了，嘆嘆嘆?。?！

六、進一步疑問

按照上面的啟動方法，數(shù)據(jù)庫是可以正常啟動了，但如果下次再 shutdown ，再啟動，是不是問題還會出現(xiàn)。答案是否定的，因為正常啟動之后，truncate 相關的 log 已經(jīng)被清掉了，所以再啟動的時候，就不會再調(diào)用 truncate_t::fixup_tables_in_non_system_tablespace 函數(shù)了，所以也就不會有問題了。

七、問題澄清

本來準備給 bugs.mysql.com 報個 bug 的，為了更準確地表明問題，找到了 MySQL 官方的代碼版本，找到了函數(shù) log_preflush_pool_modified_pages ，發(fā)現(xiàn)與我們上面分析的代碼不太一樣，如下圖所示：

可以看出，官方版本代碼是沒有這個問題的，因為出問題的時候， new_oldest 是 LSN_MAX  ，這種情況下會進入圖中有橫線的那個分支中去，這里不存在死等的問題，而只有指定刷盤到某一個具體的 LSN 值的時候，才會走到下面的分支。

可以大膽猜測一下，這個問題應該是 Percona 改出來的新的問題，并且至今沒有被發(fā)現(xiàn)。

八、總 結

問題我們現(xiàn)在清楚了，很明顯這個是一個 bug ，通過我們的分析，改 bug 的方式，可以把 fixup 放到 buf_flush_event 后面去做，應該就沒有這個問題了，但這個還需要推動官方去修改，我們做為運維人員，只需要學會遇到問題如何去避免，就夠了（當然應該去報一個 bug ），當然如果想去嘗試改掉這個問題，也是可以的，只不過要維護起來，就很不簡單了，如果沒有相應的人力，團隊，最好不要走這條路。萬一改出來問題呢？這個損失可能更大了。

這個問題，遇到的人也可能比較少，所以在看了 Percona 5.7.33 最新版本，看著代碼也沒什么變化，說明至今沒有被修改好，同時也說明，針對 truncate 這個問題，官方也沒有測試充分。

另外，還需要去思考一個問題，對于這個 bug ，如果我們對源碼不太了解，這個問題還能解決掉嗎？能知道什么原因嗎？我想可能做不到，應該是做不到的，這也從側面說明，DBA 掌握點源碼是多么的重要，這是活生生地用源碼解決問題的案例啊，或者反過來講，如果不知道源碼，如何能把這個問題，與參數(shù) innodb_flush_sync 能聯(lián)系起來？MySQL 手冊可不會告訴你這些。

DBA 這個職業(yè)，一直被業(yè)界很多人認為即將要被機器替代了，的確，因為云時代的出現(xiàn)，自動化平臺的出現(xiàn)，很多操作，都被機器替代了，所以得出的結論是，DBA 不重要了，即將會被淘汰。我認為，這個結論很明顯是錯誤的，云時代以及自動化平臺的出現(xiàn)，只能是讓 DBA 的入門門檻變得更高，讓 DBA 的工作效率更高，讓 DBA 承擔起更重要的工作，有時間解決更復雜的問題，有精力構建更好的平臺、架構，做更多的有價值的輸出。而學習源碼，就是做一個不會被淘汰的 DBA 的最好的捷徑。

而更重要的是，你的職業(yè)是一個 MySQL DBA，MySQL 給了你一個學習源碼的機會，讓你有源碼可學，這是其它數(shù)據(jù)庫所不能替代的。