MySQL Bug導致異常當機的分析流程

---

本文主要通過一個bug來記錄一下如何分析一個MySQL bug的崩潰資訊。
版本:Percona 5.7.17-11

---

一、資料庫重啟日誌分析

terminate called after throwing an instance of 'std::out_of_range' what():  vector::_M_range_check
04:10:09 UTC - mysqld got signal 6 ;
mysqld got signal 6 ;
......
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x40000
/dbdata/mysql3306/bin/mysqld(my_print_stacktrace+0x35)[0xf3e175]
/dbdata/mysql3306/bin/mysqld(handle_fatal_signal+0x4b4)[0x7c3b94]
/lib64/libpthread.so.0(+0xf7e0)[0x7f79f28e87e0]
/lib64/libc.so.6(gsignal+0x35)[0x7f79f137d495]
/lib64/libc.so.6(abort+0x175)[0x7f79f137ec75]
/usr/lib64/libstdc++.so.6(_ZN9__gnu_cxx27__verbose_terminate_handlerEv+0x12d)[0x7f79f1c37a8d]
/usr/lib64/libstdc++.so.6(+0xbcbe6)[0x7f79f1c35be6]
/usr/lib64/libstdc++.so.6(+0xbcc13)[0x7f79f1c35c13]
/usr/lib64/libstdc++.so.6(+0xbcd32)[0x7f79f1c35d32]
/usr/lib64/libstdc++.so.6(_ZSt20__throw_out_of_rangePKc+0x67)[0x7f79f1bdadb7]
/dbdata/mysql3306/bin/mysqld[0x11d8f15]
/dbdata/mysql3306/bin/mysqld[0x11d99d5]
/dbdata/mysql3306/bin/mysqld(_Z17dict_stats_updateP12dict_table_t23dict_stats_upd_option_t+0x9dc)[0x11de0cc]
/dbdata/mysql3306/bin/mysqld(dict_stats_thread+0x4f2)[0x11e0512]
/lib64/libpthread.so.0(+0x7aa1)[0x7f79f28e0aa1]
/lib64/libc.so.6(clone+0x6d)[0x7f79f1433bcd]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information in the manual which will help you identify the cause of the crash. 

這部分是資料庫崩潰的時候的棧幀，因為收到的是訊號6 SIGABRT，只要捕獲訊號後改變其行為即可。這部分在MySQL官方文件中叫做Stack Trace，參考：

28.5.1.5 Using a Stack Trace 

實際上在這裡我們已經可以看到大約是統計資料收集的問題，因為我們看到了dict_stats_thread，這是統計收集執行緒的回撥函式。

二、生成更加視覺化的Stack Trace

1、通過Stack Trace獲得記憶體地址

獲取如下：

[0xf3e175]
[0x7c3b94]
[0x7f79f28e87e0]
[0x7f79f137d495]
[0x7f79f137ec75]
[0x7f79f1c37a8d]
[0x7f79f1c35be6]
[0x7f79f1c35c13]
[0x7f79f1c35d32]
[0x7f79f1bdadb7]
[0x11d8f15]
[0x11d99d5]
[0x11de0cc]
[0x11e0512]
[0x7f79f28e0aa1]
[0x7f79f1433bcd] 

2、將這些地址放入一個檔案

如：vi /tmp/err0222.log放入即可

3、通nm命令獲取庫檔案連結檔案

如：nm -D -n ./mysqld > /tmp/mysqld.sym

4、使用mysql工具resolve_stack_dump得到輸出

如下：

[root@dyzsdb2 bin]# ./resolve_stack_dump -s /tmp/mysqld.sym -n /tmp/err0222.log | c++filt 

0xf3e175 my_print_stacktrace + 53 

0x7c3b94 handle_fatal_signal + 1204

 0x7f79f28e87e0 _end + -258115144 

0x7f79f137d495 _end + -280574355 

0x7f79f137ec75 _end + -280568243 

0x7f79f1c37a8d _end + -271422363 

0x7f79f1c35be6 _end + -271430210 

0x7f79f1c35c13 _end + -271430165 

0x7f79f1c35d32 _end + -271429878 

0x7f79f1bdadb7 _end + -271802481 

0x11d8f15 dict_stats_analyze_index_for_n_prefix(dict_index_t*, unsigned long, std::vector<unsigned long, ut_allocator<unsigned long> > const*, n_diff_data_t*, mtr_t*) + 4949 

0x11d99d5 dict_stats_analyze_index(dict_index_t*) + 2693 

0x11de0cc dict_stats_update(dict_table_t*, dict_stats_upd_option_t) + 2524 

0x11e0512 dict_stats_thread + 1266 0x7f79f28e0aa1 _end + -258147207 

0x7f79f1433bcd _end + -279827035 

實際上到這裡通過函式的呼叫我們可以發現是統計資料收集出現了問題。

三、通過官方網站查詢Bug

• https://bugs.launchpad.net/percona-server
• https://bugs.mysql.com/

在報錯資訊中提起比較代表性的資訊在官方網站中進行搜尋通過在percona中檢視發現本bug由上游MySQL程式碼造成BUG號：Bug #84940
並且發現在5.7.18中得到修復同時給出了內部BUG號如下：

