MySQL Bug剖析之Slave節點並行複製死鎖
此文已由作者溫正湖授權網易雲社群釋出。
歡迎訪問網易雲社群，瞭解更多網易技術產品運營經驗。
有天一早，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演算法可以在網路安全中做什麼？