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鎖詳情可以參考之前的月報。

死鎖分析

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 官方在這個  中修復。

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有這樣的一個，會導致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 起初只支援在核心空間進行探測，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 鎖。

轉自：