作者：李錫超
一個愛笑的江蘇蘇寧銀行 資料庫工程師，主要負責資料庫日常運維、自動化建設、DMP平臺運維。擅長MySQL、Python、Oracle，愛好騎行、研究技術。
本文來源：原創投稿
*愛可生開源社群出品，原創內容未經授權不得隨意使用，轉載請聯絡小編並註明來源。
一、前言
死鎖，作為資料庫一個常見的併發問題。此類問題：
1.觸發原因往往與應用的邏輯相關，參與的事務可能是兩個、三個、甚至更多；
2.由於不同資料庫的鎖實現機制幾乎完全不同、實現邏輯複雜，還存在多種鎖型別；
3.資料庫發生死鎖後，會立即終止部分事務，事後無法看到死鎖前的等待狀態。
即，死鎖問題具有業務關聯、機制複雜、型別多樣等特點，導致當資料庫發生死鎖問題時，不是那麼容易分析。
基於解決死鎖問題存在的難點，本文以MySQL資料庫一則併發Insert導致的死鎖為例，從發現問題、重現問題、根因分析、解決問題4個步驟，期望能提供一套關於死鎖的科學有效方案，供讀者朋友參考。
二、問題現象
某系統在進行上線前壓測時，發現應用日誌存在如下日誌提示觸發死鎖問題：
Deadlock found when trying to get lock; try restarting transaction好在壓測時，就發現了問題，避免上線後影響生產。
隨後，執行 show engine innodb status，有如下內容（脫敏後）：
------------------------
LATEST DETECTED DEADLOCK
------------------------
2023-03-24 19:07:50 140736694093568
*** (1) TRANSACTION:
TRANSACTION 56118, ACTIVE 6 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1192, 1 row lock(s), undo log entries 1
MySQL thread id 9, OS thread handle 140736685700864, query id 57 localhost root update
insert into dl_tab(id,name) values(30,10)
*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 11 page no 5 n bits 72 index ua of table `testdb`.`dl_tab` trx id 56118 lock mode S waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000a; asc ;; # 十進位制: 10
1: len 4; hex 8000001a; asc ;; # 十進位制: 26
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 11 page no 5 n bits 72 index ua of table `testdb`.`dl_tab` trx id 56118 lock mode S waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000a; asc ;; # 十進位制: 10
1: len 4; hex 8000001a; asc ;; # 十進位制: 26
*** (2) TRANSACTION:
TRANSACTION 56113, ACTIVE 12 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1192, 2 row lock(s), undo log entries 2
MySQL thread id 8, OS thread handle 140736952903424, query id 58 localhost root update
insert into dl_tab(id,name) values(40,8)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 11 page no 5 n bits 72 index ua of table `testdb`.`dl_tab` trx id 56113 lock_mode X locks rec but not gap
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000a; asc ;; # 十進位制: 10
1: len 4; hex 8000001a; asc ;; # 十進位制: 26
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 11 page no 5 n bits 72 index ua of table `testdb`.`dl_tab` trx id 56113 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 8000000a; asc ;; # 十進位制: 10
1: len 4; hex 8000001a; asc ;; # 十進位制: 26
*** WE ROLL BACK TRANSACTION (1)
------------1、死鎖資訊梳理
根據以上資訊，發現是 dl_tab 執行insert操作導致死鎖。初步梳理如下。
版本: 8.0.27
隔離級別: Read-Commited
表結構:
*************************** 1. row ***************************
Table: dl_tab
Create Table: CREATE TABLE `dl_tab` (
`id` int NOT NULL AUTO_INCREMENT,
`name` int NOT NULL,
PRIMARY KEY (`id`),
UNIQUE KEY `ua` (`name`)
) ENGINE=InnoDB AUTO_INCREMENT=41 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci注意，以上innodb status 輸出，不同的資料庫版本會有差異。主要有:
A.在MySQL 8.0.18及之後，輸出結果包括兩個事務各自持有的鎖、等待的鎖，對分析死鎖問題很有幫助。在 8.0.18之前，只包括事務1等待的鎖，事務2持有的鎖、等待的鎖，而不包括事務1持有的鎖資訊；
B.以上示例還包括具體的索引記錄值（如{10,26}：第一欄位為索引記錄的值，第二個欄位為對應的主鍵記錄）。如果沒有索引記錄值，可能只有heap no，該編號作為內部實現鎖機制非常關鍵，但無法和具體的索引記錄對應起來。此外，找了其它幾個MySQL版本發現原生版本≥5.7.21 、≥8.0有這個功能，Percona mysql 5.7.21 居然沒有這個功能；
C.事務T1 等待的鎖從輸出結果看到的是 LOCK S, 但其實獲取的鎖是 lock s next key lock, 這點從後面的原始碼分析結果中會進一步說明。
innodb status 日誌梳理：
從以上innodb status輸出。可以看到死鎖發生在唯一索引 ua 上。這的確也是在RC隔離級別配置下，比較常見的死鎖場景。進一步梳理死鎖過程:
A.首先事務T1獲取到了ua中記錄10的 lock x,rec not not gap 鎖
B.事務T2嘗試獲取ua中記錄10的lock s, next key lock，由於T1持有了記錄的獨佔鎖，因此被T1堵塞
C.事務T1嘗試獲取ua中記錄10的lock x, gap before rec,insert intention，但被堵塞
2、提出問題
除了以上現象外，無法從輸出結果得到更多的資訊，比如：
Q1: T1為什麼會持有 ua中記錄10 的鎖？
Q2: T1既然持有了鎖，為什麼又會等待鎖？
Q3: T2持有和等待相同的鎖，到底是持有還是在等待？
Q4: 死鎖到底是如何產生的？
為此，與研發同學溝通，瞭解死鎖發生的業務場景，並對問題進行了再次復現。
三、重現問題
研發同學發現是在某業務的定時任務進行併發處理時觸發，並很快在對應的開發環境復現了問題。問題復現後，同樣在應用日誌和innodb status輸出看到對應日誌，確認是同一問題。
建議讀者朋友思考1分鐘，如何進一步分析
1、嘗試解決
本著解決問題優先的原則，在唯一索引ua併發時產生的，那是否可以將唯一索引改為普通索引？如果不可以，是否可以降低併發（或者直接改為單併發）？不過很快研發同學就進行了確認，uname的唯一索引是核心框架依賴的，改不了！該功能的實時性要求很高，上線後業務量比較大，不能降低或調小併發。既然無法避免，那隻能進一步分析死鎖發生的原因，並據此確認解決方案！
研發在復現問題後，除了能看到應用日誌和innodb status輸出，還是沒有更多的資訊。此外，研發是參考測試環境，造了一批資料，然後進行模擬復現的。即: 雖然能復現這個死鎖，但無法回答最初提出的問題（Q1,Q2,Q3,Q4）。
2、跟蹤死鎖發生過程
隨後找到Percona提供一篇文章（連結: How to deal with MySQL deadlocks），大致對死鎖的問題的分析提供了思路:以應用日誌和innodb status提供的資料為基礎，結合events_statements_history、binlog(最好是statement格式)、 慢查詢日誌（slow log）、一般日誌（general log）進行分析。
根據文章利用已有的功能(events_statements_history/slow log/general log)，去找到資料庫連線執行過那些SQL語句。隨後，總結了如下指令碼：
-- 將events_statements_history 中的啟動時間轉換為標準時間
create database IF NOT EXISTS perf_db;
use perf_db;
DELIMITER //
create function f_convert_timer_to_utc(pi_timer bigint) returns timestamp(6)
DETERMINISTIC
begin
declare value_utc_time timestamp(6);
select FROM_UNIXTIME( (unix_timestamp(sysdate()) - variable_value) + pi_timer/1000000000000 ) from performance_schema.global_status where variable_name = 'Uptime' into value_utc_time;
return value_utc_time;
end;
//
DELIMITER ;
--innodb status 輸出中，死鎖資訊中MySQL thread id，實際表示是PROCESSLIST ID。執行語句找到thread_id 與PROCESSLIST_ID的對應關係
select PROCESSLIST_ID,THREAD_ID,PROCESSLIST_INFO from performance_schema.threads where PROCESSLIST_ID in (8,10);
-- 找到上一步找到的執行緒ID找到執行過的SQL語句
select THREAD_ID,
perf_db.f_convert_timer_to_utc(TIMER_START) run_start_time,
perf_db.f_convert_timer_to_utc(TIMER_END) run_end_time,
TIMER_WAIT/1000000000000 wait_time_s,
'False' is_current,
CURRENT_SCHEMA,
SQL_TEXT
from performance_schema.events_statements_history where thread_id=51
union
select THREAD_ID,
perf_db.f_convert_timer_to_utc(TIMER_START) run_start_time,
perf_db.f_convert_timer_to_utc(TIMER_END) run_end_time,
TIMER_WAIT/1000000000000 wait_time_s,
'True' is_current,
CURRENT_SCHEMA,
SQL_TEXT
from performance_schema.events_statements_current where thread_id=51
and (THREAD_ID,EVENT_ID,END_EVENT_ID) not in (select THREAD_ID,EVENT_ID,END_EVENT_ID from performance_schema.events_statements_history )
order by run_start_time;注：以上指令碼中紅色文字，需要根據實際情況替換。
整理指令碼後，研發同學再次嘗試進行了復現死鎖。查詢得到如下結果：
select PROCESSLIST_ID,THREAD_ID,PROCESSLIST_INFO from performance_schema.threads where PROCESSLIST_ID in (8,10);
+----------------+-----------+------------------+
| PROCESSLIST_ID | THREAD_ID | PROCESSLIST_INFO |
+----------------+-----------+------------------+
| 8 | 49 | NULL |
| 10 | 51 | NULL |
+----------------+-----------+------------------+
thread_id=49的sql執行情況：
| 49 | 2023-03-25 02:15:59.173352 | 2023-03-25 02:15:59.173612 | 0.0003 | False | testdb | begin |
| 49 | 2023-03-25 02:16:08.349311 | 2023-03-25 02:16:08.350678 | 0.0014 | False | testdb | insert into dl_tab(id,name) values(26,10) |
| 49 | 2023-03-25 02:16:26.824176 | 2023-03-25 02:16:26.826121 | 0.0019 | False | testdb | insert into dl_tab(id,name) values(40,8) |
+-----------+----------------------------+----------------------------+-------------+------------+----------------+-------------------------------------------+
thread_id=51 的sql執行情況：
| 51 | 2023-03-25 02:15:58.040749 | 2023-03-25 02:15:58.041057 | 0.0003 | False | testdb | begin |
| 51 | 2023-03-25 02:16:17.408110 | 2023-03-25 02:16:26.828374 | 9.4203 | False | testdb | insert into dl_tab(id,name) values(30,10) |梳理結果如下：
根據上述梳理結果，透過人工方式在開發環境執行上述SQL語句，再次發生死鎖，且innodb status的死鎖資訊與測試環境基本相同。
至此，回答了最開始提出的問題Q1：
Q1: T1為什麼會持有 ua中記錄10 的鎖？
答：因為該事務前面執行了語句如下語句，所以持有了記錄(26,10)的鎖：insert into dl_tab(id,name) values(26,10);
3、關於跟蹤死鎖額外的思考
從這個死鎖的發生過程，剛好是innodb status死鎖資訊輸出結果中的兩個會話導致了死鎖。但參與死鎖的可能涉及3個、4個或者更多的事務，因此還有如下幾個額外的問題：
Q5: 如果是3個或更多的事務參與死鎖，如何跟蹤？
Q6: 執行的SQL語句應該是導致死鎖最直接的原因，其本質鎖的是記錄、鎖型別及堵塞關係，如何檢視？
Q7: 死鎖發生後，由於MySQL死鎖檢測機制會自動發現死鎖，並會挑選事務進行回退。事務被回退了之後，就破壞了死鎖的第一現場。除了innodb status提供的最近一次死鎖資訊外（特別是8.0.18之前不包括事務1持有的鎖資訊），再無其它可用的分析資料。
綜合以上3個問題，總結了如下補充方案，以採集相關的效能資料：
- 針對Q7：在測試環境臨時關閉死鎖檢測，然後再次復現：
innodb_deadlock_detect = off
innodb_lock_wait_timeout = 10
innodb_rollback_on_timeout = on- 針對Q5,Q6：結合MySQL已有的實時鎖與鎖等待效能資料，總結了如下指令碼：
-- 建立工作目錄
cd <path-to-dir>
mkdir deadlock_data
cd deadlock_data
-- 建立死鎖資料儲存表
mysql -uroot -S /tmp/mysql.sock
create database IF NOT EXISTS perf_db;
use perf_db
CREATE TABLE `tab_deadlock_info` (
`id` int primary key auto_incrment,
`curr_dt` datetime(6) NOT NULL,
`thread_id` bigint unsigned DEFAULT NULL,
`conn_id` bigint unsigned DEFAULT NULL,
`trx_id` bigint unsigned DEFAULT NULL,
`object_name` varchar(64) DEFAULT NULL,
`INDEX_NAME` varchar(64) DEFAULT NULL,
`lock_type` varchar(32) NOT NULL,
`lock_mode` varchar(32) NOT NULL,
`lock_status` varchar(32) NOT NULL,
`LOCK_DATA` varchar(8192) CHARACTER SET utf8mb4 DEFAULT NULL,
`blk_trx_id` bigint unsigned DEFAULT NULL,
`blk_thd_id` bigint unsigned DEFAULT NULL,
index idx_curr_dt(curr_dt)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
-- 檢視當前存在的鎖及鎖堵塞資訊
-- data_locks/data_lock_waits 自MySQL 8.0.1提供，之前版本查詢information_schema.innodb_locks/ information_schema.innodb_lock_waits獲取類似資訊
vi save_lock_data.sql
insert into tab_deadlock_info(curr_dt,thread_id,conn_id,trx_id,object_name,index_name,
lock_type,lock_mode,lock_status,lock_data,blk_trx_id,blk_thd_id)
select NOW(6) curr_dt,a.thread_id,b.PROCESSLIST_ID conn_id,
ENGINE_TRANSACTION_ID trx_id, object_name,
INDEX_NAME,lock_type,lock_mode,lock_status,LOCK_DATA,
c.BLOCKING_ENGINE_TRANSACTION_ID blk_trx_id,
c.BLOCKING_THREAD_ID blk_thd_id
from performance_schema.data_locks a left join performance_schema.threads b
on a.thread_id=b.thread_id
left join performance_schema.data_lock_waits c
on a.ENGINE_TRANSACTION_ID=c.REQUESTING_ENGINE_TRANSACTION_ID and a.thread_id=c.REQUESTING_THREAD_ID
where a.thread_id=b.thread_id order by thread_id,trx_id;
-- 查詢指令碼
mysql -uroot -S /tmp/mysql.sock perf_db -e "source save_lock_data.sql"
-- 定時查詢指令碼
vi run_save_lock.sh
while true
do
sleep 0.1 # 指定查詢間隔時間，結合實際需求調整
mysql -uroot -S /tmp/mysql.sock perf_db -e "source save_lock_data.sql" 2>>run_save_lock.err
done
-- 執行查詢
sh run_save_lock.sh說明：
A.配置上述innodb_deadlock_detect引數關閉死鎖檢測，innodb status將不在會繼續輸出最後LATEST DETECTED DEADLOCK資訊；
B.應用日誌看到的告警為鎖超時告警：Lock wait timeout exceeded; try restarting transaction。可以據此找到鎖超時發生時間。
再次復現後使用使用tab_deadlock_info查詢鎖資料如下：
同時，使用步驟2)查詢的語句資訊如下：
綜合上述查詢結果，梳理得到如下結果：
再次梳理出了死鎖的發生過程。
四、根因分析
透過上述過程，可以看到死鎖發生的過程，獲取的鎖及其屬性資訊。但要分析出為什麼會發生死鎖，還需要結合MySQL的鎖實現機制。由於以上死鎖場景，涉及唯一索引的插入實現邏輯，將結合原始碼進行解讀。
1、單列唯一索引插入邏輯
下圖中：
藍色線表示T1第一次插入執行的邏輯；
紫色線表示T2第一次插入執行的邏輯；
黑色線表示T1第二次插入執行的邏輯；
與唯一索引插入記錄相關鎖操作，使用了紅色短箭頭標記；
豎線與紅色短尖頭交叉表示執行了函式，否則表示未執行。
2、最終死鎖過程
以時間維度，結合以上的mysql加鎖邏輯進行分析：
A. T1、T2開啟了一個事務，隨後T1執行了插入(26,10)的insert語句
B. T2執行了插入(30,10)的insert語句。進行唯一性衝突檢查，嘗試獲取LOCK_S | LOCK_ORDINARY[line 15]。那為什麼看到時LOCK S，是因為LOCK_ORDINARY對應的數字表示為0，任何與之進行“與”運算都等於本身，所以看不出來：
C. 然後T2所在的連線會將T1中的隱式鎖轉換為顯示鎖[line 17]，此時T1將獲取LOCK_REC | LOCK_X | LOCK_REC_NOT_GAP，即看到的Lock X, Rec_not_gap。由於是T2所在的執行緒為T1建立的鎖，因此該鎖對應的thread_id為T2的執行緒ID，但trx_id為T1的事務ID
D. 但由於 T1的LOCK X|LOCK_REC_NOT_GAP與T2的LOCK S| LOCK_ORDINARY不相容[line 23]，因此T2被堵塞
E. 當T2被堵塞時，內部函式add_to_waitq 在處理時，同樣會記錄建立一個鎖，並設定屬性 LOCK_S | LOCK_ORDINARY | LOCK_WAIT | LOCK_REC，以指示鎖等待[line 24]。隨後T2返回上層函式，以等待鎖資源[line 38]
F. 隨後，T1又執行了(40,8)的insert語句。由於其插入的唯一索引值是8（注意不是10），因此不存在主鍵衝突，直接執行樂觀插入操作[line 43]。
G. 執行樂觀插入時，需要檢查其它事務是否堵塞insert操作。其核心是獲取待插入記錄的下一個值[line 46-47]（這裡剛好是10），並獲取該記錄上的所有鎖，與需要新增的鎖（LOCK_X | LOCK_GAP | LOCK_INSERT_INTENTION）判斷是否存在衝突[line 51]。
H. 第E步T2持有了記錄10的LOCK_S | LOCK_ORDINARY | LOCK_WAIT | LOC
K_REC 鎖與T1的LOCK_X | LOCK_GAP | LOCK_INSERT_INTENTION不相容，因此T1被T2堵塞[line 51]
I. 死鎖形成。
如需瞭解更多實現細節，大家可以結合原始碼進一步確認。
至此，回答了最開始提出的問題Q2,Q3,Q4：
Q2: T1既然持有了鎖，為什麼又會等待鎖？
答：持有鎖應該沒有疑問，在分析類似問題注意隱式鎖轉換為顯示鎖的機制(lock_rec_convert_impl_to_expl)。等待鎖主要由於T2被堵塞後，會建立鎖（LOCK_S | LOCK_ORDINARY | LOCK_WAIT | LOCK_REC）。然後T1在執行樂觀插入時，需要遍歷記錄上存在的所有>鎖進行鎖衝突判斷，由於鎖模式不相容，因此被堵塞
Q3: T2持有和等待相同的鎖，到底是持有還是在等待？
答：雖然從innodb status看到T2持有和等待都是lock s, next key lock。但實際上等待lock s, next key lock；由於鎖衝突，加入等待佇列時會持有鎖LOCK_S | LOCK_ORDINARY | LOCK_WAIT | LOCK_REC
Q4: 死鎖到底是如何產生的？
答：見以上分析死鎖過程分析
五、解決問題
綜合以上死鎖發生的發生過程和原因，總結原因如下：
原因1：主要研發過度依賴唯一索引，插入的資料不符合唯一索引要求，需要進行唯一性衝突檢查。
原因2：批次插入的資料不是有序的。兩種情況同時存在，導致死鎖發生。
原因2在併發場景下，控制起來較為複雜。原因1該場景為併發批次插入邏輯，可以在執行插入時，避免插入重複的uname。隨後，研發同學進行邏輯最佳化後，問題不再發生。
對於死鎖問題，建議結合業務情況儘量選擇Read Committed隔離級別，適當的減少Unique索引。如確實發生死鎖，讀者朋友可以參考本次故障案例，合理利用效能資料來跟蹤死鎖問題，結合原始碼或者已有的案例分析死鎖根本原因和解決方案。
以上資訊僅左右交流，作者水平有限，如有不足之處，歡迎在評論區交流。