MySQL：5.6 大事務(wù)show engine innodb status故障一例

今天遇到一個(gè)朋友的線上問(wèn)題，大概意思就是說(shuō)，我有一個(gè)線上的大事務(wù)大概100G左右，正在做回滾，當(dāng)前看起來(lái)似乎影響了線上的業(yè)務(wù)，并且回滾很慢，是否可以減輕對(duì)線上業(yè)務(wù)的影響。并且朋友已經(jīng)取消了雙1設(shè)置，但是沒(méi)有任何改觀。版本MySQL 5.6

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

首先我們需要知道的是，MySQL并不適合大事務(wù)，大概列舉一些MySQL中大事務(wù)的影響：

• binlog文件作為一次寫入，會(huì)在sync階段消耗大量的IO，會(huì)導(dǎo)致全庫(kù)hang主，狀態(tài)大多為query end。
• 大事務(wù)會(huì)造成導(dǎo)致主從延遲。
• 大事務(wù)可能導(dǎo)致某些需要備份掛起，原因在于flush table with read lock，拿不到MDL GLOBAL 級(jí)別的鎖，等待狀態(tài)為 Waiting for global read lock。
• 大事務(wù)可能導(dǎo)致更大Innodb row鎖加鎖范圍，導(dǎo)致row鎖等待問(wèn)題。
• 回滾困難。

基于如上一些不完全的列舉，我們應(yīng)該在線上盡可能的避免大事務(wù)。好了我們下面來(lái)進(jìn)行問(wèn)題討論。

一、問(wèn)題

前面已經(jīng)說(shuō)了，我們已經(jīng)取消了雙1設(shè)置，所謂的雙1就是 sync_binlog=1和 innodb_flush_log_at_trx_commit=1。這兩個(gè)參數(shù)線上要保證為1，前者保證binlog的安全，后者保證redo的安全，它們?cè)跀?shù)據(jù)庫(kù)crash recovery的時(shí)候起到了關(guān)鍵做用，不設(shè)置為雙1可能導(dǎo)致數(shù)據(jù)丟失。具體的參數(shù)含義不做過(guò)多討論。但是這里的問(wèn)題是即便取消了雙1，沒(méi)有任何改觀，因此似乎說(shuō)明IO問(wèn)題不是主要瓶頸呢？下面我們來(lái)看幾個(gè)截圖：

• vmstat 截圖

• iostat 截圖
  

• top -Hu截圖

我們重點(diǎn)觀察vmstat的r 和 b列發(fā)現(xiàn)，IO隊(duì)列沒(méi)有有什么問(wèn)題 并且wa%并不大。我們觀察iostat中的%util和讀寫數(shù)據(jù)大小來(lái)看問(wèn)題不大，并且tps遠(yuǎn)沒(méi)達(dá)到極限（SSD盤）。我們top -Hu 可以觀察到 %us不小，并且有線程已經(jīng)打滿了（99.4%CPU）一個(gè)CPU核。

因此我們可以將方向轉(zhuǎn)為研究CPU瓶頸的產(chǎn)生，希望能夠?qū)?wèn)題有幫助，然后從提供的perf top中我們有如下發(fā)現(xiàn)：

好了我們將問(wèn)題先鎖定到lock_number_of_rows_locked這個(gè)函數(shù)上。

二、函數(shù)lock_number_of_rows_locked的作用

朋友用的5.6，但是我這里以5.7.26的版本進(jìn)行描述。然后下一節(jié)描述5.6和5.7算法上的關(guān)鍵差異。

不知道大家是否注意過(guò)show engine innodb status中的這樣一個(gè)標(biāo)志：

