一條從未見過的報警，開啟曲折的MySQL死鎖排查

作者：佚名 2021-03-02 10:11:13

從日志的字面意思來看，顯然，是MySQL數據庫在執行事務時，發現了死鎖的情況，那么這種死鎖是如何產生的，背后又潛藏著怎樣的隱患，又該如何去解決呢，我們一起來排查一下。

故障背景

國慶期間，收到一條從未見過的報警，后面間歇性地又報出類似的偶現報警，便忽然來了興致，摘了其中一條，探究一下其中的故事。

*** (1) TRANSACTION:  
TRANSACTION 6286508066, ACTIVE 0 sec updating or deleting  
mysql tables in use 1, locked 1  
LOCK WAIT 9 lock struct(s), heap size 1136, 14 row lock(s), undo log entries 1  
MySQL thread id 189619143, OS thread handle 140619931252480, query id 1148803196 10.200.18.103 ke_information updating  
update `user_feed_26` set `notification` = 1, `mtime` = '2020-10-03 09:11:11' where `user_id` = 2000000126212250 and `action` in ('resblock_weekly', 'bizcircle_weekly', 'district_weekly') and `notification` = 0 
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:  
RECORD LOCKS space id 2229 page no 263938 n bits 264 index idx_user_id of table `lianjia_user_feed`.`user_feed_26` trx id 6286508066 lock_mode X locks gap before rec insert intention waiting 
Record lock, heap no 93 PHYSICAL RECORD: n_fields 5; compact format; info bits 0  
 0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
 1: len 14; hex 6f6e5f7368656c665f616761696e; asc on_shelf_again;;  
 2: len 1; hex 81; asc  ;;  
 3: len 12; hex 313034313033373433363737; asc 104103743677;;  
 4: len 4; hex 95f12ab5; asc   * ;;

從日志的字面意思來看，顯然，是MySQL數據庫在執行事務時，發現了死鎖的情況，那么這種死鎖是如何產生的，背后又潛藏著怎樣的隱患，又該如何去解決呢，我們一起來排查一下~

排查過程

霧里看花

剛開始收到這個報警，第一反應，是有不同事務互相鎖，結果產生了死鎖。那么壞了，十有八九是某個代碼片段里寫的邏輯出了問題。但是排查了一整圈，涉及到這個sql的代碼，既沒有開啟事務，更沒有多個事務，那么代碼的bug基本上就可以排除了。

那么這些個事務是怎么來的呢？眾所周知，MySQL的事務支持與存儲引擎有關，MyISAM不支持事務，INNODB支持事務，更新時采用的是行級鎖。由于我們的數據庫采用的是INNODB引擎，意味著，會將update語句當做一個事務來處理。那難道是更新同一條數據，出現的沖突嗎？于是找DBA同學要來了死鎖日志（數據庫版本：5.7.24 事務隔離級別為RR）。

事務一日志：

*** (1) TRANSACTION:  
TRANSACTION 6286508066, ACTIVE 0 sec updating or deleting  
mysql tables in use 1, locked 1  
LOCK WAIT 9 lock struct(s), heap size 1136, 14 row lock(s), undo log entries 1  
MySQL thread id 189619143, OS thread handle 140619931252480, query id 1148803196 10.200.18.103 ke_information updating  
update `user_feed_26` set `notification` = 1, `mtime` = '2020-10-03 09:11:11' where `user_id` = 2000000126212250 and `action` in ('resblock_weekly', 'bizcircle_weekly', 'district_weekly') and `notification` = 0 
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:  
RECORD LOCKS space id 2229 page no 263938 n bits 264 index idx_user_id of table `lianjia_user_feed`.`user_feed_26` trx id 6286508066 lock_mode X locks gap before rec insert intention waiting 
Record lock, heap no 93 PHYSICAL RECORD: n_fields 5; compact format; info bits 0  
 0: len 8; hex 80071afd5112d89a; asc     Q   ;; 
 1: len 14; hex 6f6e5f7368656c665f616761696e; asc on_shelf_again;; 
 2: len 1; hex 81; asc  ;;  
 3: len 12; hex 313034313033373433363737; asc 104103743677;;  
 4: len 4; hex 95f12ab5; asc   * ;;

由日志可以看出，事務一執行的sql語句是：

update `user_feed_26` set `notification` = 1, `mtime` = '2020-10-03 09:11:11' where `user_id` = 2000000126212250 and `action` in ('resblock_weekly', 'bizcircle_weekly', 'district_weekly') and `notification` = 0

在等待的鎖是：

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:  
ECORD LOCKS space id 2229 page no 263938 n bits 264 index idx_user_id of table `lianjia_user_feed`.`user_feed_26` trx id 6286508066 lock_mode X locks gap before rec insert intention waiting

這里顯示的是事務在等待什么鎖。RECORD LOCKS 表示記錄鎖，并且可以看出要加鎖的索引為idx_user_id，space id為2229，page no為263938，lock_mode X 標識該記錄鎖為排它鎖，insert intention waiting 表示要加的鎖為插入意向鎖，并處于鎖等待狀態。

