一次詭異的線上資料庫的死鎖問題排查過程

前幾天，線上發生了一次資料庫死鎖問題，這一問題前前後後排查了比較久的時間，這個過程中自己也對資料庫的鎖機制有了更深的理解。本文總結了這次死鎖排查的全過程，並分析了導致死鎖的原因及解決方案。希望給大家提供一個死鎖的排查及解決思路。

本文涉及到MySql執行引擎、資料庫隔離級別、Innodb鎖機制、索引、資料庫事務等多領域知識。前車之鑒，後事之師，希望讀者們都可以有所收穫。

1

現象

某天晚上，同事正在釋出，突然線上大量報警，很多是關於資料庫死鎖的，報警提示資訊如下：

{“errorCode”:”SYSTEM_ERROR”,”errorMsg”:”nested exception is org.apache.ibatis.exceptions.PersistenceException: 
Error updating database. Cause: ERR-CODE: [TDDL-4614][ERR_EXECUTE_ON_MYSQL] 
Deadlock found when trying to get lock; 
The error occurred while setting parameters\n### SQL: 
update fund_transfer_stream set gmt_modified=now(),state = ? where fund_transfer_order_no = ? and seller_id = ? and state = ‘NEW’

透過報警，我們基本可以定位到發生死鎖的資料庫以及資料庫表。先來介紹下本文案例中涉及到的資料庫相關資訊。

2

背景情況

我們使用的資料庫是Mysql 5.7，引擎是InnoDB，事務隔離級別是READ-COMMITED。

資料庫版本查詢方法：

select version();

引擎查詢方法：

show create table fund_transfer_stream;

建表陳述句中會顯示儲存引擎資訊，形如：ENGINE=InnoDB

事務隔離級別查詢方法：

select @@tx_isolation;

事務隔離級別設定方法（只對當前Session生效）：

set session transaction isolation level read committed;

PS：註意，如果資料庫是分庫的，以上幾條SQL陳述句需要在單庫上執行，不要在邏輯庫執行。

發生死鎖的表結構及索引情況（隱去了部分無關欄位和索引）：

CREATE TABLE `fund_transfer_stream` ( 
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT COMMENT ‘主鍵’,
  `gmt_create` datetime NOT NULL COMMENT ‘建立時間’,
  `gmt_modified` datetime NOT NULL COMMENT ‘修改時間’, 
  `pay_scene_name` varchar(256) NOT NULL COMMENT ‘支付場景名稱’, 
  `pay_scene_version` varchar(256) DEFAULT NULL COMMENT ‘支付場景版本’,
  `identifier` varchar(256) NOT NULL COMMENT ‘唯一性標識’,
  `seller_id` varchar(64) NOT NULL COMMENT ‘賣家Id’,
  `state` varchar(64) DEFAULT NULL COMMENT ‘狀態’, `fund_transfer_order_no` varchar(256) 
  DEFAULT NULL COMMENT ‘資金平臺傳回的狀態’, 
  PRIMARY KEY (`id`),UNIQUE KEY `uk_scene_identifier` 
  (KEY `idx_seller` (`seller_id`),
  KEY `idx_seller_transNo` (`seller_id`,`fund_transfer_order_no`(20))
  ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COMMENT=‘資金流水’;

該資料庫共有三個索引，1個聚簇索引（主鍵索引），2個非聚簇索（非主鍵索引）引。

聚簇索引：

PRIMARY KEY (`id`)

非聚簇索引：

KEY `idx_seller` (`seller_id`),

KEY `idx_seller_transNo` (`seller_id`,`fund_transfer_order_no`(20))

以上兩個索引，其實idx_seller_transNo已經改寫到了idx_seller，由於歷史原因，因為該表以seller_id分表，所以是先有的idx_seller，後有的idx_seller_transNo

3

死鎖日誌

當資料庫發生死鎖時，可以透過以下命令獲取死鎖日誌：

show engine innodb status

發生死鎖，第一時間檢視死鎖日誌，得到死鎖日誌內容如下：

Transactions deadlock detected, dumping detailed information.
2019–03–19T21:44:23.516263+08:00 5877341 [Note] InnoDB: 

*** (1) TRANSACTION:
TRANSACTION 173268495, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 304 lock struct(s), heap size 41168, 6 row lock(s), undo log entries 1
MySQL thread id 5877358, OS thread handle 47356539049728, query id 557970181 11.183.244.150 fin_instant_app updating

update `fund_transfer_stream` set `gmt_modified` = NOW(), `state` = ‘PROCESSING’ where ((`state` = ‘NEW’) AND (`seller_id` = ‘38921111’) AND (`fund_transfer_order_no` = ‘99010015000805619031958363857’))
2019–03–19T21:44:23.516321+08:00 5877341 [Note] InnoDB: 

*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 173 page no 13726 n bits 248 index idx_seller_transNo of table `xxx`.`fund_transfer_stream` trx id 173268495 lock_mode X locks rec but not gap
Record lock, heap no 168 PHYSICAL RECORD: n_fields 3; compact format; info bits 0

2019–03–19T21:44:23.516565+08:00 5877341 [Note] InnoDB: 

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 173 page no 12416 n bits 128 index PRIMARY of table `xxx`.`fund_transfer_stream` trx id 173268495 lock_mode X locks rec but not gap waiting
Record lock, heap no 56 PHYSICAL RECORD: n_fields 17; compact format; info bits 0
2019–03–19T21:44:23.517793+08:00 5877341 [Note] InnoDB: 

*** (2) TRANSACTION:
TRANSACTION 173268500, ACTIVE 0 sec fetching rows, thread declared inside InnoDB 81
mysql tables in use 1, locked 1
302 lock struct(s), heap size 41168, 2 row lock(s), undo log entries 1
MySQL thread id 5877341, OS thread handle 47362313119488, query id 557970189 11.131.81.107 fin_instant_app updating

update `fund_transfer_stream_0056` set `gmt_modified` = NOW(), `state` = ‘PROCESSING’ where ((`state` = ‘NEW’) AND (`seller_id` = ‘38921111’) AND (`fund_transfer_order_no` = ‘99010015000805619031957477256’))
2019–03–19T21:44:23.517855+08:00 5877341 [Note] InnoDB: 

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 173 page no 12416 n bits 128 index PRIMARY of table `fin_instant_0003`.`fund_transfer_stream_0056` trx id 173268500 lock_mode X locks rec but not gap
Record lock, heap no 56 PHYSICAL RECORD: n_fields 17; compact format; info bits 0

2019–03–19T21:44:23.519053+08:00 5877341 [Note] InnoDB: 

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 173 page no 13726 n bits 248 index idx_seller_transNo of table `fin_instant_0003`.`fund_transfer_stream_0056` trx id 173268500 lock_mode X locks rec but not gap waiting
Record lock, heap no 168 PHYSICAL RECORD: n_fields 3; compact format; info bits 0

2019–03–19T21:44:23.519297+08:00 5877341 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (2)

簡單解讀一下死鎖日誌，可以得到以下資訊：

1、導致死鎖的兩條SQL陳述句分別是：

update `fund_transfer_stream_0056` 
set `gmt_modified` = NOW(), `state` = ‘PROCESSING’ 
where ((`state` = ‘NEW’) AND (`seller_id` = ‘38921111’) AND (`fund_transfer_order_no` = ‘99010015000805619031957477256’))

和

update `fund_transfer_stream_0056` 
set `gmt_modified` = NOW(), `state` = ‘PROCESSING’ 
where ((`state` = ‘NEW’) AND (`seller_id` = ‘38921111’) AND (`fund_transfer_order_no` = ‘99010015000805619031958363857’))

2、事務1，持有索引idx_seller_transNo的鎖，在等待獲取PRIMARY的鎖。

3、事務2，持有PRIMARY的鎖，在等待獲取idx_seller_transNo的鎖。

4、因事務1和事務2之間發生迴圈等待，故發生死鎖。

5、事務1和事務2當前持有的鎖均為：lock_mode X locks rec but not gap

兩個事務對記錄加的都是X 鎖，No Gap鎖，即對當行記錄加鎖(Record Lock)，並未加間隙鎖。

X鎖：排他鎖、又稱寫鎖。若事務T對資料物件A加上X鎖，事務T可以讀A也可以修改A，其他事務不能再對A加任何鎖，直到T釋放A上的鎖。這保證了其他事務在T釋放A上的鎖之前不能再讀取和修改A。

與之對應的是S鎖：共享鎖，又稱讀鎖，若事務T對資料物件A加上S鎖，則事務T可以讀A但不能修改A，其他事務只能再對A加S鎖，而不能加X鎖，直到T釋放A上的S鎖。這保證了其他事務可以讀A，但在T釋放A上的S鎖之前不能對A做任何修改。

Gap Lock：間隙鎖，鎖定一個範圍，但不包括記錄本身。GAP鎖的目的，是為了防止同一事務的兩次當前讀，出現幻讀的情況。

Next-Key Lock：1+2，鎖定一個範圍，並且鎖定記錄本身。對於行的查詢，都是採用該方法，主要目的是解決幻讀的問題。

4

問題排查

根據我們目前已知的資料庫相關資訊，以及死鎖的日誌，我們基本可以做一些簡單的判定。

首先，此次死鎖一定是和Gap鎖以及Next-Key Lock沒有關係的。因為我們的資料庫隔離級別是RC（READ-COMMITED）的，這種隔離級別是不會新增Gap鎖的。前面的死鎖日誌也提到這一點。

然後，就要翻程式碼了，看看我們的程式碼中事務到底是怎麼做的。核心程式碼及SQL如下：

@Transactional(rollbackFor = Exception.class)
public int doProcessing(String sellerId, Long id, String fundTransferOrderNo) {
    fundTreansferStreamDAO.updateFundStreamId(sellerId, id, fundTransferOrderNo);
    return fundTreansferStreamDAO.updateStatus(sellerId, fundTransferOrderNo,”PROCESSING”);
}

該程式碼的目的是先後修改同一條記錄的兩個不同欄位，updateFundStreamId SQL：

update fund_transfer_stream
        set gmt_modified=now(),fund_transfer_order_no = #{fundTransferOrderNo}
        where id = #{id} and seller_id = #{sellerId}

updateStatus SQL：

update fund_transfer_stream
    set gmt_modified=now(),state = #{state}
    where fund_transfer_order_no = #{fundTransferOrderNo} and seller_id = #{sellerId}
    and state = ‘NEW’

可以看到，我們的同一個事務中執行了兩條Update陳述句，這裡分別檢視下兩條SQL的執行計劃：

updateFundStreamId執行的時候使用到的是PRIMARY索引。

updateStatus執行的時候使用到的是idx_seller_transNo索引。

透過執行計劃，我們發現updateStatus其實是有兩個索引可以用的，執行的時候真正使用的是idx_seller_transNo索引。這是因為MySQL查詢最佳化器是基於代價（cost-based）的查詢方式。因此，在查詢過程中，最重要的一部分是根據查詢的SQL陳述句，依據多種索引，計算查詢需要的代價，從而選擇最優的索引方式生成查詢計劃。

我們查詢執行計劃是在死鎖發生之後做的，事後查詢的執行計劃和發生死鎖那一刻的索引使用情況並不一定相同的。但是，我們結合死鎖日誌，也可以定位到以上兩條SQL陳述句執行的時候使用到的索引。即updateFundStreamId執行的時候使用到的是PRIMARY索引，updateStatus執行的時候使用到的是idx_seller_transNo索引。

有了以上這些已知資訊，我們就可以開始排查死鎖原因及其背後的原理了。透過分析死鎖日誌，再結合我們的程式碼以及資料庫建表陳述句，我們發現主要問題出在我們的idx_seller_transNo索引上面：

 KEY `idx_seller_transNo` (`seller_id`,`fund_transfer_order_no`(20))

索引建立陳述句中，我們使用了字首索引，為了節約索引空間，提高索引效率，我們只選擇了fund_transfer_order_no欄位的前20位作為索引值。

因為fund_transfer_order_no只是普通索引，而非唯一性索引。又因為在一種特殊情況下，會有同一個使用者的兩個fund_transfer_order_no的前20位相同，這就導致兩條不同的記錄的索引值一樣（因為seller_id 和fund_transfer_order_no(20)都相同 ）。

就如本文中的例子，發生死鎖的兩條記錄的fund_transfer_order_no欄位的值：99010015000805619031958363857和99010015000805619031957477256 這兩個就是前20位相同的。

那麼為什麼fund_transfer_order_no的前20位相同會導致死鎖呢？

5

加鎖原理

我們就拿本次的案例來看一下MySql資料庫加鎖的原理是怎樣的，本文的死鎖背後又發生了什麼。

我們在資料庫上模擬死鎖場景，執行順序如下：

我們知道，在MySQL中，行級鎖並不是直接鎖記錄，而是鎖索引。索引分為主鍵索引和非主鍵索引兩種，如果一條sql陳述句操作了主鍵索引，MySQL就會鎖定這條主鍵索引；如果一條陳述句操作了非主鍵索引，MySQL會先鎖定該非主鍵索引，再鎖定相關的主鍵索引。

主鍵索引的葉子節點存的是整行資料。在InnoDB中，主鍵索引也被稱為聚簇索引（clustered index）

非主鍵索引的葉子節點的內容是主鍵的值，在InnoDB中，非主鍵索引也被稱為非聚簇索引（secondary index）

所以，本文的示例中涉及到的索引結構（索引是B+樹，簡化成表格了）如圖：

死鎖的發生與否，並不在於事務中有多少條SQL陳述句，死鎖的關鍵在於：兩個(或以上)的Session加鎖的順序不一致。那麼接下來就看下上面的例子中兩個事務的加鎖順序是怎樣的：

下圖是分解圖，每一條SQL執行的時候加鎖情況：

結合以上兩張圖，我們發現了導致死鎖的原因： 

事務1執行update1佔用PRIMARY = 1的鎖 ——> 事務2執行update1 佔有PRIMARY = 2的鎖； 

事務1執行update2佔有idx_seller_transNo = (3111095611，99010015000805619031)的鎖，嘗試佔有PRIMARY = 2鎖失敗（阻塞）；

事務2執行update2嘗試佔有idx_seller_transNo = (3111095611，99010015000805619031)的鎖失敗（死鎖）；

事務在以非主鍵索引為where條件進行Update的時候，會先對該非主鍵索引加鎖，然後再查詢該非主鍵索引對應的主鍵索引都有哪些，再對這些主鍵索引進行加鎖。）

6

解決方法

至此，我們分析清楚了導致死鎖的根本原理以及其背後的原理。那麼這個問題解決起來就不難了。

可以從兩方面入手，分別是修改索引和修改程式碼（包含SQL陳述句）。

修改索引：只要我們把字首索引 idx_seller_transNo中fund_transfer_order_no的字首長度修改下就可以了。比如改成50。即可避免死鎖。

但是，改了idx_seller_transNo的字首長度後，可以解決死鎖的前提條件是update陳述句真正執行的時候，會用到fund_transfer_order_no索引。如果MySQL查詢最佳化器在代價分析之後，決定使用索引 KEY idx_seller(seller_id)，那麼還是會存在死鎖問題。原理和本文類似。

所以，根本解決辦法就是改程式碼：

• 所有update都透過主鍵ID進行。

• 在同一個事務中，避免出現多條update陳述句修改同一條記錄。

7

總結與思考

在死鎖發生之後的一週內，我幾乎每天都會抽空研究一會，問題早早的就定位到了，修改方案也有了，但是其中原理一直沒搞清楚。

前前後後做過很多中種推斷及假設，又都被自己一次次推翻。最終還是要靠實踐來驗證自己的想法。於是我自己在本地安裝了資料庫，實戰的做了些測試，並實時檢視資料庫鎖情況。show engine innodb status ;可以檢視鎖情況。最終才搞清楚原理。

簡單說幾點思考：

1、遇到問題，不要猜！！！親手復現下問題，然後再來分析。

2、不要忽略背景關係！！！我剛開始就是隻關註死鎖日誌，一直忽略了程式碼中的事務其實還執行了另外一條SQL陳述句（updateFundStreamId）。

3、理論知識再充足，關鍵時刻不一定想的起來！！！

4、坑都是自己埋的！！！

參考資料： 

http://hedengcheng.com/?p=771

https://dev.mysql.com/doc/refman/5.7/en/innodb-transaction-isolation-levels.html

《MySql實戰45講》

https://www.hollischuang.com/archives/914