MySQL實例crash的案例分析

【做者】

王棟：攜程技術保障中心數據庫專家，對數據庫疑難問題的排查和數據庫自動化智能化運維工具的開發有強烈的興趣。

【問題描述】

咱們生產環境有一組集羣的多臺MySQL服務器(MySQL 5.6.21)，不按期的會crash，但error log中只記錄了重啓信息，未記錄crash時的堆棧：

mysqld_safe Number of processes running now: 0
mysqld_safe mysqld restarted

接下來首先排查系統日誌/var/log/message文件，crash時沒有其餘異常信息，也不是OOM致使的。

【排查思路】

因爲日誌中未記錄有價值的信息。爲定位crash的緣由，首先開啓mysql core dump的功能。
下面是開啓core dump的步驟：
一、 在my.cnf文件中增長2個配置項

[mysqld]

core_file

[mysqld_safe]

core-file-size=unlimited

二、修改系統參數，配置suid_dumpable

echo 1 >/proc/sys/fs/suid_dumpable

三、重啓mysql服務，配置生效

【問題分析】

開啓core dump後，服務器再次crash時生成了core file。
用gdb分析生成的core file，能夠看到crash時的堆棧信息以下：

從函數table_esms_by_digest::delete_all_rows能夠看出觸發crash的是truncate table events_statements_summary_by_digest操做。
咱們內部有個DML的分析工具，用來統計數據庫每分鐘增刪改查的訪問量。該工具的數據源是events_statements_summary_by_digest表，採集程序會每一分鐘採集一次這張表的數據，採集完成後執行truncate操做。
暫停這組集羣上DML採集程序後MySQL沒有再發生crash。

進一步分析多個core file，發現最終函數的調用都發生在_lf_pinbox_real_free函數上。
結合現場環境，有兩處地方值得分析：

一、 內存的不正常值。當打印該變量時，此處變量的地址偏低，不太正常：

(gdb) p pins->pinbox

$2 = (LF_PINBOX *) 0x1367208

二、紅字部分爲pfs逐條釋放digest記錄的操做，正在釋放某行數據時出現錯誤：

void reset_esms_by_digest()

{

uint index;

if (statements_digest_stat_array == NULL)

return;

PFS_thread *thread= PFS_thread::get_current_thread();

if (unlikely(thread == NULL))

return;

for (index= 0; index < digest_max; index++)

{

statements_digest_stat_array[index].reset_index(thread);

statements_digest_stat_array[index].reset_data();

}

digest_index= 1;

}

猜想有兩種可能致使錯誤：
一、高併發下，對內存訪問出現衝突；
二、某個特殊SQL致使，在處理hash時。

在網上搜索相似的問題，有了進一步的進展，基本肯定了這個問題是bug致使

以下Mysql的bug report中講述了相似問題
https://bugs.mysql.com/bug.php?id=73979
更詳細的環境描述以下鏈接中
https://bugs.launchpad.net/percona-server/+bug/1351148

查到5.6.35上的bug fix的修復內容，和咱們碰到的狀況很是相似。
對比_lf_pinbox_real_free的修改，該部分確實進行很大的調整。

下面是MySQL 5.6.35函數_lf_pinbox_real_free的代碼片斷：

static void _lf_pinbox_real_free(LF_PINS pins)
 {
 LF_PINBOX pinbox= pins->pinbox;

struct st_match_and_save_arg arg = {pins, pinbox, pins->purgatory};

pins->purgatory= NULL;

pins->purgatory_count= 0;

lf_dynarray_iterate(&pinbox->pinarray,

(lf_dynarray_func)match_and_save, &arg);

if (arg.old_purgatory)

{

void *last= arg.old_purgatory;

while (pnext_node(pinbox, last))

last= pnext_node(pinbox, last);

pinbox->free_func(arg.old_purgatory, last, pinbox->free_func_arg);

}

}

下面是MySQL 5.6.21函數的_lf_pinbox_real_free的代碼片斷

static void _lf_pinbox_real_free(LF_PINS pins)
 {
 int npins;
 void list;

void **addr= NULL;

void first= NULL, last= NULL;

LF_PINBOX pinbox= pins->pinbox;
 npins= pinbox->pins_in_array+1;
 if (pins->stack_ends_here != NULL)
 {
 int alloca_size= sizeof(void )LF_PINBOX_PINSnpins;

if (available_stack_size(&pinbox, *pins->stack_ends_here) > alloca_size)

{

struct st_harvester hv;

addr= (void **) alloca(alloca_size);

hv.granary= addr;

hv.npins= npins;

_lf_dynarray_iterate(&pinbox->pinarray,

(lf_dynarray_func)harvest_pins, &hv);

npins= hv.granary-addr;

if (npins)

qsort(addr, npins, sizeof(void *), (qsort_cmp)ptr_cmp);

}

}

同時觀察到出問題的集羣有指標異常，QPS不到6000，Threads_connected將近8000。（對比其餘高併發的集羣，QPS在20000以上，Threads_connected也只有300左右）。

排查應用端的鏈接方式，瞭解到其中一個應用有近百臺應用服務器，可能同時發起請求，卻沒有合理的複用鏈接，維持大量的鏈接線程增大了bug觸發的機率。

Bugs Fixed的描述以下：

Miscalculation of memory requirements for qsort operations could result in stack overflow errors in situations with a large number of concurrent server connections. (Bug #73979, Bug #19678930, Bug #23224078)

【解決思路】

咱們經過分析crash時的core file文件，找到crash時的觸發條件，暫停DML採集程序（truncate table events_statements_summary_by_digest操做）後恢復。 後面瞭解到這是MySQL的一個bug，在MySQL 5.6.35版本後已修復。這個bug在應用端與數據庫創建大量的鏈接時，更容易觸發。