Record lock, heap no 93 PHYSICAL RECORD: n_fields 5; compact format; info bits 0  
0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
1: len 14; hex 6f6e5f7368656c665f616761696e; asc on_shelf_again;;  
2: len 1; hex 81; asc  ;;  
3: len 12; hex 313034313033373433363737; asc 104103743677;;  
4: len 4; hex 95f12ab5; asc   * ;;

結合索引信息第二行 on_shelf_again 可以知道，這行鎖的 action 字段是 on_shelf_again ;

事務二日志：

 *** (2) TRANSACTION:  
TRANSACTION 6286508067, ACTIVE 0 sec updating or deleting, thread declared inside InnoDB 4980  
mysql tables in use 1, locked 1  
12 lock struct(s), heap size 1136, 22 row lock(s), undo log entries 3  
MySQL thread id 189619144, OS thread handle 140620050204416, query id 1148803197 10.200.17.37 pt_user updating  
UPDATE `user_feed_26` SET  `notification` = '1' , `mtime` = '2020-10-03 09:11:11'  WHERE `user_id` = '2000000126212250'  AND `action` in ( 'deal','price_changed','ting_shou','house_new_picture','house_new_vr','price_changed_rise','on_shelf_again')  AND `notification` = '0' 
*** (2) HOLDS THE LOCK(S):  
RECORD LOCKS space id 2229 page no 263938 n bits 264 index idx_user_id of table `lianjia_user_feed`.`user_feed_26` trx id 6286508067 lock_mode X locks gap before rec 
Record lock, heap no 83 PHYSICAL RECORD: n_fields 5; compact format; info bits 0  
 0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
 1: len 4; hex 6465616c; asc deal;; 
 2: len 1; hex 81; asc  ;;  
 3: len 12; hex 313034313032363731333238; asc 104102671328;;  
 4: len 4; hex 95e14632; asc   F2;;  
Record lock, heap no 93 PHYSICAL RECORD: n_fields 5; compact format; info bits 0  
 0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
 1: len 14; hex 6f6e5f7368656c665f616761696e; asc on_shelf_again;;  
 2: len 1; hex 81; asc  ;;  
 3: len 12; hex 313034313033373433363737; asc 104103743677;;  
 4: len 4; hex 95f12ab5; asc   * ;;  
*** 省略……  
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:  
RECORD LOCKS space id 2229 page no 263938 n bits 264 index idx_user_id of table `lianjia_user_feed`.`user_feed_26` trx id 6286508067 lock_mode X locks gap before rec insert intention waiting 
Record lock, heap no 87 PHYSICAL RECORD: n_fields 5; compact format; info bits 32  
 0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
 1: len 15; hex 64697374726963745f7765656b6c79; asc district_weekly;;  
 2: len 1; hex 80; asc  ;;  
 3: len 8; hex 3233303038373831; asc 23008781;;  
 4: len 4; hex 95f63035; asc   05;;

事務二的日志，相比于事務一多了持有鎖的信息：

 *** (2) HOLDS THE LOCK(S):  
RECORD LOCKS space id 2229 page no 263938 n bits 264 index idx_user_id of table `lianjia_user_feed`.`user_feed_26` trx id 6286508067 lock_mode X locks gap before rec 
Record lock, heap no 83 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 
 0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
 1: len 4; hex 6465616c; asc deal;;  
 2: len 1; hex 81; asc  ;;  
 3: len 12; hex 313034313032363731333238; asc 104102671328;;  
 4: len 4; hex 95e14632; asc   F2;;  
Record lock, heap no 93 PHYSICAL RECORD: n_fields 5; compact format; info bits 0  
 0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
 1: len 14; hex 6f6e5f7368656c665f616761696e; asc on_shelf_again;;  
 2: len 1; hex 81; asc  ;;  
 3: len 12; hex 313034313033373433363737; asc 104103743677;;  
 4: len 4; hex 95f12ab5; asc   * ;;  
*** 省略……

從日志看，事務二持有一個記錄鎖，RECORD LOCKS這是個記錄鎖，space id為2229，page no為263938 并且通過索引信息可以看出，事務二恰好持有事務一需要的那行記錄鎖，即：

Record lock, heap no 93 PHYSICAL RECORD: n_fields 5; compact format; info bits 0  
 0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
 1: len 14; hex 6f6e5f7368656c665f616761696e; asc on_shelf_again;;  
 2: len 1; hex 81; asc  ;;  
 3: len 12; hex 313034313033373433363737; asc 104103743677;;  
 4: len 4; hex 95f12ab5; asc   * ;;  
lock_mode X locks gap before rec 表示這是一個排他鎖，并且是一個間隙鎖  
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:  
RECORD LOCKS space id 2229 page no 263938 n bits 264 index idx_user_id of table `lianjia_user_feed`.`user_feed_26` trx id 6286508067 lock_mode X locks gap before rec insert intention waiting 
Record lock, heap no 87 PHYSICAL RECORD: n_fields 5; compact format; info bits 32  
 0: len 8; hex 80071afd5112d89a; asc     Q   ;;  
 1: len 15; hex 64697374726963745f7765656b6c79; asc district_weekly;;  
 2: len 1; hex 80; asc  ;;  
 3: len 8; hex 3233303038373831; asc 23008781;;  
 4: len 4; hex 95f63035; asc   05;;

