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 實現分析](http://mysql.taobao.org/monthly/2015/11/04/ "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](http://gitlab.alibaba-inc.com/mysql-server/mysql-server/commit/f42e9f8fd2309e85f25ff0471eb5f7e397311b2a)?中修復。 ### 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](https://github.com/mysql/mysql-server/commit/c72d8f9565d95b3f763371edffd870ddc1268a54)，會導致SQL線程在等待 COMMIT 鎖的時候被kill，直接跳過事務，這樣備庫會比主庫少一個事務，因此 kill 后需要對比主備數據，把少的事務補上。如果你使用的 MySQL 版本已經修掉這個bug，也就是在 5.6.21 版本及之后，那么 kill SQL 線程是安全的。 ## 死鎖重現如果為了測試或研究代碼，要想復現死鎖該怎么辦呢？如果直接在備庫執行一個 FTWRL，很可能是復現不了的，因為FTWRL是獲取2個鎖，全局讀鎖和全局 COMMIT 鎖，SQL 線程非常可能被全局讀鎖堵到（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](https://sourceware.org/systemtap/ "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 鎖。