此文已由作者溫正湖授權網易雲社區發布。
歡迎訪問網易雲社區，了解更多網易技術產品運營經驗。
有天一早，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+款雲產品！
更多網易技術、產品、運營經驗分享請點擊。
相關文章：
【推薦】 當我們在談論multidex65535時，我們在談論什么
【推薦】 Vuex實踐
【推薦】 機器學習、深度學習、和AI算法可以在網絡安全中做什么？