关键字：数据库分布式架构、数据库复制、数据库容灾

问题：

在一个客户的线上监控告警中，提示主从延迟不断升高，我们登上数据库进行查看一下，发现 MySQL 从库复制状态提示 SQL 线程在 waiting for global read lock。

请点击输入图片描述

在数据库的进程列表中发现了存在的等待全局读锁和 kill slave 的进程；高可用在不断重启复制，原因是由于 NAT 网络中域名反解析出错导致高可用软件对复制的误判。

请点击输入图片描述

这里就能看出两个问题，第一是有个下发全局读锁的对象，一般在从库上就是备份工具了，第二就是 slave 正在被 kill，而且时间相当长，因此这里可能存在一种特殊的死锁。

查看 mysql 进程时的巧合下，发现 mysqldump 进程已存在 10 多个小时，对比等 FTWRL 的进程的时间，就坐实了下发全局读锁的对象是 mysqldump：

请点击输入图片描述

线上没有开启 performance_schema 的 instruments 和 consumers（PS：这个对于锁监控很重要，一定记得打开）。如果开启了 performance_schema，可以通过 metadata_locks 查到相关锁记录，这个我们在后面的复现中看一下。

请点击输入图片描述

上述情况分析得出存在一个特殊的死锁，形成 MySQL Server 层和存储引擎层的死锁闭环，而且不能完全追踪到所有锁记录。

解决：

这样三个锁组合成的死锁在其他客户端执行 UNLOCKS TABLE 是解不开的，只需要 kill 掉全局读锁或者等待全局锁的锁一个即可，因为没有找到全局锁对应的线程，这里将等全局锁的线程 kill 掉，数据库就恢复了，再看残留的 mysqldump 进程消失了：

请点击输入图片描述

两个锁就此解开了

请点击输入图片描述

故障恢复，延迟追平。

Review：为什么 stop slave 和 FTWRL 会发生死锁？

在 mysql 5.7.26 中执行 mysqldump 加参数 master_data、single_transaction 和 flush_logs 得出的 general log 中发现

mysqldump执行的general log
root@127.0.0.1 on  using TCP/IP
/*!40100 SET @@SQL_MODE='' */
/*!40103 SET TIME_ZONE='+00:00' */
FLUSH /*!40101 LOCAL */ TABLES
FLUSH TABLES WITH READ LOCK                                       # 加全局读锁
Refresh                                                           # 刷新日志
  
SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ           # 设置设置会话级别RR
START TRANSACTION /*!40100 WITH CONSISTENT SNAPSHOT */          
SHOW MASTER STATUS                                                # 获取master的状态
UNLOCK TABLES                                                     # 解锁表
···
Quit

场景复现：

请点击输入图片描述

（图片建议点开放大看）

[root@localhost ~]# gdb -ex "set pagination 0" -ex "thread apply all bt" --batch -p 13192   # 打印对应MySQL进程堆栈——找到stop slave卡住的线程后处理输出
······
Thread 23 (Thread 0x7f98f027e700 (LWP 19446)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 ()
#1  native_cond_timedwait
#2  my_cond_timedwait
#3  inline_mysql_cond_timedwait
#4  terminate_slave_thread (thd=0x7f98740008c0, term_lock=0x7f9884022908, term_cond=0x7f9884022a08, slave_running=0x7f9884022ac4, stop_wait_timeout=0x7f98f027c448, need_lock_term=false) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/sql/rpl_slave.cc:1861
#5  terminate_slave_threads (mi=0x7f988401c500, thread_mask=3, stop_wait_timeout=<optimized out>, need_lock_term=false) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/sql/rpl_slave.cc:1671
#6  stop_slave (thd=0x7f987c00f650, mi=0x7f988401c500, net_report=true, for_one_channel=false, push_temp_tables_warning=0x7f98f027c52f) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/sql/rpl_slave.cc:10261
#7  stop_slave (thd=0x7f987c00f650) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/sql/rpl_slave.cc:615
#8  stop_slave_cmd
#9  mysql_execute_command
#10 mysql_parse
#11 dispatch_command
#12 do_command
#13 handle_connection
#14 pfs_spawn_thread
#15 start_thread ()
#16n clone ()
  
# 可以看到# 5 stop_wait_timeout，获取更多相关信息
(gdb) thread 34
[Switching to thread 34 (Thread 0x7f58d661f700 (LWP 13240))]
#0  0x00007f592d8e0d42 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
(gdb) f 5
#5  0x0000000000f0ed57 in terminate_slave_threads (mi=0x7f587801f050, thread_mask=3, stop_wait_timeout=<optimized out>, need_lock_term=false)
    at /export/home/pb2/build/sb_0-32013917-1545390211.74/mysql-5.7.26/sql/rpl_slave.cc:1671
warning: Source file is more recent than executable.
1671        if ((error=terminate_slave_thread(mi->rli->info_thd, sql_lock,
(gdb) print mi->rli->info_thd
$1 = (THD *) 0x7f58700008c0
 
  
Thread 21 (Thread 0x7f58c05a6700 (LWP 14238)):
#9  apply_event_and_update_pos (ptr_ev=0x7f58c05a56c8, thd=0x7f58700008c0, rli=0x7f5878024b30)
#10 exec_relay_log_event (thd=0x7f58700008c0, rli=0x7f5878024b30)
  
# 通过gdb输出看到stop slave持有mi->rli->info_thd,在等待当前会话地址为0x7f58700008c0，定位到线程21的apply_event_and_update_pos 和exec_relay_log_event函数执行
apply_event_and_update_pos：应用给定事件并提高relay log的位置。
exec_relay_log_event：这是从SQL线程调用于执行relay log中下一个事件的顶级功能。
mi=master info, rli=relay log info

请点击输入图片描述

请点击输入图片描述

terminate_slave_thread 函数：等 SQL thread 终止的函数。该函数在请求线程终止后被调用（通过将 Relay_log_info 或 Master_info 配置中的 abort_slave 设置为 1），线程的终止由 *slave_running 控制。函数将在等待条件之前获取 term_lock，need_lock_term 为 false 的情况下，mutex 应该属于这个函数的调用者，在函数返回之后一直保持获取 mutex 的状态。

请点击输入图片描述

mysqldump 备份期间出现的操作是：

• master-data=2 会结合 single-transaction 给数据库加一个全局读锁。

• flush-logs 是要对 relay log 进行 refresh。

STOP SLAVE 在备份期间做的操作是：

• STOP SLAVE 会等待 IO 线程结束，然后释放 LOCK_msp_map 和占有的 master_info

流程：

• mysqldump 备份进行 FTWRL 之后恰巧遇到 HA 执行 STOP SLAVE，SQL Thread 在 STOP 之前持有 mi->stop_cond 锁，commit 的时候等待 MDL_COMMIT，FTWRL 之后执行的 flush logs 时 reflresh 下发了一个系统锁，它是在等待 mi->stop_cond 的释放，因为 FTWRL 和 FLUSH LOGS 是一个程序发出的，所有从逻辑上讲 mysqldump 自己是在等待自己释放资源，便陷入了无限等待中，形成了我们看到的死锁。

关于 LOCK_msp_map 锁有兴趣的同学可以自行谷歌搜索

参考：

https://bugs.mysql.com/bug.php?id=70307

https://bugs.mysql.com/file.php?id=20542&bug_id=70307

https://www.percona.com/blog/2012/03/23/how-flush-tables-with-read-lock-works-with-innodb-tables/

关键字：数据库分布式架构、数据库复制、数据库容灾