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
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
在報錯資訊中提起比較代表性的資訊在官方網站中進行搜尋透過在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函式上。
作者微信：
微信.jpg
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/29734436/viewspace-2151285/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 當機導致slave異常分析
- 核心引數導致的備庫當機分析
- ORACLE 11.2.0.4 rac for linux 鏈路宕導致的單節點異常當機OracleLinux
- crontab導致CPU異常的問題分析及處理
- 神奇的DEBUG：因為異常導致MongoDB容器無法啟動MongoDB
- A站大流量導致服務崩潰異常分析
- MySQL 預插入的資料條數過多導致異常MySql
- UE floating pawn movement Bug Set location 導致速度異常發射
- 華為交換機LLDP震盪導致網路異常
- 外接程式 VMDebugger 未能載入或導致了異常 修復
- ORA-04031錯誤導致當機案例分析
- MySQL Case-時間問題導致MySQL例項批次當機MySql
- Oracle RAC啟動因CTSS導致的異常Oracle
- MySQL：MGR修改max_binlog_cache_size引數導致異常MySql
- SCN異常增長導致資料庫異常關閉風險的防範資料庫
- 記 Laravel Observer 導致 Redis 佇列異常LaravelServerRedis佇列
- 異常程式導致大量資源佔用
- cv::Mat轉QImage導致影像色彩異常
- 15、MySQL Case-時間問題導致MySQL例項批次當機MySql
- 序列異常導致災備端應用異常處理一則
- 從原始碼分析JSONObject因版本差異導致toString格式異常問題原始碼JSONObject
- 【譯】Gradle 的依賴關係處理不當，可能導致你編譯異常Gradle編譯
- GDI資源洩漏導致的程式異常的解析
- Oracle 資料庫不一致導致異常的恢復Oracle資料庫
- 一次意外斷電導致mysql檔案損壞，啟動異常MySql
- 伺服器架構導致的SEO收錄異常伺服器架構
- 異常連線導致的記憶體洩漏排查記憶體
- 驅動導致的當機怎麼解決
- 一條sql語句導致的資料庫當機問題及分析SQL資料庫
- 一條sql語句“導致”的資料庫當機問題及分析SQL資料庫
- MySQL8.0的一個bug導致複製延時MySql
- 時區不一致導致spring應用異常Spring
- MySQL Slave異常關機的處理MySql
- 360衛士阻止程式建立，導致各種異常
- OGG 表結構變化導致同步異常
- crontab設定導致的伺服器程式異常問題伺服器
- MongoDB 異常當機與引數cacheSizeGBMongoDB
- 由drop datafile導致的oracle bugOracle