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

GitHub 1.8k Star 的Java工程師成神之路 ，不來了解一下嗎?

GitHub 1.8k Star 的Java工程師成神之路 ，真的不來了解一下嗎?

GitHub 1.8k Star 的Java工程師成神之路 ，真的肯定不來了解一下嗎?

現象

某天晚上，同事正在發佈，忽然線上大量報警，不少是關於數據庫死鎖的，報警提示信息以下：

{"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'
複製代碼

經過報警，咱們基本能夠定位到發生死鎖的數據庫以及數據庫表。先來介紹下本文案例中涉及到的數據庫相關信息。

背景狀況

咱們使用的數據庫是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

死鎖日誌

當數據庫發生死鎖時，能夠經過如下命令獲取死鎖日誌：

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)
複製代碼

簡單解讀一下死鎖日誌，能夠獲得如下信息：

一、致使死鎖的兩條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'))
複製代碼

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

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

四、因事務1和事務2之間發生循環等待，故發生死鎖。

同時，經過cloud DBA也能看到發生死鎖時資源佔有及等待狀況以下圖，和死鎖日誌中獲得的信息基本一致。

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

兩個事務對記錄加的都是X 鎖，No Gap鎖，即對當行記錄加鎖，併爲加間隙鎖。

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，鎖定一個範圍，而且鎖定記錄自己。對於行的查詢，都是採用該方法，主要目的是解決幻讀的問題。

詳見：www.cnblogs.com/zhoujinyi/p… 、 dev.mysql.com/doc/refman/…

問題排查

根據咱們目前已知的數據庫相關信息，以及死鎖的日誌，咱們基本能夠作一些簡單的斷定。

首先，這次死鎖必定是和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, FundTransferStreamState.PROCESSING.name());
}
複製代碼

該代碼的目的是前後修改同一條記錄的兩個不一樣字段，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位相同會致使死鎖呢？

加鎖原理

咱們就拿本次的案例來看一下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的時候，會先對該非主鍵索引加鎖，而後再查詢該非主鍵索引對應的主鍵索引都有哪些，再對這些主鍵索引進行加鎖。）

解決方法

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

能夠從兩方面入手，分別是修改索引和修改代碼（包含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語句修改同一條記錄。
複製代碼

總結與思考

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

前先後後作過不少中種推斷及假設，又都被本身一次次推翻。最終仍是要靠實踐來驗證本身的想法。因而我本身在本地安裝了數據庫，實戰的作了些測試，並實時查看數據庫鎖狀況。show engine innodb status ;能夠查看鎖狀況。最終才搞清楚原理。

簡單說幾點思考：

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

二、不要忽略上下文！！！我剛開始就是隻關注死鎖日誌，一直忽略了代碼中的事務其實還執行了另一條SQL語句（updateFundStreamId）。

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

四、坑都是本身埋的！！！

有道無術，術可成；有術無道，止於道；歡迎關注【Java之道】公衆號，一塊兒以道御術，以術識道；

參考資料： MySQL 加鎖處理分析

innodb 事務隔離級別

《MySql實戰45講》

MySQL中的行級鎖,表級鎖,頁級鎖