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

背景

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

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

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

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

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

死鎖分析

CASE 1

我們先看一下死鎖時的現場是怎樣的：

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 鎖。

這時候如果我們再連接進去執行 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 看下相關線程的 backtrace，show slave status 線程的 backtrace 如下，非常明顯是在等mutex，對應代碼為 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進去，去調試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。

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

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

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

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

之后的 show slave status 都被堵，是因為在執行 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 中修復。

CASE 2

在上面的bug修復后，又出現了死鎖，但死鎖的情況卻不一樣，show processlist 結果如下：

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 ...

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

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

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

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

死鎖解決

如果不可避免出現了死鎖，該怎么解決呢？

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

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

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

死鎖重現

如果為了測試或研究代碼，要想復現死鎖該怎么辦呢？如果直接在備庫執行一個 FTWRL，很可能是復現不了的，因為FTWRL是獲取2個鎖，全局讀鎖和全局 COMMIT 鎖，SQL 線程非?？赡鼙蝗肿x鎖堵到（Waiting for global read lock），而不是被 COMMIT 鎖堵（Waiting for commit lock）。

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

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

列出所有我們可以對 mysqld 進行探測的地方。

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

列出所有可以對 Xid_log_event 類進行探測的地方。

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

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

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 是正在跑的備庫進程PID，執行上面的 stap 命令后，每當備庫執行到 Xid_log_event::do_commit 時，stap 就會打出個 “got it”，然后 SQL 線程暫停3s，這就給了我們充足的時間去執行 FTWRL，在SQL線程 commit 前拿到 COMMIT 鎖。

轉自：http://www.kancloud.cn/taobaomysql/monthly/117960