MySQL · 答疑解惑 · 物理備份死鎖分析

背景

本文對 5.6 主備場景下，在備庫做物理備份遇到死鎖的case進(jìn)行分析，希望對大家有所幫助。

這里用的的物理備份工具是 Percona-XtraBackup(PXB)，有的同學(xué)可能不清楚其備份流程，所以這里先簡單說下，PXB的備份步驟是這樣的：

1. 拷貝 InnoDB redo log，這是一個單獨的線程在拷，直到備份結(jié)束；
2. 拷貝所有InnoDB ibd文件；
3. 加全局讀鎖，執(zhí)行 FLUSH TABLES WITH READ LOCK(FTWRL);
4. 拷貝 frm、MYD、MYI 等文件；
5. 獲取位點信息，執(zhí)行 show slave status 和 show master status；
6. 解鎖，UNLOCK TABLES;
7. 做一些收尾處理，備份結(jié)束。

如果 MyISAM 表很多話，全局讀鎖的持有時間會比較長，所以一般都在備庫做備份。

另外 FLUSH TABLE WITH READ LOCK 這條命令會獲取2個MDL鎖，全局讀鎖（MDL_key::GLOBAL）和全局COMMIT（MDL_key::COMMIT）鎖，MDL鎖詳情可以參考之前的月報MDL 實現(xiàn)分析。

死鎖分析

CASE 1

我們先看一下死鎖時的現(xiàn)場是怎樣的：

mysql> show processlist;
+----+-------------+-----------------+------+---------+------+----------------------------------------+-------------------+
| Id | User        | Host            | db   | Command | Time | State                                  | Info              |
+----+-------------+-----------------+------+---------+------+----------------------------------------+-------------------+
| 1 | root        | 127.0.0.1:53309 | NULL | Query   | 278 | init                                   | show slave status |
| 2 | system user |                 | NULL | Connect | 381 | Queueing master event to the relay log | NULL |
| 3 | system user |                 | NULL | Connect | 311 | Waiting for commit lock                | NULL |
| 4 | root        | 127.0.0.1:53312 | NULL | Query   | 0 | init                                   | show processlist  |
+----+-------------+-----------------+------+---------+------+----------------------------------------+-------------------+

可以看到 show slave status 被堵了很久，另外 SQL 線程在 Waiting for commit lock，說明在等待 COMMIT 鎖。

這時候如果我們再連接進(jìn)去執(zhí)行 show slave status 也會被堵，并且即使 Ctrl-C kill 掉線程，線程依然還在。

mysql> show processlist;
+----+-------------+-----------------+------+---------+------+----------------------------------------+-------------------+
| Id | User        | Host            | db   | Command | Time | State                                  | Info              |
+----+-------------+-----------------+------+---------+------+----------------------------------------+-------------------+
| 1 | root        | 127.0.0.1:53309 | NULL | Query   | 753 | init                                   | show slave status |
| 2 | system user |                 | NULL | Connect | 856 | Queueing master event to the relay log | NULL |
| 3 | system user |                 | NULL | Connect | 786 | Waiting for commit lock                | NULL |
| 4 | root        | 127.0.0.1:53312 | NULL | Killed  | 188 | init                                   | show slave status |
| 5 | root        | 127.0.0.1:53314 | NULL | Query   | 0 | init                                   | show processlist  |
| 8 | root        | 127.0.0.1:53318 | NULL | Killed  | 125 | init                                   | show slave status |
| 11 | root        | 127.0.0.1:53321 | NULL | Killed  | 123 | init                                   | show slave status |
| 14 | root        | 127.0.0.1:53324 | NULL | Query   | 120 | init                                   | show slave status |
+----+-------------+-----------------+------+---------+------+----------------------------------------+-------------------+

pstack 看下相關(guān)線程的 backtrace，show slave status 線程的 backtrace 如下，非常明顯是在等mutex，對應(yīng)代碼為 mysql_mutex_lock(&mi->rli->data_lock):

#0 __lll_lock_wait #1 _L_lock_974 #2 __GI___pthread_mutex_lock #3 inline_mysql_mutex_lock #4 show_slave_status #5 mysql_execute_command #6 mysql_parse #7 dispatch_command #8 do_command #9 do_handle_one_connection #10 handle_one_connection ...

SQL 線程的 backtrace 如下，在等 COMMIT 鎖：

