MySQL:5.6 大事務show engine innodb status故障一例
- 2020 年 3 月 13 日
- 筆記
導讀：
今天遇到一個朋友的線上問題，大概意思就是說，我有一個線上的大事務大概100G左右，正在做回滾，當前看起來似乎影響了線上的業務，並且回滾很慢，是否可以減輕對線上業務的影響。並且朋友已經取消了雙1設置，但是沒有任何改觀。版本MySQL 5.6
首先我們需要知道的是，MySQL並不適合大事務，大概列舉一些MySQL中大事務的影響：
- binlog文件作為一次寫入，會在sync階段消耗大量的IO，會導致全庫hang主，狀態大多為query end。
- 大事務會造成導致主從延遲。
- 大事務可能導致某些需要備份掛起，原因在於flush table with read lock，拿不到MDL GLOBAL 級別的鎖，等待狀態為 Waiting for global read lock。
- 大事務可能導致更大Innodb row鎖加鎖範圍，導致row鎖等待問題。
- 回滾困難。
基於如上一些不完全的列舉，我們應該在線上儘可能的避免大事務。好了我們下面來進行問題討論。
一、問題
前面已經說了，我們已經取消了雙1設置，所謂的雙1就是 sync_binlog=1和 innodb_flush_log_at_trx_commit=1。這兩個參數線上要保證為1，前者保證binlog的安全，後者保證redo的安全，它們在資料庫crash recovery的時候起到了關鍵做用，不設置為雙1可能導致數據丟失。具體的參數含義不做過多討論。但是這裡的問題是即便取消了雙1，沒有任何改觀，因此似乎說明IO問題不是主要瓶頸呢？下面我們來看幾個截圖：
- vmstat 截圖
- iostat 截圖
- top -Hu截圖
我們重點觀察vmstat的r 和 b列發現，IO隊列沒有有什麼問題 並且wa%並不大。我們觀察iostat中的%util和讀寫數據大小來看問題不大，並且tps遠沒達到極限（SSD盤）。我們top -Hu 可以觀察到 %us不小，並且有執行緒已經打滿了（99.4%CPU）一個CPU核。
因此我們可以將方向轉為研究CPU瓶頸的產生，希望能夠對問題有幫助，然後從提供的perf top中我們有如下發現：
好了我們將問題先鎖定到lock_number_of_rows_locked這個函數上。
_
朋友用的5.6，但是我這裡以5.7.26的版本進行描述。然後下一節描述5.6和5.7演算法上的關鍵差異。
不知道大家是否注意過show engine innodb status中的這樣一個標誌：
這個標記就來自函數lock_number_of_rows_locked，含義為當前事務加行鎖的行數。而這個函數包裹在函數lock_print_info_all_transactions下面，lock_print_info_all_transactions函數是列印我們通常看到show engine innodb status中事務部分的核心參數。我們來看一下簡單的流程：
PrintNotStarted print_not_started(file);//建立一個結構體，目的是做not start 事務的列印 ut_list_map(trx_sys->mysql_trx_list, print_not_started); //這個地方列印出那些事務狀態是no start的事務。mysql_trx_list是全事務。 const trx_t* trx; TrxListIterator trx_iter; //這個迭代器是trx_sys->rw_trx_list 這個鏈表的迭代器 const trx_t* prev_trx = 0; /* Control whether a block should be fetched from the buffer pool. */ bool load_block = true; bool monitor = srv_print_innodb_lock_monitor && (srv_show_locks_held != 0); while ((trx = trx_iter.current()) != 0) { //通過迭代器進行迭代 ，顯然這裡不會有隻讀事務的資訊，全部是讀寫事務。 ... /* If we need to print the locked record contents then we need to fetch the containing block from the buffer pool. */ if (monitor) { /* Print the locks owned by the current transaction. */ TrxLockIterator& lock_iter = trx_iter.lock_iter(); if (!lock_trx_print_locks( //列印出鎖的詳細資訊 file, trx, lock_iter, load_block))
簡單的說就是先列印哪些處於not start的事務，然後列印那些讀寫事務的資訊，當然我們的回滾事務肯定也包含在其中了，需要注意的是只讀事務show engine不會列印。對於處於回滾狀態的事務我們可以在show engine中觀察到如下資訊：
函數trx_print_low可以看到大部分的資訊，這裡就不詳細解釋了。既然如此我們需要明白lock_number_of_rows_locked是如何計算的，下面進行討論。
三、函數lock_number_of_rows_locked的演算法變化
上面我們說了函數lock_number_of_rows_locked函數會列印出當前事務加行鎖的行數。那麼我們來看一下5.6和5.7演算法的不同。
- 5.7.26
實際上只有如下一句話：
return(trx_lock->n_rec_locks);
我們可以看到這是返回了一個計數器，而這個計數器的遞增就是在每行記錄加鎖後完成的，在函數lock_rec_set_nth_bit的末尾可以看到 ++lock->trx->lock.nreclocks ，因此這是一種預先計算的機制。
因此這樣的計算代價很低，也不會由於某個事務持有了大量的鎖，而導致計算代價過高。
- 5.6.22
隨後我翻了一下5.6.22的程式碼，發現完全不同如下：
for (lock = UT_LIST_GET_FIRST(trx_lock->trx_locks); //使用for循環每個獲取的鎖結構 lock != NULL; lock = UT_LIST_GET_NEXT(trx_locks, lock)) { if (lock_get_type_low(lock) == LOCK_REC) { //過濾為行鎖 ulint n_bit; ulint n_bits = lock_rec_get_n_bits(lock); for (n_bit = 0; n_bit < n_bits; n_bit++) {//開始循環每一個鎖結構的每一個bit位進行統計 if (lock_rec_get_nth_bit(lock, n_bit)) { n_records++; } } } } return(n_records);
我們知道循環本身是一種CPU密集型的操作，這裡使用了嵌套循環實現。因此如果在5.6中如果出現大事務操作了大量的行，那麼獲取行鎖記錄的個數的時候，將會出現高耗CPU的情況。
四、原因總結和解決
有了上面的分析我們很清楚了，觸發的原因有如下幾點：
- MySQL 5.6版本
- 有大事務的存在，大概100G左右的數據加行鎖了
- 使用了show engine innodb status
這樣當在統計這個大事務行鎖個數的時候，就會進行大量的循環操作。從現象上看就是執行緒消耗了大量的CPU資源，並且處於perf top的第一位。
知道了原因就很簡單了，找出為頻繁使用show engine innodb status的監控工具，隨後業務全部恢復正常，IO利用率也上升了如下：
當然如果能夠使用更新的版本比如5.7及8.0 版本將不會出現這個問題，可以考慮使用更高版本。
分析性能問題需要首先找到性能的瓶頸然後進行集中突破，比如本例中CPU資源消耗更加嚴重。也許解決問題就在一瞬間。
五、其他
最後通過朋友後面查詢的bug如下：https://bugs.mysql.com/bug.php?id=68647 發現印風（翟衛翔）已經在多年前提出過了這個問題，並且做出了修改意見，並且這個修改意見官方採納了，也就是上面我們分析的演算法改變。經過印風（翟衛翔）的測試有bug中有如下描述：
- From perf top, function locknumberofrowslocked may occupy more than 20% of CPU sometimes
也就是CPU消耗會高達20%。
下面是5.7.26調用棧幀：