同樣，這里顯示的是事務二在等待什么鎖。RECORD LOCKS 表示記錄鎖，并且可以看出要加鎖的索引為idx_user_id，space id為2229，page no為263938 lock_mode X 標識該記錄鎖為排它鎖，insert intention waiting 表示要加的鎖為插入意向鎖，并處于鎖等待狀態。雖然，事務一的日志中沒有標明它持有了哪些鎖，但是結合事務二等待的鎖結構中 district_weekly 字段來看，事務一是持有該鎖的，因此，兩個事務形成了互相等待鎖釋放的場景，從而形成了死鎖。

那么疑問來了，兩個sql：

# sql1:  
update `user_feed_26` set `notification` = 1, `mtime` = '2020-10-03 09:11:11' where `user_id` = 2000000126212250 and `action` in ('resblock_weekly', 'bizcircle_weekly', 'district_weekly') and `notification` = 0 
# sql2:  
UPDATE `user_feed_26` SET  `notification` = '1' , `mtime` = '2020-10-03 09:11:11'  WHERE `user_id` = '2000000126212250'  AND `action` in ( 'deal','price_changed','ting_shou','house_new_picture','house_new_vr','price_changed_rise','on_shelf_again')  AND `notification` = '0'

明明兩個語句的where條件不一樣，也不交叉，為什么會占用彼此的鎖呢？

山窮水復

為了驗證這種case，我們在線下嘗試進行復現。表結構如下：

#CREATE TABLE `user_feed_26` (  
  `feed_id` int(10) NOT NULL AUTO_INCREMENT,  
  `user_id` bigint(20) NOT NULL,  
……  
  PRIMARY KEY (`feed_id`),  
  KEY `idx_user_id` (`user_id`,`action`,`notification`,`feed_target`),  
…… 
) ENGINE=InnoDB AUTO_INCREMENT=371826027 DEFAULT CHARSET=utf8 COMMENT='用戶推送表';

但是無論如何，都是鎖等待，而不會形成死鎖。這是怎么回事呢？

帶著懷疑的態度，我們查看了一下語句的執行計劃：

通過執行計劃我們發現，這里并沒有走死鎖日志里出現的那個idx_user_id索引，而是走的主鍵索引，因此并沒有產生死鎖。

大膽猜測：是因為模擬的數據量太小，導致并沒有走復合索引。

于是，我們往線下模擬庫里灌入了大概100w左右的隨機數據，再次查看執行計劃：

果然，當數據量變大之后，就會走對應的復合索引了。再經過一次嘗試，果然復現出了線上那種死鎖場景，但是問題來了，為什么會出現這種情況呢？

柳暗花明

為了了解背后真實的原理，我們再次研讀了MySQL鎖相關的資料，也得知了事情的真相。

首先，簡單說一下MySQL加鎖的基本原則：

原則 1：加鎖的基本單位是 next-key lock。next-key lock 是前開后閉區間；
原則 2：查找過程中訪問到的對象才會加鎖。

優化 1：唯一索引上的等值查詢加鎖時，next-key lock 退化為行鎖。

優化 2：非唯一索引上的等值查詢加鎖時，對where條件中的值所在區間向右（后）遍歷時，該區間的右邊界不滿足等值條件的時候，next-key lock 退化為間隙鎖。這個比較難理解，舉個例子：

若在表ta的列a上有非唯一索引：index_a,該索引中存在的值為：1，1，3，3，7，9：當你執行select a from ta where ta.a=5時，就會從3開始往右（后）遍歷，此時對應的是(3,7]但是由于該區間的最后一個值7不滿足=5的條件，因此該next-key lock就退化為gap lock (3,7)。

由此可知，當我們執行的update語句，在查詢的時候，給對應的索引idx_user_id加上了間隙鎖，從而互相之間產生了死鎖。舉個簡單的例子說明一下：

事務2執行了一個update, where 條件為3，因此獲得了（1，3）的Gap鎖；
事務1也執行了一個update，where條件為5，因此獲得了一個（5，+∞），同時等待（1，7）插入意向鎖；
事務2又執行了一個update，where條件為8，那么他將等待（5，+∞）。

于是乎，死鎖就產生了。

那么，如何避免這種死鎖再次發生呢？

通過唯一索引（一般主鍵都是）來更新，先通過select語句查出符合條件的記錄的唯一索引，再通過唯一索引來更新。

select id from table where a=? and b=?;  
update table set column=xxx where idid= id;

避免在同一時間點運行多個對同一表進行讀寫的腳本，特別注意加鎖且操作數據量比較大的語句；我們經常會有一些定時腳本，避免它們在同一時間點運行；如本次事件所示，Gap 鎖往往是程序中導致死鎖的真兇，由于默認情況下 MySQL 的隔離級別是 RR，所以如果能確定幻讀和不可重復讀對應用的影響不大，可以考慮將隔離級別改成 RC，可以避免 Gap 鎖導致的死鎖。

責任編輯：龐桂玉來源： DBAplus社群

MySQL 死鎖數據庫