MySQL · 答疑解惑 · 物理备份死锁分析
最后更新于：2022-04-01 10:36:50
## 背景
本文对 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 锁。