這個(gè)標(biāo)記就來(lái)自函數(shù)lock_number_of_rows_locked，含義為當(dāng)前事務(wù)加行鎖的行數(shù)。而這個(gè)函數(shù)包裹在函數(shù)lock_print_info_all_transactions下面，lock_print_info_all_transactions函數(shù)是打印我們通?？吹絪how engine innodb status中事務(wù)部分的核心參數(shù)。我們來(lái)看一下簡(jiǎn)單的流程：

    PrintNotStarted print_not_started(file);//建立一個(gè)結(jié)構(gòu)體，目的是做not start 事務(wù)的打印
    ut_list_map(trx_sys->mysql_trx_list, print_not_started); //這個(gè)地方打印出那些事務(wù)狀態(tài)是no start的事務(wù)。mysql_trx_list是全事務(wù)。
    const trx_t*    trx;
    TrxListIterator trx_iter; //這個(gè)迭代器是trx_sys->rw_trx_list 這個(gè)鏈表的迭代器
    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) { //通過(guò)迭代器進(jìn)行迭代 ，顯然這里不會(huì)有只讀事務(wù)的信息，全部是讀寫事務(wù)。
       ...
        /* 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( //打印出鎖的詳細(xì)信息
                    file, trx, lock_iter, load_block))

簡(jiǎn)單的說(shuō)就是先打印哪些處于not start的事務(wù)，然后打印那些讀寫事務(wù)的信息，當(dāng)然我們的回滾事務(wù)肯定也包含在其中了，需要注意的是只讀事務(wù)show engine不會(huì)打印。
對(duì)于處于回滾狀態(tài)的事務(wù)我們可以在show engine中觀察到如下信息：

函數(shù)trx_print_low可以看到大部分的信息，這里就不詳細(xì)解釋了。既然如此我們需要明白lock_number_of_rows_locked是如何計(jì)算的，下面進(jìn)行討論。

三、函數(shù)lock_number_of_rows_locked的算法變化

上面我們說(shuō)了函數(shù)lock_number_of_rows_locked函數(shù)會(huì)打印出當(dāng)前事務(wù)加行鎖的行數(shù)。那么我們來(lái)看一下5.6和5.7算法的不同。

• 5.7.26

實(shí)際上只有如下一句話：

return(trx_lock->n_rec_locks);

我們可以看到這是返回了一個(gè)計(jì)數(shù)器，而這個(gè)計(jì)數(shù)器的遞增就是在每行記錄加鎖后完成的，在函數(shù)lock_rec_set_nth_bit的末尾可以看到 ++lock->trx->lock.n_rec_locks ，因此這是一種預(yù)先計(jì)算的機(jī)制。

因此這樣的計(jì)算代價(jià)很低，也不會(huì)由于某個(gè)事務(wù)持有了大量的鎖，而導(dǎo)致計(jì)算代價(jià)過(guò)高。

• 5.6.22

隨后我翻了一下5.6.22的代碼，發(fā)現(xiàn)完全不同如下：

    for (lock = UT_LIST_GET_FIRST(trx_lock->trx_locks); //使用for循環(huán)每個(gè)獲取的鎖結(jié)構(gòu)
         lock != NULL;
         lock = UT_LIST_GET_NEXT(trx_locks, lock)) {
        if (lock_get_type_low(lock) == LOCK_REC) { //過(guò)濾為行鎖 
            ulint    n_bit;
            ulint    n_bits = lock_rec_get_n_bits(lock);
            for (n_bit = 0; n_bit < n_bits; n_bit++) {//開(kāi)始循環(huán)每一個(gè)鎖結(jié)構(gòu)的每一個(gè)bit位進(jìn)行統(tǒng)計(jì)
                if (lock_rec_get_nth_bit(lock, n_bit)) {
                    n_records++;
                }
            }
        }
    }
    return(n_records);

我們知道循環(huán)本身是一種CPU密集型的操作，這里使用了嵌套循環(huán)實(shí)現(xiàn)。因此如果在5.6中如果出現(xiàn)大事務(wù)操作了大量的行，那么獲取行鎖記錄的個(gè)數(shù)的時(shí)候，將會(huì)出現(xiàn)高耗CPU的情況。

四、原因總結(jié)和解決

有了上面的分析我們很清楚了，觸發(fā)的原因有如下幾點(diǎn)：

• MySQL 5.6版本
• 有大事務(wù)的存在，大概100G左右的數(shù)據(jù)加行鎖了
• 使用了show engine innodb status

這樣當(dāng)在統(tǒng)計(jì)這個(gè)大事務(wù)行鎖個(gè)數(shù)的時(shí)候，就會(huì)進(jìn)行大量的循環(huán)操作。從現(xiàn)象上看就是線程消耗了大量的CPU資源，并且處于perf top的第一位。

知道了原因就很簡(jiǎn)單了，找出為頻繁使用show engine innodb status的監(jiān)控工具，隨后業(yè)務(wù)全部恢復(fù)正常，IO利用率也上升了如下：

當(dāng)然如果能夠使用更新的版本比如5.7及8.0 版本將不會(huì)出現(xiàn)這個(gè)問(wèn)題，可以考慮使用更高版本。

分析性能問(wèn)題需要首先找到性能的瓶頸然后進(jìn)行集中突破，比如本例中CPU資源消耗更加嚴(yán)重。也許解決問(wèn)題就在一瞬間。

五、其他

最后通過(guò)朋友后面查詢的bug如下：
https://bugs.mysql.com/bug.php?id=68647
發(fā)現(xiàn)印風(fēng)（翟衛(wèi)翔）已經(jīng)在多年前提出過(guò)了這個(gè)問(wèn)題，并且做出了修改意見(jiàn)，并且這個(gè)修改意見(jiàn)官方采納了，也就是上面我們分析的算法改變。經(jīng)過(guò)印風(fēng)（翟衛(wèi)翔）的測(cè)試有bug中有如下描述：

• From perf top, function lock_number_of_rows_locked may occupy more than 20% of CPU sometimes

也就是CPU消耗會(huì)高達(dá)20%。

下面是5.7.26調(diào)用棧幀：

#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