关于死锁:故障分析-全局读锁一直没有释放发生了什么

64次阅读

共计 4240 个字符,预计需要花费 11 分钟才能阅读完成。

作者:刘开洋
爱可生交付服务部团队北京 DBA,次要负责解决 MySQL 的 troubleshooting 和我司自研数据库自动化治理平台 DMP 的日常运维问题,对数据库及周边技术有浓重的学习趣味,喜爱看书,谋求技术。
本文起源:原创投稿
* 爱可生开源社区出品,原创内容未经受权不得随便应用,转载请分割小编并注明起源。

问题:

在一个客户的线上监控告警中,提醒主从提早一直升高,咱们登上数据库进行查看一下,发现 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.ph…

https://bugs.mysql.com/file.p…

https://www.percona.com/blog/…

正文完
 0