物理备份死锁分析

原文：http://mysql.taobao.org/monthly/2016/01/05/

背景

本文对 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 线程非常可能被全局读锁堵到（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 锁。