問(wèn)題背景

周一上班，首先向同事了解了一下上周的測(cè)試情況，被告知在多實(shí)例場(chǎng)景下 MySQL Server hang 住，無(wú)法測(cè)試下去，原生版本不存在這個(gè)問(wèn)題，而新版本上出現(xiàn)了這個(gè)問(wèn)題，不禁心頭一顫，心中不禁感到奇怪，還好現(xiàn)場(chǎng)環(huán)境還在，為排查問(wèn)題提供了一個(gè)好的環(huán)境，隨即便投入到緊張的問(wèn)題排查過(guò)程當(dāng)中。問(wèn)題實(shí)例表現(xiàn)如下：

首先，通過(guò) pstack 工具獲取當(dāng)前問(wèn)題實(shí)例的堆棧信息以便后面具體線程的查找 & 問(wèn)題線程的定位：

使用 pt-pmp 工具統(tǒng)計(jì) hang.info 中的進(jìn)程信息，如下：

問(wèn)題分析

從堆棧上可以看出，有這樣幾類(lèi)線程：

等待進(jìn)入 INNODB engine 層的用戶線程，測(cè)試環(huán)境中 innodb_thread_concurrency=16， 當(dāng) INNODB 層中的活躍線程數(shù)目大于此值時(shí)則需要排隊(duì)，所以會(huì)有大量的排隊(duì)線程，這個(gè)參數(shù)的影響&作用本身就是一篇很不錯(cuò)的文章，由于篇幅有限，在此不做擴(kuò)展，感興趣者可以參考官方文檔：14.14 InnoDB Startup Options and System Variables；
操作過(guò)程中需要寫(xiě) redo log 的后臺(tái)線程，主要包括 page cleaner 線程、異步 io threads等；
正在讀取Page頁(yè)面的 purge 線程 & 操作 change buffer 的 master thread；
大量的需要寫(xiě) redo log 的用戶線程。
從以上的分類(lèi)不難看出，所有需要寫(xiě) redo log 的線程都在等待 log_sys->mutex，那么這個(gè)保護(hù) redo log buffer 的 mutex 被究竟被哪個(gè)線程獲取了呢，因此，我們可以順著這個(gè)線索進(jìn)行問(wèn)題排查，需要解決以下問(wèn)題：

問(wèn)題一：哪個(gè)線程獲取了 log_sys->mutex ？
問(wèn)題二：獲取 log_sys->mutex 的線程為什么沒(méi)有繼續(xù)執(zhí)行下去，是在等其它鎖還是其它原因？
問(wèn)題三：如果不是硬件問(wèn)題，整個(gè)資源竟?fàn)幍倪^(guò)程是如何的？

1.問(wèn)題一：由表及里

在查找 log_sys->mutex 所屬線程情況時(shí)，有兩點(diǎn)可以幫助我們快速的定位到這個(gè)線程：

由于 log_sys->mutex 同時(shí)只能被同一個(gè)線程獲得，所以在 pt-pmp 的信息輸出中就可以排除線程數(shù)目大于1的線程；
此線程既然已經(jīng)獲取了 log_sys->mutex, 那就應(yīng)該還是在寫(xiě)日志的過(guò)程中，因此重點(diǎn)可以查看寫(xiě)日志的邏輯，即包括：mtr_log_reserve_and_write 或 log_write_up_to 的堆棧。
順著上面的思路很快的從 pstack 中找到了以下線程：

這里我們簡(jiǎn)單介紹一下MySQL寫(xiě) redo log 的過(guò)程（省略u(píng)ndo & buffer pool 部分），當(dāng)對(duì)數(shù)據(jù)進(jìn)行修改時(shí)，MySQL 會(huì)首先對(duì)針對(duì)操作類(lèi)型記錄不同的 redo 日志，主要過(guò)程是：

記錄操作前的數(shù)據(jù)，根據(jù)不同的類(lèi)型生成不同的 redo 日志，redo 的類(lèi)型可以參考文件：src/storage/innobase/include/mtr0mtr.h 記錄操作之后的數(shù)據(jù)，對(duì)于不同的類(lèi)型會(huì)包含不同的內(nèi)容，具體可以參考函數(shù)：recv_parse_or_apply_log_rec_body()； 寫(xiě)日志到 redo buffer，并將此次涉及到臟頁(yè)的數(shù)據(jù)加入到 buffer_pool 的 flush list 鏈表中； 根據(jù) innodb_flush_log_at_trx_commit 的值來(lái)判斷在commit 的時(shí)候是否進(jìn)行 sync 操作。