[10 Feb 2017 8:12] Shane Bester
Oli, Umesh, this would be same as internal:
Bug 24585978 - INNODB: ASSERTION TOTAL_RECS > 0 FAILURE IN FILE DICT0STATS.CC 

四、查詢Bug到底修改了什麼地方

這裡請教了阿里的印風兄才知道怎麼檢視，首先拿到了內部bug號：24585978
然後在git的commit log中搜尋得到
git --no-pager log >/root/commitlog
vi /root/commitlog 找到commit號為：
29acdaaaeef9afe32b42785f1da3d79d56ed7e59
如下是這個bug的修復地方：

commit 29acdaaaeef9afe32b42785f1da3d79d56ed7e59
Author: Thirunarayanan Balathandayuthapani 
Date:   Wed Feb 8 12:00:52 2017 +0530 Bug #24585978 INNODB: ASSERTION TOTAL_RECS > 0 FAILURE
                        IN FILE DICT0STATS.CC
    
    Analysis:
    ========
    There was missing bracket for IF conditon in dict_stats_analyze_index_level() and it leads to wrong result.
    
    Fix:
    ====
    Fix the IF condition in dict_stats_analyze_index_level() so that it satisfied
    the if condtion only if level is zero.
    
    Reviewed-by : Jimmy Yang 

diff --git a/storage/innobase/dict/dict0stats.cc b/storage/innobase/dict/dict0stats.cc
index 3494070..55a2626 100644 --- a/storage/innobase/dict/dict0stats.cc
+++ b/storage/innobase/dict/dict0stats.cc
@@ -1099,10 +1099,10 @@ dict_stats_analyze_index_level(
                leaf-level delete marks because delete marks on
                non-leaf level do not make sense. */
 
- if (level == 0 && srv_stats_include_delete_marked? 0:
+ if (level == 0 && (srv_stats_include_delete_marked ? 0:
                    rec_get_deleted_flag(
                            rec,
-                           page_is_comp(btr_pcur_get_page(&pcur)))) {
+                           page_is_comp(btr_pcur_get_page(&pcur))))) { if (rec_is_last_on_page
                            && !prev_rec_is_copied 

五、為什麼這麼修改

這裡是我的淺顯的分析，不對的地方的還請見諒。
我們發現這裡實際上修改就是多了一個括號而已，但是意義是相當重要的。

if (level == 0 && srv_stats_include_delete_marked ? 0:
            rec_get_deleted_flag(
                rec,
                page_is_comp(btr_pcur_get_page(&pcur)))) 
修改為了 if (level == 0 && (srv_stats_include_delete_marked ? 0:
            rec_get_deleted_flag(
                rec,
                page_is_comp(btr_pcur_get_page(&pcur))))) 

修改前：
如果level != 0 不管innodb_stats_include_delete_marked引數如何設定必然觸發判斷是否存在del_flag,然後通過設定偏移量的方式 跳過這行，但是隨後的(*total_recs)++; 將不會觸發，極端情況下可能為0。
而在上層程式碼dict_stats_analyze_index中的found_level:地方實際上是需要非葉子結點行數不為0的如下：

 /* if any of these is 0 then there is exactly one page in the
        B-tree and it is empty and we should have done full scan and should not be here */
        ut_ad(total_recs > 0);
        ut_ad(n_diff_on_level[n_prefix - 1] > 0); 

六、如何規避

在官網檢視的時候有如下方式可以規避這個Bug

• 升級到5.7.18
• 設定引數

innodb-stats-persistent             = 0 

innodb-stats-transient-sample-pages = 20 

innodb-stats-auto-recalc            = 0 

設定這些引數後實際上是使用的老的非固化的統計資料收集的方式，而不會通過執行緒dict_stats_thread收集下面是邏輯片段位於row_update_statistics_if_needed中如下：

 if (dict_stats_is_persistent_enabled(table)) { //引數innodb-stats-persistent 作用 if (counter > n_rows / 10 /* 10% */ && dict_stats_auto_recalc_is_enabled(table)) {//引數innodb-stats-auto-recalc 作用 dict_stats_recalc_pool_add(table);
            table->stat_modified_counter = 0;
        } return;
    } /* Calculate new statistics if 1 / 16 of table has been modified
    since the last time a statistics batch was run.
    We calculate statistics at most every 16th round, since we may have
    a counter table which is very small and updated very often. */ if (counter > 16 + n_rows / 16 /* 6.25% */) {

        ut_ad(!mutex_own(&dict_sys->mutex)); /* this will reset table->stat_modified_counter to 0 */ dict_stats_update(table, DICT_STATS_RECALC_TRANSIENT);
    } 

這樣做的話肯定不會呼叫到觸發bug的函式，有興趣的可以看看dict_stats_update(table, DICT_STATS_RECALC_TRANSIENT);的邏輯。實際上使用的是老的方式斷點可以打在btr_estimate_number_of_different_key_vals函式上。

作者微信：

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/7728585/viewspace-2151173/，如需轉載，請註明出處，否則將追究法律責任。