MySQL：修改系統時鐘會導致數據庫hang住嗎？

水平有限，有誤請諒解

約定：

• page rwlock：控制page frame本生的讀寫鎖，這個通常再進行對page的讀取和修改的時候會涉及到，比如對page的修改需要上x類型的鎖。

• page mutex：主要控制page的io狀態等信息的mutex，本文不涉及。

• MTR：最小日誌單元，對於寫操作而言，其中包含了redo信息和page rwlock信息，MTR提交的時候會釋放page rw lock，並且將本次MTR的redo信息寫到redo buffer。

一、問題展示

最近遇到2次這個比較奇葩得問題，一次是8.0.16/一次是8.0.18，主要是信號量監控線程發現讀寫鎖超時自殺重啟數據庫。問題現象如下：

1. 讀寫鎖超時crash

主要的等待在如下的rwlock上，如下：

• 某線程 --Thread 140571742508800 has waited at buf0flu.cc line 1357 for 830 seconds the semaphore

• 某線程 --Thread 140579717510912 has waited at btr0pcur.h line 656 for 613 seconds the semaphore

當然不是上面這麼少，肯定很多，但是類型大概就是這兩種。

2. 日誌系統完全停止

這個問題主要在於整個信號量超時期間，從第一個信息輸出到最後一個信息輸出都不會變比如如下：

Log sequence number          20600471237
Log buffer assigned up to    20600471237
Log buffer completed up to   20600471237
Log written up to            20600471237
Log flushed up to            20600471237
Added dirty pages up to      20598368792
Pages flushed up to          20598368792
Last checkpoint at           20598368792
...
Pending writes: LRU 0, flush list 2, single page 0

這裏伴隨着刷盤IO的問題。

二、初次分析

1. 這些堵塞的線程到底是什麼，又堵塞在什麼讀寫鎖上

一般來講我們讀寫鎖一般都説文中開頭説的page rwlock。

--Thread 140571742508800 has waited at buf0flu.cc line 1357 for 830 seconds the semaphore 這種類型的實際上一看等待點就知道這玩意是clean線程，稍微翻一下代碼就知道這裏是在做flush list的刷盤。通常刷盤的時候會獲取page rwlock（sx類型）

--Thread 140579717510912 has waited at btr0pcur.h line 656 for 613 seconds the semaphore 這種類型的實際上就是正常的用户session，在對page進行訪問或者修改的時候需要page rwlock（x/s類型）。

那麼我們的redo日誌系統卡住前後的幾個lsn代表什麼意思呢？如下：

Log written up to            20600471237     
Log flushed up to            20600471237
Added dirty pages up to      20598368792
Pages flushed up to          20598368792

• Log written up to ：這實際上是log writer線程寫入到的redo的lsn位，在log_files_write_buffer函數內部更改，當然log writer是不斷地進行recent write數組，然後不斷地寫入到redo。對應log.write_lsn.load()。

• Log flushed up to：這實際上是log flusher線程刷盤到的redo的lsn位點，在log_flush_lown函數內部更改。對應 log.flushed_to_disk_lsn.load()。

• Added dirty pages up to：這實際上在8.0.16/8.0.18是由log closer線程更新的，但是8.0.22對log closer線程做了刪除，直接由用户線程自己負責。主要是查看推進的recent close數組的位點。對應就是log.recent_closed.tail()變量。而recent close數組作為clean線程和用户線程（8.0.22之前還有log closer線程）之間同步信息，我們很容易發現clean線程在根據recent close數組推進的結果進行刷髒參考函數page_cleaner_flush_pages_recommendation的開頭。

• Pages flushed up to：這實際上又log checkpoint線程更新，在進行進行檢查點之前，會進行可以進行檢查點的位置，那麼這個位置必須是已經寫了髒數據的位點，從計算的方式來看主要是應該是獲取各個buffer pool上flush list最老的那個page，那麼就是當前髒葉刷新的位點，但是有一些特別的計算函數log_compute_available_for_checkpoint_lsn

我們看到一個特別的現象就是Log flushed up to - Added dirty pages up to 大概不就是2M的空間，我印象中recent_closed數組的最大值就是2M，因此是不是説明recent_closed已經滿了，但是log closer線程不做推進了。如果是這種情況也很容模擬，我只需要用gdb的掛起線程的功能，將log closer掛起即可，我隨後進行了測試確實現象一模一樣。這也很容易理解，如果redo刷盤功能停止，那麼MTR的提交必然會受到堵塞，而我們page rwlock在MTR提交的時候釋放，所以hang住很容易理解。那麼是不是有BUG呢，當然版本比較老，如果有這個問題應該會由爆出來，因此用 log closer BUG mysql為關鍵字好像並沒有找到相關的BUG。

三、再次分析

前面考慮的是recent_closed數組已滿的情況，還會不會是recent_closed數組根本就是空的呢，我隨後查看log closer問題時候的stack，發現是正常的等待狀態，因此recent_closed數組為空的可能性就很大了。然後稍微看看MTR提交的時候關於recent_closed的更改前會判斷recent_closed是否有足夠的空間，如果這裏出現問題，那麼後面的recent_closed數組更新和將髒塊掛入到flush list就不會做，那麼log_closer線程自然會在推進完最後一次recent_closed數組後，因為無事可做而掛起。代碼很簡單就是下面這點：

然後呢我以log_wait_for_space_in_log_recent_closed函數為關鍵字尋找BUG，真還有如下：

• http://bugs.mysql.com/bug.php?id=96615

看提交者的描述這種問題就會導致 log closer無事可做而掛起，原因是在等待空閒recent_closed數組空間的時候用的不是原子時鐘，如果修改系統時間可能會出現這個問題。官方也沒説修復這個問題，最後的回覆如下：

看來真的不能隨便更改系統時間，非原子時鐘問題，可能導致某些該喚醒的不能喚醒。這回導致系統直接hang住。

可能這樣描述比較難理解，我用一個圖來表示吧，因為涉及的東西比較多。注意了，這裏不是説的事務提交，是MTR的提交，實際上我們的redo是一直在做寫入操作的，MTR的提交和後台線程之間是異步的。但是一旦涉及到事務提交，那麼雙1的情況下就必須要保證redo 刷盤，那麼到底異步的這些操作到底刷盤沒有，那就需要去額外的確認操作，如果還沒刷盤那就等，這個由我們的log_writer_notifier/log_flush_notifier線程介入，卻確認和反饋給用户線程。但是這個BUG裏不涉及，紅色部分就是問題所在點，