#0 pthread_cond_timedwait #1 inline_mysql_cond_timedwait #2 MDL_wait::timed_wait #3 MDL_context::acquire_lock #4 ha_commit_trans #5 trans_commit #6 Xid_log_event::do_commit #7 Xid_log_event::do_apply_event #8 Log_event::apply_event #9 apply_event_and_update_pos #10 exec_relay_log_event #11 handle_slave_sql ...

如果我們gdb進(jìn)去，去調(diào)試SQL線程，在 MDL_context::acquire_lock中：

(gdb) p (MDL_key::enum_mdl_namespace)lock->key->m_ptr[0] $24 = MDL_key::COMMIT (gdb) p ((THD*)lock->m_granted.m_list.m_first->m_ctx->m_owner)->thread_id $25 = 1

可以看到 COMMIT 鎖被線程 1 持有。

SQL線程在 Xid_log_event::do_commit 之前會持有 rli_ptr->data_lock。

所以現(xiàn)在就清楚了，是線程1（備份線程）和線程3（SQL線程）死鎖了，還原下死鎖過程：

1. 備份線程執(zhí)行 FTWRL，拿到 COMMIT 鎖；
2. SQL線程執(zhí)行到Xid event，準(zhǔn)備提交事務(wù)，請求 COMMIT 鎖，被備份線程阻塞；
3. 備份線程為了獲取 slave 執(zhí)行位點，執(zhí)行 show slave status，需要獲取 rli->data_lock，被 SQL 線程阻塞。

就這樣2個線程互相持有等待，形成死鎖。

我們知道，MDL 是有死鎖檢測的，為什么這里沒有檢測到呢？因為rli->data_lock是一個mutex，不屬于MDL系統(tǒng)的，在這個死鎖場景中，MDL鎖系統(tǒng)只能檢測到對 COMMIT 鎖的請求，是不存在死鎖的。

之后的 show slave status 都被堵，是因為在執(zhí)行 show slave status 前，會請求一個mutex:

mysql_mutex_lock(&LOCK_active_mi); res= show_slave_status(thd, active_mi);
mysql_mutex_unlock(&LOCK_active_mi);

之前死鎖的 show slave status 沒有退出，后面的 show slave status 自然堵在這個 mutex 上，并且因為無法檢測 thd->killed，所以一直無法退出。

死鎖的原因是SQL線程在提交的時候，持有 rli->data_lock 鎖，其實這個是不需要的，MySQL 官方在這個 patch 中修復(fù)。

CASE 2

在上面的bug修復(fù)后，又出現(xiàn)了死鎖，但死鎖的情況卻不一樣，show processlist 結(jié)果如下：

mysql> show processlist;
+----+-------------+-----------------+------+---------+------+----------------------------------+-------------------+
| Id | User        | Host            | db   | Command | Time | State                            | Info              |
+----+-------------+-----------------+------+---------+------+----------------------------------+-------------------+
| 2 | system user |                 | NULL | Connect | 436 | Waiting for master to send event | NULL |
| 3 | system user |                 | NULL | Connect | 157 | Waiting for commit lock          | NULL |
| 6 | root        | 127.0.0.1:42787 | NULL | Query   | 86 | init                             | show slave status |
| 7 | root        | 127.0.0.1:42788 | NULL | Query   | 96 | Killing slave                    | stop slave        |
| 8 | root        | 127.0.0.1:42789 | NULL | Query   | 0 | init                             | show processlist  |
+----+-------------+-----------------+------+---------+------+----------------------------------+-------------------+

依然是 SQL 線程在等待commit鎖，然后 show slave status 被堵住沒有返回，不同的是多了一個 stop slave; 我們來看下 stop slave 的backtrace:

#0 pthread_cond_timedwait #1 inline_mysql_cond_timedwait #2 terminate_slave_thread #3 terminate_slave_threads #4 stop_slave #5 mysql_execute_command #6 mysql_parse #7 dispatch_command #8 do_command #9 do_handle_one_connection #10 handle_one_connection ...

對應(yīng)代碼，可以發(fā)現(xiàn) stop slave 正在等待 SQL 線程退出，而SQL線程此時正在等待備份線程（id=6）持有的 COMMIT 鎖。整個死鎖過程是這樣的：

