## 背景 本文对 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 锁。