上面的堆棧則是寫(xiě)Redo后將臟頁(yè)加到 flush list 過(guò)程中時(shí) hang 住了，即此線程在獲取了 log_sys->mutex 后，在獲取 log_sys->log_flush_order_mutex 的過(guò)程中 hang 住了，而此時(shí)有大量的線程在等待該線程釋放log_sys->mutex鎖，問(wèn)題一 已經(jīng)有了答案，那么log_sys->log_flush_order_mutex 是個(gè)什么東東，它又被哪個(gè)占用了呢？

說(shuō)明：

1、MySQL 的 buffer pool 維護(hù)了一個(gè)有序的臟頁(yè)鏈表 (flush list according LSN order)，這樣在做 checkpoint & log_free_check 的過(guò)程中可以很快的定位到 redo log 需要推進(jìn)的位置，在將臟頁(yè)加入；
2、flush list 過(guò)程中需要對(duì)其上鎖以保證 flush list 中 LSN 的有序性， 但是如果使用 log_sys->mutex，在并發(fā)量大的時(shí)候則會(huì)造成 log_sys->mutex 的 contention，進(jìn)而引起性能問(wèn)題，因此添加了另外一個(gè) mutex 來(lái)保護(hù)臟頁(yè)按 LSN 的有序性，代碼說(shuō)明如下：

2.問(wèn)題二：彈盡糧絕

在問(wèn)題一的排查過(guò)程中我們確定了 log_sys->mutex 的所屬線程， 這個(gè)線程在獲得 log_sys->log_flush_order_mutex 的過(guò)程中 hang 住了，因此線程堆?？梢苑忠詾橄聨最?lèi)：

Thread 446， 獲得 log_sys->mutex, 等待獲取 log_sys->log_flush_order_mutex 以把臟頁(yè)加入到 buffer_pool 的 flush list中； 需要獲得 log_sys->mutex 以寫(xiě)日志或者讀取日志信息的線程； 未知線程獲得 log_sys->log_flush_order_mutex，在做其它事情的時(shí)候被 hang 住。

因此，問(wèn)題的關(guān)鍵是找到哪個(gè)線程獲取了 log_sys->log_flush_order_mutex。

為了找到相關(guān)的線程做了以下操作：

查找獲取 log_sys->log_flush_order_mutex 的地方；

結(jié)合現(xiàn)有 pstack 中的線程信息，仔細(xì)查看上述查找結(jié)果中的相關(guān)代碼，發(fā)現(xiàn)基本沒(méi)有線程獲得 log_sys->log_flush_order_mutex； gdb 進(jìn)入 MySQL Server, 將 log_sys->log_flush_order_mutex 打印出來(lái)，發(fā)現(xiàn) {waiters=1; lock_word= 0}!!!，即 Thread 446 在等待一個(gè)空閑的 mutex，而這個(gè)Mutex也確實(shí)被等待，由于我們的版本為 Release 版本，所以很多有用的信息沒(méi)有辦法得到，而若用 debug 版本跑則很難重現(xiàn)問(wèn)題，log_flush_order_mutex 的定義如下：

由以上的分析可以得出 問(wèn)題二 的答案：

只有兩個(gè)線程和log_sys->log_flush_order_mutex有關(guān)，其中一個(gè)是 Thread 446 線程， 另外一個(gè)則是最近一次調(diào)用 log_flush_order_mutex_exit() 的線程； 現(xiàn)有線程中某個(gè)線程在釋放log_sys->log_flush_order_mutex的過(guò)程中沒(méi)有喚醒 Thread 446，導(dǎo)致Thread 446 hang 并造成其它線程不能獲得 log_sys->mutex，進(jìn)而造成實(shí)例不可用； log_sys->log_flush_order_mutex 沒(méi)有被任何線程獲得。 3.問(wèn)題三：絕處逢生

由問(wèn)題二的分析過(guò)程可知 log_sys->log_flush_order_mutex 沒(méi)有被任何線程獲得，可是為什么 Thread 446 沒(méi)有被喚醒呢，信號(hào)丟失還是程序問(wèn)題？如果是信號(hào)丟失，為什么可以穩(wěn)定復(fù)現(xiàn)？官方的bug list 列表中是沒(méi)有類(lèi)似的 Bug的，搜了一下社區(qū)，發(fā)現(xiàn)可用信息很少，這個(gè)時(shí)候分析好像陷入了死胡同，心里壓力開(kāi)始無(wú)形中變大……好像沒(méi)有辦法，但是任何問(wèn)題都是有原因的，找到了原因，也就是有解的了……再一次將注意力移到了 Thread 446 的堆棧中，然后查看了函數(shù)：

由問(wèn)題二的分析過(guò)程可以得出某線程在 log_flush_order_mutex_exit 的退出過(guò)程沒(méi)有將 Thread 446 喚醒，那么就順著這個(gè)函數(shù)找，看它如何喚醒其它本程的，在沒(méi)有辦法的時(shí)候也只有這樣一步一步的分析代碼，希望有些收獲，隨著函數(shù)調(diào)用的不斷深入，將目光定在了 mutex_exit_func 上, 函數(shù)中的注釋引起了我的注意：