1. 備份線程執(zhí)行 FTWRL，拿到 COMMIT 鎖；
2. SQL線程執(zhí)行到Xid event，準(zhǔn)備提交事務(wù)，請求 COMMIT 鎖，被備份線程阻塞；
3. 用戶執(zhí)行 stop slave，準(zhǔn)備停掉備庫復(fù)制線程，等待 SQL 線程退出；
4. 備份線程為了獲取 slave 執(zhí)行位點，執(zhí)行 show slave status，需要獲取 LOCK_active_mi 鎖，被用戶線程（stop slave）阻塞。

這次是備份線程、SQL 線程、用戶線程3個線程互相持有等待，形成死鎖。

這次并不是代碼bug，算是一個用法問題，因此我們在運維過程中，如果發(fā)現(xiàn) SQL 線程在 Waiting for commit lock，就不要 stop slave。

死鎖解決

如果不可避免出現(xiàn)了死鎖，該怎么解決呢？

通過上面的分析可以看到，不管是在 case 1 還是 case 2，備份線程和用戶線程都不再接受響應(yīng)了，要解決死鎖的話，只能 kill 掉 SQL 線程了，那么直接 kill 是否有風(fēng)險呢？

SQL 線程能執(zhí)行 Xid event，說明是在更新事務(wù)引擎表，kill 掉應(yīng)該沒問題（事務(wù)可以回滾，之后可以重做），但是5.6有這樣的一個bug，會導(dǎo)致SQL線程在等待 COMMIT 鎖的時候被kill，直接跳過事務(wù)，這樣備庫會比主庫少一個事務(wù)，因此 kill 后需要對比主備數(shù)據(jù)，把少的事務(wù)補上。

如果你使用的 MySQL 版本已經(jīng)修掉這個bug，也就是在 5.6.21 版本及之后，那么 kill SQL 線程是安全的。

死鎖重現(xiàn)

如果為了測試或研究代碼，要想復(fù)現(xiàn)死鎖該怎么辦呢？如果直接在備庫執(zhí)行一個 FTWRL，很可能是復(fù)現(xiàn)不了的，因為FTWRL是獲取2個鎖，全局讀鎖和全局 COMMIT 鎖，SQL 線程非常可能被全局讀鎖堵到（Waiting for global read lock），而不是被 COMMIT 鎖堵（Waiting for commit lock）。

一種方法是寫 testcase，用 dubug sync 功能設(shè)置同步點，讓線程停在指定的地方，但這要求 mysqld 跑在deubg模式下，并且要求有一定的MySQL 源碼開發(fā)基礎(chǔ)；
另一種方法是改代碼，延長do_commit的時間，比如 sleep 一段時間，這樣就給我們足夠的時間讓 FTWRL 在 SQL 線程請求 COMMIT 鎖前執(zhí)行完成，但是這需改代碼，然后重新編譯安裝；
如果我們不會用debug sync，又不想改代碼重新編譯安裝，就想在已有的環(huán)境測，改怎么辦呢？SYSTEMTAP!

systemtap 起初只支持在內(nèi)核空間進(jìn)行探測，0.6 版本之后可以在用戶空間進(jìn)行探測，使用 systemtap 需要程序中包含 debug 信息（程序編譯時加上 -g 選項）。

列出所有我們可以對 mysqld 進(jìn)行探測的地方。

sudo stap -L 'process("/usr/sbin/mysqld").function("*")'

列出所有可以對 Xid_log_event 類進(jìn)行探測的地方。

sudo stap -L 'process("/usr/sbin/mysqld").function("*Xid_log_event::*")'

如果我們想讓 Xid_log_event::do_commit 執(zhí)行有點延遲，可以這樣做：

sudo stap -v -g -d /usr/bin/mysqld --ldd -e 'probe process(16011).function("Xid_log_event::do_commit") { printf("got it\n")  mdelay(3000) }'

16011 是正在跑的備庫進(jìn)程PID，執(zhí)行上面的 stap 命令后，每當(dāng)備庫執(zhí)行到 Xid_log_event::do_commit 時，stap 就會打出個 “got it”，然后 SQL 線程暫停3s，這就給了我們充足的時間去執(zhí)行 FTWRL，在SQL線程 commit 前拿到 COMMIT 鎖。

轉(zhuǎn)自：http://www.kancloud.cn/taobaomysql/monthly/117960