《一個(gè)罕見的MySQL redo死鎖問題排查及解決過程》要點(diǎn)：
本文介紹了一個(gè)罕見的MySQL redo死鎖問題排查及解決過程，希望對您有用。如果有疑問，可以聯(lián)系我們。

作者：張青林,騰訊云布道師、MySQL架構(gòu)師,隸屬騰訊TEG-基礎(chǔ)架構(gòu)部-CDB內(nèi)核開發(fā)團(tuán)隊(duì),專注于MySQL內(nèi)核研發(fā)&相關(guān)架構(gòu)工作,有著服務(wù)多個(gè)10W級QPS客戶的數(shù)據(jù)庫優(yōu)化及穩(wěn)定性維護(hù)經(jīng)驗(yàn).騰訊云數(shù)據(jù)庫團(tuán)隊(duì)：繼承騰訊數(shù)據(jù)庫團(tuán)隊(duì)十多年海量存儲的內(nèi)部數(shù)據(jù)庫運(yùn)營和運(yùn)維經(jīng)驗(yàn),推出一系列高性能關(guān)系型、分布式、文檔型和緩存類數(shù)據(jù)庫產(chǎn)品,并提供高可用性、自動(dòng)化運(yùn)維和易維護(hù)的云數(shù)據(jù)庫綜合解決方案.

問題背景

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

• 并發(fā)量為 384 的時(shí)候出現(xiàn)的問題；
• MySQL 服務(wù)器無法執(zhí)行事務(wù)相關(guān)的語句,即使簡單的 select 語句也無法執(zhí)行；
• 所有線程處于等待狀態(tài),無法 KILL.

現(xiàn)場環(huán)境的收集

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

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

問題分析

從堆棧上可以看出,有這樣幾類線程：

• 等待進(jìn)入 INNODB engine 層的用戶線程,測試環(huán)境中 innodb_thread_concurrency=16, 當(dāng) INNODB 層中的活躍線程數(shù)目大于此值時(shí)則需要排隊(duì),所以會(huì)有大量的排隊(duì)線程,這個(gè)參數(shù)的影響&作用本身就是一篇很不錯(cuò)的文章,由于篇幅有限,在此不做擴(kuò)展,感興趣者可以參考官方文檔：https://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_thread_concurrency；
• 操作過程中需要寫 redo log 的后臺線程,主要包括 page cleaner 線程、異步 io threads等；
• 正在讀取Page頁面的 purge 線程 & 操作 change buffer 的 master thread；
• 大量的需要寫 redo log 的用戶線程.

從以上的分類不難看出,所有需要寫 redo log 的線程都在等待 log_sys->mutex,那么這個(gè)保護(hù) redo log buffer 的 mutex 被究竟被哪個(gè)線程獲取了呢,因此,我們可以順著這個(gè)線索進(jìn)行問題排查,需要解決以下問題：

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

1、問題一：由表及里

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

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

順著上面的思路很快的從 pstack 中找到了以下線程：

這里我們簡單介紹一下MySQL寫 redo log 的過程(省略undo & buffer pool 部分),當(dāng)對數(shù)據(jù)進(jìn)行修改時(shí),MySQL 會(huì)首先對針對操作類型記錄不同的 redo 日志,主要過程是：

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

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

說明：

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

2、問題二：彈盡糧絕

在問題一的排查過程中我們確定了 log_sys->mutex 的所屬線程, 這個(gè)線程在獲得 log_sys->log_flush_order_mutex 的過程中 hang 住了,因此線程堆棧可以分以為下幾類：

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

因此,問題的關(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)基本沒有線程獲得 log_sys->log_flush_order_mutex；
• gdb 進(jìn)入 MySQL Server, 將 log_sys->log_flush_order_mutex 打印出來,發(fā)現(xiàn) {waiters=1; lock_word= 0}!!!,即 Thread 446 在等待一個(gè)空閑的 mutex,而這個(gè)Mutex也確實(shí)被等待,由于我們的版本為 Release 版本,所以很多有用的信息沒有辦法得到,而若用 debug 版本跑則很難重現(xiàn)問題,log_flush_order_mutex 的定義如下：

由以上的分析可以得出 問題二 的答案：

• 只有兩個(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的過程中沒有喚醒 Thread 446,導(dǎo)致Thread 446 hang 并造成其它線程不能獲得 log_sys->mutex,進(jìn)而造成實(shí)例不可用；
• log_sys->log_flush_order_mutex 沒有被任何線程獲得.

3、問題三：絕處逢生

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

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

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

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

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

• 機(jī)器周末都在 hang 著,為什么沒有檢測到異常并 abort 呢?
• 既然 sync_arr_wake_threads_if_sema_free 可以喚醒,為什么沒有喚醒呢?

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

經(jīng)過上面的分析問題越來越明朗了,過程可以簡單的歸結(jié)為：

• Thread 446 獲得 log_sys->mutex, 但是在等待 log_sys->log_flush_order_mutex 的過程中沒有被喚醒；
• Thread XXX 在釋放 log_sys->log_flush_order_mutex 的過程中出現(xiàn)了 memory barrier 問題,沒有喚醒 Thread 446；
• Thread 470 獲得 log_sys->mutex 時(shí)被 hang 住,導(dǎo)致無法執(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ān)于 Memory barrier 的介紹可以參考 ：https://en.wikipedia.org/wiki/Memory_barrier

http://name5566.com/4535.html

問題解決

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

• 直接移除 log_get_lsn 在此處的判斷,本身就是開發(fā)人員加的一些判斷信息,為了定位 LSN 的異常而寫的,用到的時(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)過修改之后的版本在測試過程中沒有沒有再復(fù)現(xiàn)此問題.

問題擴(kuò)展

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

bug影響范圍：MySQL 5.6.28 及之前的版本都有此問題.

文章出處：DBAplus社群

轉(zhuǎn)載請注明本頁網(wǎng)址：
http://www.fzlkiss.com/jiaocheng/4406.html