從上面的注釋中可以得到兩點(diǎn)信息：

由于 memory barrier 的存在，mutex_get_waiters & mutex_reset_lock_word 的調(diào)用順序可能與執(zhí)行順序相反，這種情況下會(huì)引起 hang 問(wèn)題； 專門(mén)寫(xiě)了一個(gè)函數(shù) sync_arr_wake_threads_if_sema_free() 來(lái)解決上述問(wèn)題。

由上面的注釋可以看到，并不是信號(hào)丟失，而是多線程 memory barrier 的存在可能會(huì)造成指令執(zhí)行的順序的異常，這種問(wèn)題確定存在，但既然有sync_arr_wake_threads_if_sema_free() 規(guī)避這個(gè)問(wèn)題，為什么還會(huì)存在 hang 呢？有了這個(gè)線索，瞬間感覺(jué)有了些盼頭……經(jīng)過(guò)查找 sync_arr_wake_threads_if_sema_free 只在 srv_error_monitor_thread 有調(diào)用，這個(gè)線程是專門(mén)對(duì) MySQL 內(nèi)部異常情況進(jìn)行監(jiān)控并打印出 error 信息的線程，臭名昭著的 600S 自殺案也是它的杰作， 那么問(wèn)題來(lái)了：

機(jī)器周末都在 hang 著，為什么沒(méi)有檢測(cè)到異常并 abort 呢？ 既然 sync_arr_wake_threads_if_sema_free 可以喚醒，為什么沒(méi)有喚醒呢？

順著這個(gè)思路，查看了pstack 中 srv_error_monitor_thread 的堆棧，可以發(fā)現(xiàn)此線程在獲取 log_sys->mutex 的時(shí)候hang 住了，因此無(wú)法執(zhí)行sync_arr_wake_threads_if_sema_free() & 常歸的異常檢查，正好回答了上面的問(wèn)題，詳細(xì)堆棧如下：

經(jīng)過(guò)上面的分析問(wèn)題越來(lái)越明朗了，過(guò)程可以簡(jiǎn)單的歸結(jié)為：

Thread 446 獲得 log_sys->mutex, 但是在等待 log_sys->log_flush_order_mutex 的過(guò)程中沒(méi)有被喚醒； Thread XXX 在釋放 log_sys->log_flush_order_mutex 的過(guò)程中出現(xiàn)了 memory barrier 問(wèn)題，沒(méi)有喚醒 Thread 446； Thread 470 獲得 log_sys->mutex 時(shí)被 hang 住，導(dǎo)致無(wú)法執(zhí)行 sync_arr_wake_threads_if_sema_free(), 導(dǎo)致了整個(gè)實(shí)例的 hang ?。?Thread 470 需要獲得 Thread 446 的 log_sys->mutex， 而 Thread 446 需要被 Thread 470 喚醒才會(huì)釋放 log_sys->mutex;

結(jié)合 log_sys->log_flush_order_mutex 的狀態(tài)信息，實(shí)例 hang 住的整個(gè)過(guò)程如下：

關(guān)于 Memory barrier 的介紹可以參考 ：

Memory barrierhttp://name5566.com/4535.html

問(wèn)題解決

既然知道了問(wèn)題產(chǎn)生的原因，那么問(wèn)題也就可以順利解決了，有兩種方法：

直接移除 log_get_lsn 在此處的判斷，本身就是開(kāi)發(fā)人員加的一些判斷信息，為了定位 LSN 的異常而寫(xiě)的，用到的時(shí)候也Crash了，用處不大； 保留判斷，將 log_get_lsn 修改為 log_peek_lsn, 后者會(huì)首先進(jìn)行 try_lock，當(dāng)發(fā)現(xiàn)上鎖失敗的時(shí)候會(huì)直接返回，而不進(jìn)行判斷，這種方法較優(yōu)雅些； 經(jīng)過(guò)修改之后的版本在測(cè)試過(guò)程中沒(méi)有沒(méi)有再?gòu)?fù)現(xiàn)此問(wèn)題。

問(wèn)題擴(kuò)展

雖然問(wèn)題解決了，但官方版本中肯定存在著這個(gè)問(wèn)題，為什么 buglist 沒(méi)有找到相關(guān)信息呢，于是在查看了最新代碼，發(fā)現(xiàn)這個(gè)問(wèn)題已經(jīng)修復(fù)，修復(fù)方法為上面列的第二種方法，詳細(xì)的 commit message 信息如下：

bug影響范圍：MySQL 5.6.28 及之前的版本都有此問(wèn)題。