MySQL：5.6 大事務show engine innodb status故障一例

---

今天遇到一個朋友的線上問題，大概意思就是說，我有一個線上的大事務大概100G左右，正在做回滾，當前看起來似乎影響了線上的業務，並且回滾很慢，是否可以減輕對線上業務的影響。並且朋友已經取消了雙1設定，但是沒有任何改觀。版本MySQL 5.6

---

歡迎關注我的《深入理解MySQL主從原理 32講 》，如下：

---

首先我們需要知道的是，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這個函式上。

二、函式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.n_rec_locks ，因此這是一種預先計算的機制。

因此這樣的計算代價很低，也不會由於某個事務持有了大量的鎖，而導致計算代價過高。

• 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 lock_number_of_rows_locked may occupy more than 20% of CPU sometimes

也就是CPU消耗會高達20%。

下面是5.7.26呼叫棧幀：

#0  lock_number_of_rows_locked (trx_lock=0x7fffedc5bdd0) at /mysql/mysql-5.7.26/storage/innobase/lock/lock0lock.cc:1335
#1  0x0000000001bd700f in trx_print_latched (f=0x301cad0, trx=0x7fffedc5bd08, max_query_len=600) at /mysql/mysql-5.7.26/storage/innobase/trx/trx0trx.cc:2633
#2  0x0000000001a3ac40 in lock_trx_print_wait_and_mvcc_state (file=0x301cad0, trx=0x7fffedc5bd08) at /mysql/mysql-5.7.26/storage/innobase/lock/lock0lock.cc:5170
#3  0x0000000001a3b28f in lock_print_info_all_transactions (file=0x301cad0) at /mysql/mysql-5.7.26/storage/innobase/lock/lock0lock.cc:5357
#4  0x0000000001b794b1 in srv_printf_innodb_monitor (file=0x301cad0, nowait=0, trx_start_pos=0x7fffec3f4cc0, trx_end=0x7fffec3f4cb8)
    at /mysql/mysql-5.7.26/storage/innobase/srv/srv0srv.cc:1250
#5  0x00000000019bd5c9 in innodb_show_status (hton=0x2e85bd0, thd=0x7fffe8000c50, 
    stat_print=0xf66cab <stat_print(THD*, char const*, size_t, char const*, size_t, char const*, size_t)>)
    at /mysql/mysql-5.7.26/storage/innobase/handler/ha_innodb.cc:15893
#6  0x00000000019bdf35 in innobase_show_status (hton=0x2e85bd0, thd=0x7fffe8000c50, 
    stat_print=0xf66cab <stat_print(THD*, char const*, size_t, char const*, size_t, char const*, size_t)>, stat_type=HA_ENGINE_STATUS)
    at /mysql/mysql-5.7.26/storage/innobase/handler/ha_innodb.cc:16307