最新博客
最新资源下载
MySQL Bug剖析之Slave节点并行复制死锁
勿忘初心2018-10-19 18:30此文已由作者温正湖授权网易云社区发布。
欢迎访问网易云社区，了解更多网易技术产品运营经验。
有天一早，DBA同学就找上来了，说有个DDB集群下的RDS实例Slave节点（从库）死锁了，请求支援。说实话，一大早就遇到死锁这种棘手的问题，我的内心是奔溃的。不过万幸的是，DBA说这个实例还未正式上线，处于上线前压测阶段。这么一来，至少现场可以一直保持着。方便定位问题。那么，是什么问题呢，不卖关子，直接上图：
这是show processlist的结果。可以看到有一大坨的连接，基本上都是权限操作相关的语句，全都卡在“waiting for table level lock”上。还有几个复制管理操作，比如stop slave，也卡住了。这密密麻麻一大堆，看得都烦。还是得从这些连接里面挖掘出少数有用的信息。所以登上实例的mysql客户端捋下才是王道。先看看有没有锁相关的直接信息：
show engine innodb status\G ------------ TRANSACTIONS ------------ Trx id counter 6506046 Purge done for trx's n:o < 6506038 undo n:o < 0 state: running but idle History list length 2057 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421794207149728, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421794207150640, not started
里面根本就没有持锁相关的提示，而且事务全都处于not started状态。再看看InnoDB锁相关表：
mysql> select * from information_schema.INNODB_LOCK_WAITS; Empty set (0.00 sec) mysql> mysql> select * from information_schema.INNODB_LOCKS; Empty set (0.00 sec)
还是空空如也。既然这样，那直接看这些连接吧。理一理先后顺序，发现有3个连接是最早同时被卡主的：
| 284480 | system user | | dbn3 | Connect | 60771 | 0 | Waiting for table level lock | FLUSH PRIVILEGES | | 28 | rdsadmin | localhost | NULL | Query | 60771 | 0 | Waiting for table level lock | select count(distinct(User)) from mysql.user where Super_priv = 'Y' | | 284481 | system user | | dbn2 | Connect | 60771 | 0 | Waiting for preceding transaction to commit | GRANT SELECT ON *.* TO 'qs'@'10.122.170.%' IDENTIFIED WITH 'mysql_native_password' AS '*5B9E9DAAD2D1AD00E6D25C667B2E4EFD165CA560' |
有2个连接在等table lock，其中一个是用户连接，所做的事情是查询mysql.user表有super权限的账号，另一个连接，执行刷权限的操作。剩下的1个连接在等待前一个事务提交。其中第一个和第三个为system user。为了能够看到更具体的信息，我们进一步查询了performance_schema.threads表，得到如下结果：
mysql> select * from threads where THREAD_ID in (284481, 284480) order by PROCESSLIST_ID desc\G *************************** 1. row *************************** THREAD_ID: 284506 NAME: thread/sql/slave_worker TYPE: FOREGROUND PROCESSLIST_ID: 284481 PROCESSLIST_USER: rdsadmin PROCESSLIST_HOST: localhost PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Connect PROCESSLIST_TIME: 62124 PROCESSLIST_STATE: Waiting for preceding transaction to commit PROCESSLIST_INFO: GRANT SELECT ON *.* TO 'qs'@'10.122.170.%' IDENTIFIED WITH 'mysql_native_password' AS '*5B9E9DAAD2D1AD00E6D25C667B2E4EFD165CA560' PARENT_THREAD_ID: 284504 ROLE: NULL INSTRUMENTED: YES HISTORY: YES CONNECTION_TYPE: NULL THREAD_OS_ID: 7281 *************************** 2. row *************************** THREAD_ID: 284505 NAME: thread/sql/slave_worker TYPE: FOREGROUND PROCESSLIST_ID: 284480 PROCESSLIST_USER: rdsadmin PROCESSLIST_HOST: localhost PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Connect PROCESSLIST_TIME: 62124 PROCESSLIST_STATE: Waiting for table level lock PROCESSLIST_INFO: FLUSH PRIVILEGES PARENT_THREAD_ID: 284504 ROLE: NULL INSTRUMENTED: YES HISTORY: YES CONNECTION_TYPE: NULL THREAD_OS_ID: 7280 2 rows in set (0.00 sec)
可以发现这两个system user连接其实是MySQL Multi-Threads（多线程，MTS，或并行）复制的worker线程，他们共同的父进程（PARENT_THREAD_ID）是284504。我们再看下这个父进程在干嘛：
mysql> select * from threads where THREAD_ID in (284504) order by PROCESSLIST_ID desc\G *************************** 1. row *************************** THREAD_ID: 284504 NAME: thread/sql/slave_sql TYPE: FOREGROUND PROCESSLIST_ID: 284479 PROCESSLIST_USER: rdsadmin PROCESSLIST_HOST: localhost PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Connect PROCESSLIST_TIME: 62124 PROCESSLIST_STATE: Waiting for dependent transaction to commit PROCESSLIST_INFO: NULL PARENT_THREAD_ID: 282714 ROLE: NULL INSTRUMENTED: YES HISTORY: YES CONNECTION_TYPE: NULL THREAD_OS_ID: 7279 1 rows in set (0.00 sec)
该父进程即为多线程复制的sql线程，其所处的状态为"Waiting for dependent transaction to commit"，看代码可以发现，这个状态的意思是等待当前的Group提交后才能并行执行一下个Group的事务。我们知道InnoDB表是没有表锁的，而本例大量的连接在等表锁，根据其操作内容，可以基本确定是在等待mysql.user表的锁，该表是MyISAM表。grant to语句跟"FLUSH PRIVILEGES"语句肯定是互斥的。而flush语句状态为"Waiting for preceding transaction to commit"，这状态的意思是等待同一个Group中靠前的事务先完成提交。那么它的前一个事务是什么呢？其实不好判断。
google一直是定位问题的好帮手，在分析这个案例的同时，也没忘去google一把，发现了一个有点类似的案例http://dbaplus.cn/news-11-1874-1.html。但我们的案例中并没有Flush tables with read lock。仅有的用户连接是"select count(distinct(User)) from mysql.user where Super_priv = 'Y' ",这个连接无法起到FTWRL的作用。那么会不会是"FLUSH PRIVILEGES"呢？其实有一定的可能性。但假若真是如此，那么就是MySQL本身的一个Bug了，因为没有用户连接的参与，2个mysqld自身的worker线程就导致了死锁。那么如何确定就是这个"FLUSH PRIVILEGES"阻塞了grant to呢。根据从库执行到的Master Binlog位置，看下对应的Binlog信息即可。查询到的结果如下：
从图中我们可以发现，last_commited同为734263的Group有2个事务，分别是"FLUSH PRIVILEGES"和" GRANT SELECT ON *.* TO 'qs'@'10.122.170.%' IDENTIFIED WITH 'mysql_native_password' AS '*5B9E9DAAD2D1AD00E6D25C667B2E4EFD165CA560'"。其中sequence_number为734264的"FLUSH PRIVILEGES"在前，sequence_number为734265的grant语句在后。在开启并行（或多线程）复制的从库上。734265语句先得到执行，到了commit阶段，由于设置了slave_preserve_commit_order参数，导致734265需要等待734264先提交后才能提交。但由于这两个事务都需要更新mysql.user，且该表为MyISAM表，加锁粒度为表级（table level），这就使得734265需要等待734264先提交后才能提交，但734264需要等待734265提交后才会释放的mysql.user表锁，于是last_commited为734263的这个Group的2个事务无法正常完成。进一步导致作为并行复制的事务分发线程的sql线程一直无法给worker线程派发下一个Group（last_commited为734265）的事务。这就把整个Slave的复制锁死了。
到这里，需要交代一个DBA提供的背景："一开始是在ddb层,,去改用户密码,,来来回回改了几次,,,然后其中一个节点的内部从就出现了Waiting for table level lock ,,, 都是跟权限相关的"。我们结合Binlog信息可以进一步发现，上层至少在数据库dbn2、dbn3上分别同时执行了" GRANT SELECT ON *.* TO 'qs'@'10.122.170.%' IDENTIFIED WITH 'mysql_native_password' AS '*5B9E9DAAD2D1AD00E6D25C667B2E4EFD165CA560'"和"FLUSH PRIVILEGES"。由于这两个操作是都需要加mysql.user的表锁，所以实际执行时是互斥的，不存在并行提交的Group概念，或者说按照Group Commit机制，这两个操作是不会出现在同一个Group中的。
但为什么实际上却出现了呢，这是由于MySQL 5.7.3开始对group commit做了进一步优化，这里不做详细解释，感兴趣的同学可以看下这个参考文献（http://mysql.taobao.org/monthly/2016/08/01/）。
将该Bug上报给MySQL官方，得到了官方的开发同学的确认，并建了个bug（https://bugs.mysql.com/bug.php?id=89229）。该Bug对实际业务的影响很小，线上一般不会在多个数据库上并发执行赋权语句，而是由于是在从库上发生，即使出现了，也可以通过kill掉mysqld重新拉起解决该问题。此外，其实在执行" GRANT SELECT ON *.* TO 'qs'@'10.122.170.%' IDENTIFIED WITH 'mysql_native_password' AS '*5B9E9DAAD2D1AD00E6D25C667B2E4EFD165CA560'"后，并不需要执行"FLUSH PRIVILEGES"。grant to语句本身就会刷新权限信息。
网易云免费体验馆，0成本体验20+款云产品！
更多网易技术、产品、运营经验分享请点击。
相关文章：
【推荐】 邪恶的三位一体：机器学习、黑暗网络和网络犯罪
