MySQL 物理备份死锁分析

410次阅读

共计 6919 个字符，预计需要花费 18 分钟才能阅读完成。

背景

本文对 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

可以看到 show slave status 被堵了很久，另外 SQL 线程在 Waiting for commit lock，说明在等待 COMMIT 锁。

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

依然是 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 锁。

本文永久更新链接地址 ：http://www.linuxidc.com/Linux/2016-08/134302.htm

正文完

星哥玩云-微信公众号