如果我們的業務處在一個非常初級的階段，併發程度比較低，那麼我們可以幾年都遇不到一次死鎖問題的發生，反之，我們業務的併發程度非常高，那麼時不時爆出的死鎖問題肯定讓我們非常撓頭。不過在死鎖問題發生時，很多沒有經驗的同學的第一反應就是成為一隻鴕鳥：這玩意兒很高深，我也看不懂，聽天由命吧，又不是一直髮生。其實如果大家認真研讀了我們之前寫的3篇關於MySQL中語句加鎖分析的文章：
加上本篇關於死鎖日誌的分析，那麼解決死鎖問題應該也不是那麼摸不著頭腦的事情了。
準備工作
為了故事的順利發展，我們需要建一個表：
CREATE TABLE hero ( id INT, name VARCHAR(100), country varchar(100), PRIMARY KEY (id), KEY idx_name (name)) Engine=InnoDB CHARSET=utf8;我們為hero表的id列建立了聚簇索引，為name列建立了一個二級索引。這個hero表主要是為了儲存三國時的一些英雄，我們向表中插入一些記錄：
INSERT INTO hero VALUES (1, 'l劉備', '蜀'), (3, 'z諸葛亮', '蜀'), (8, 'c曹操', '魏'), (15, 'x荀彧', '魏'), (20, 's孫權', '吳');現在表中的資料就是這樣的：
mysql> SELECT * FROM hero;+----+------------+---------+| id | name | country |+----+------------+---------+| 1 | l劉備 | 蜀 || 3 | z諸葛亮 | 蜀 || 8 | c曹操 | 魏 || 15 | x荀彧 | 魏 || 20 | s孫權 | 吳 |+----+------------+---------+5 rows in set (0.00 sec)準備工作就做完了。
建立死鎖情景
我們先建立一個發生死鎖的情景，在Session A和Session B中分別執行兩個事務，具體情況如下：
我們分析一下：
從第③步中可以看出，
Session A中的事務先對hero表聚簇索引的id值為1的記錄加了一個X型正經記錄鎖。從第④步中可以看出，
Session B中的事務對hero表聚簇索引的id值為3的記錄加了一個X型正經記錄鎖。從第⑤步中可以看出，
Session A中的事務接著想對hero表聚簇索引的id值為3的記錄也加了一個X型正經記錄鎖，但是與第④步中Session B中的事務加的鎖衝突，所以Session A進入阻塞狀態，等待獲取鎖。從第⑥步中可以看出，
Session B中的事務想對hero表聚簇索引的id值為1的記錄加了一個X型正經記錄鎖，但是與第③步中Session A中的事務加的鎖衝突，而此時Session A和Session B中的事務迴圈等待對方持有的鎖，死鎖發生，被MySQL伺服器的死鎖檢測機制檢測到了，所以選擇了一個事務進行回滾，並向客戶端傳送一條訊息：ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
以上是我們從語句加了什麼鎖的角度出發來進行死鎖情況分析的，但是實際應用中我們可能壓根兒不知道到底是哪幾條語句產生了死鎖，我們需要根據MySQL在死鎖發生時產生的死鎖日誌來逆向定位一下到底是什麼語句產生了死鎖，從而再優化我們的業務。
檢視死鎖日誌
設計InnoDB的大叔給我們提供了SHOW ENGINE INNODB STATUS命令來檢視關於InnoDB儲存引擎的一些狀態資訊，其中就包括了系統最近一次發生死鎖時的加鎖情況。在上邊例子中的死鎖發生時，我們執行一下這個命令：
mysql> SHOW ENGINE INNODB STATUS\G...省略了好多其他資訊------------------------LATEST DETECTED DEADLOCK------------------------2019-06-20 13:39:19 0x70000697e000*** (1) TRANSACTION:TRANSACTION 30477, ACTIVE 10 sec starting index readmysql tables in use 1, locked 1LOCK WAIT 3 lock struct(s), heap size 1160, 2 row lock(s)MySQL thread id 2, OS thread handle 123145412648960, query id 46 localhost 127.0.0.1 root statisticsselect * from hero where id = 3 for update*** (1) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30477 lock_mode X locks rec but not gap waitingRecord lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 80000003; asc ;; 1: len 6; hex 000000007517; asc u ;; 2: len 7; hex 80000001d0011d; asc ;; 3: len 10; hex 7ae8afb8e8919be4baae; asc z ;; 4: len 3; hex e89c80; asc ;;*** (2) TRANSACTION:TRANSACTION 30478, ACTIVE 8 sec starting index readmysql tables in use 1, locked 13 lock struct(s), heap size 1160, 2 row lock(s)MySQL thread id 3, OS thread handle 123145412927488, query id 47 localhost 127.0.0.1 root statisticsselect * from hero where id = 1 for update*** (2) HOLDS THE LOCK(S):RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gapRecord lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 80000003; asc ;; 1: len 6; hex 000000007517; asc u ;; 2: len 7; hex 80000001d0011d; asc ;; 3: len 10; hex 7ae8afb8e8919be4baae; asc z ;; 4: len 3; hex e89c80; asc ;;*** (2) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap waitingRecord lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000007517; asc u ;; 2: len 7; hex 80000001d00110; asc ;; 3: len 7; hex 6ce58898e5a487; asc l ;; 4: len 3; hex e89c80; asc ;;*** WE ROLL BACK TRANSACTION (2)------------...省略了好多其他資訊
我們只關心最近發生的死鎖資訊，所以就把以LATEST DETECTED DEADLOCK這一部分給單獨提出來分析一下。下邊我們就逐行看一下這個輸出的死鎖日誌都是什麼意思：
首先看第一句：
2019-06-20 13:39:19 0x70000697e000這句話的意思就是死鎖發生的時間是：2019-06-20 13:39:19，後邊的一串十六進位制
0x70000697e000表示的作業系統為當前session分配的執行緒的執行緒id。然後是關於死鎖發生時第一個事務的有關資訊：
*** (1) TRANSACTION:# 為事務分配的id為30477# 事務處於ACTIVE狀態已經10秒了# 事務現在正在做的操作就是：“starting index read”TRANSACTION 30477, ACTIVE 10 sec starting index read# 此事務使用了1個表，為1個表上了鎖（此處不是說為該表加了表鎖，只要不是進行一致性讀的表，都需要加鎖，具體怎麼加鎖請看加鎖語句分析或者小冊章節）mysql tables in use 1, locked 1# 此事務處於LOCK WAIT狀態，擁有3個鎖結構（2個行鎖結構，1個表級別X型意向鎖結構，鎖結構在小冊中重點介紹過）# heap size是為了儲存鎖結構而申請的記憶體大小（我們可以忽略），其中有2個行鎖的結構LOCK WAIT 3 lock struct(s), heap size 1160, 2 row lock(s)# 本事務所線上程的id是2（MySQL自己命名的執行緒id），該執行緒在作業系統級別的id就是那一長串數字# 當前查詢的id為46（MySQL內部使用，可以忽略），還有使用者名稱主機資訊MySQL thread id 2, OS thread handle 123145412648960, query id 46 localhost 127.0.0.1 root statistics# 本事務發生阻塞的語句select * from hero where id = 3 for update# 本事務當前在等待獲取的鎖：*** (1) WAITING FOR THIS LOCK TO BE GRANTED:# 等待獲取的表空間ID為151，頁號為3，也就是表hero的PRIMAY索引中的某條記錄的鎖# n_bits是為了儲存本頁面的鎖資訊而分配的一串記憶體空間，小冊中有詳細介紹# 該鎖的型別是X型正經記錄鎖（rec but not gap）RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30477 lock_mode X locks rec but not gap waiting# 該記錄在頁面中的heap_no為2，具體的記錄資訊如下：Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0# 這是主鍵值0: len 4; hex 80000003; asc ;;# 這是trx_id隱藏列1: len 6; hex 000000007517; asc u ;;# 這是roll_pointer隱藏列2: len 7; hex 80000001d0011d; asc ;;# 這是name列3: len 10; hex 7ae8afb8e8919be4baae; asc z ;;# 這是country列4: len 3; hex e89c80; asc ;;從這個資訊中可以看出，
Session A中的事務為2條記錄生成了鎖結構，但是其中有一條記錄上的X型正經記錄鎖（rec but not gap）並沒有獲取到，沒有獲取到鎖的這條記錄的位置是：表空間ID為151，頁號為3，heap_no為2。當然，設計InnoDB的大叔還貼心的給出了這條記錄的詳細情況，它的主鍵值為80000003，這其實是InnoDB內部儲存使用的格式，其實就代表數字3，也就是該事務在等待獲取hero表聚簇索引主鍵值為3的那條記錄的X型正經記錄鎖。然後是關於死鎖發生時第二個事務的有關資訊：
其中的大部分資訊我們都已經介紹過了，我們就挑重要的說：
*** (2) TRANSACTION:TRANSACTION 30478, ACTIVE 8 sec starting index readmysql tables in use 1, locked 13 lock struct(s), heap size 1160, 2 row lock(s)MySQL thread id 3, OS thread handle 123145412927488, query id 47 localhost 127.0.0.1 root statisticsselect * from hero where id = 1 for update# 表示該事務獲取到的鎖資訊*** (2) HOLDS THE LOCK(S):RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gapRecord lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0# 主鍵值為30: len 4; hex 80000003; asc ;;1: len 6; hex 000000007517; asc u ;;2: len 7; hex 80000001d0011d; asc ;;3: len 10; hex 7ae8afb8e8919be4baae; asc z ;;4: len 3; hex e89c80; asc ;;# 表示該事務等待獲取的鎖資訊*** (2) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 171 page no 3 n bits 72 index PRIMARY of table `dahaizi`.`hero` trx id 30478 lock_mode X locks rec but not gap waitingRecord lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0# 主鍵值為10: len 4; hex 80000001; asc ;;1: len 6; hex 000000007517; asc u ;;2: len 7; hex 80000001d00110; asc ;;3: len 7; hex 6ce58898e5a487; asc l ;;4: len 3; hex e89c80; asc ;;從上邊的輸出可以看出來，
Session B中的事務獲取了hero表聚簇索引主鍵值為3的記錄的X型正經記錄鎖，等待獲取hero表聚簇索引主鍵值為1的記錄的X型正經記錄鎖（隱含的意思就是這個hero表聚簇索引主鍵值為1的記錄的X型正經記錄鎖已經被SESSION A中的事務獲取到了）。看最後一部分：
*** WE ROLL BACK TRANSACTION (2)最終InnoDB儲存引擎決定回滾第2個事務，也就是
Session B中的那個事務。
思索分析的思路
檢視死鎖日誌時，首先看一下發生死鎖的事務等待獲取鎖的語句都是啥。
本例中，發現
SESSION A發生阻塞的語句是：select * from hero where id = 3 for updateSESSION B發生阻塞的語句是：select * from hero where id = 1 for update然後切記：到自己的業務程式碼中找出這兩條語句所在事務的其他語句。
找到發生死鎖的事務中所有的語句之後，對照著事務獲取到的鎖和正在等待的鎖的資訊來分析死鎖發生過程。
從死鎖日誌中可以看出來，
SESSION A獲取了hero表聚簇索引id值為1的記錄的X型正經記錄鎖（這其實是從SESSION B正在等待的鎖中獲取的），檢視SESSION A中的語句，發現是下邊這個語句造成的（對照著語句加鎖分析那三篇文章）:select * from hero where id = 1 for update;還有
SESSION B獲取了hero表聚簇索引id值為3的記錄的X型正經記錄鎖，檢視SESSION B中的語句，發現是下邊這個語句造成的（對照著語句加鎖分析那三篇文章）:select * from hero where id = 3 for update;然後看
SESSION A正在等待hero表聚簇索引id值為3的記錄的X型正經記錄鎖，這個是由於下邊這個語句造成的：select * from hero where id = 3 for update;然後看
SESSION B正在等待hero表聚簇索引id值為1的記錄的X型正經記錄鎖，這個是由於下邊這個語句造成的：select * from hero where id = 1 for update;然後整個死鎖形成過程就根據死鎖日誌給還原出來了。
文章系轉載
文章來源：我們都是小青蛙（微信公眾號）
本作品採用《CC 協議》，轉載必須註明作者和本文連結