這樣分析一個死鎖問題

jeanron100發表於2017-09-11

  之前也列舉了幾期的MySQL死鎖問題,光有操作演練,還缺少一些自己的分析,所以我就打算補充一下。

   首先對於死鎖問題,我們分析的背景是基於MySQL事務隔離級別為RR,儲存引擎為InnoDB,在MySQL 5.6,5.7版本均可復現問題。

   怎麼來分析一個死鎖問題呢,我一直在琢磨這個問題,自己也總結了不少出現的場景,但是感覺還是有一些欠缺或者不完善的地方。那麼我們就換一個思路來分析死鎖問題,透過日誌來反推死鎖產生的可能場景,然後依次深入,擴充套件,這樣一來,這個問題的分析就帶有透過很多不確定性分析判斷,得到確定性的結果,然後分析和預期一致,這個問題就算基本搞明白了。

   所以在此我不給出表結構,只給出死鎖的日誌來。這樣一段日誌,是在MySQL設定了死鎖檢測,輸出日誌的引數後得到的。

   透過一段死鎖日誌來挖掘一些有價值的資訊。

   整個死鎖的日誌分為了兩個事務,Transaction 1和Transaction 2,這裡需要指出的是,這其實是發生死鎖的臨界狀態的事務資訊,就好似一個印章。我們看到的是最後得到的一個狀態資訊(類似蓋上印章的一瞬間),而完整的過程是沒法透過日誌體現出來的,還有一個,如果仔細看上面的日誌就會發現,事務1的日誌還是不夠完整,持有的鎖,等待的鎖,只列印出了等待的鎖,有很多業內朋友是透過修改核心程式碼來把這個資訊補充完整的。

這樣分析一個死鎖問題

  但是發生死鎖的時候是有兩個事務互相阻塞,迴圈形成死鎖,我們就依次來分析兩個事務的日誌資訊。

  事務1的日誌資訊如下,我們可以看到整個事務持續(阻塞)了46秒鐘,很快就會達到觸發超時的閾值,涉及的表有1個(tables in use 1),有2個鎖(一個表級意向鎖,一個行鎖)語句為: delete from dtest1 where num=10,,加鎖的物件是索引num,這個唯一的行鎖處於等待狀態(WAITING FOR THIS LOCK TO BE GRANTED),相關的鎖等待為(lock_mode X waiting,next key鎖)。

*** (1) TRANSACTION:
TRANSACTION 2844, ACTIVE 46 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 5, OS thread handle 140582228653824, query id 55 localhost root updating
delete from dtest1 where num=10
2017-09-11T10:07:08.103195Z 6 [Note] InnoDB: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:

RECORD LOCKS space id 34 page no 4 n bits 72 index num of table `test`.`dtest1` trx id 2844 lock_mode X waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 8000000a; asc     ;;
 1: len 4; hex 8000000a; asc     ;;


再來看看第二個事務,內容略長一些。可以看到分為兩部分內容,一部分是持有的鎖(HOLDS THE LOCK),鎖模式為(lock_mode X locks rec but not gap,no gap lock),另一部分是等待的鎖,鎖模式為(lock mode S waiting)

2017-09-11T10:07:08.103243Z 6 [Note] InnoDB: *** (2) TRANSACTION:

TRANSACTION 2843, ACTIVE 92 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 2
MySQL thread id 6, OS thread handle 140582228387584, query id 58 localhost root update
insert into dtest1 values(11,10)
2017-09-11T10:07:08.103260Z 6 [Note] InnoDB: *** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 34 page no 4 n bits 72 index num of table `test`.`dtest1` trx id 2843 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 8000000a; asc     ;;
 1: len 4; hex 8000000a; asc     ;;
2017-09-11T10:07:08.103301Z 6 [Note] InnoDB: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 34 page no 4 n bits 72 index num of table `test`.`dtest1` trx id 2843 lock mode S waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 8000000a; asc     ;;
 1: len 4; hex 8000000a; asc     ;;

2017-09-11T10:07:08.103348Z 6 [Note] InnoDB: *** WE ROLL BACK TRANSACTION (1)

   大體我們得到了這樣的資訊,一個事務等待的行鎖模式為next key lock,另外一個事務持有record lock,等待的鎖為S鎖,出現S鎖看來是一個突破口,我們就需要明白為什麼會是S鎖,事務2中相關的SQL是insert語句,如果需要進行唯一性衝突檢查的時候,是需要先加一個S鎖,所以由此我們可以進一步推理出這個Num對應的索引是一個唯一性索引。

  由此我們可以進一步分析,何時得到這個S鎖,肯定是在另外一個事務(也可能是其他的事務,比一定是事務1)中會去觸發,在事務2中才會持有一個S鎖,所以這樣一來insert之前是有一個事務在做一個和唯一性索引相關的操作,我們理一下。

  事務1相關的SQL:

   delete from dtest1 where num=10

  事務2相關的SQL:

   insert into dtest1 values(11,10)

  根據持有的S鎖我們可以猜測可能是在事務2之前有一個DML操作阻塞了唯一性索引,我們假設為insert或者delete操作(限定下範圍),進一步限定是兩個會話中的事務,下面的分析就很重要了。

   事務2中的持有的S鎖,我們可以從下往上去推理,事務1上面肯定是一個delete操作,也就是日誌中的第一部分顯示,是一個delete操作。

   按照這個方向往下去想,整個死鎖的場景應該是下面這樣的。

   事務2:

   insert/delete操作待分析

   事務1:

   delete from dtest1 where num=10;

   事務2:

   insert into dtest1 values(11,10);

  如果在事務2中先做的是一個insert操作,顯然在事務2中會直接丟擲duplicate的報錯,所以此處在insert,delete中只能是delete的操作,

   所以整個死鎖的過程真實的情況就是:

   事務2:

   delete from dtest1 where num=10;  --record lock

   事務1:

   delete from dtest1 where num=10;   --申請X鎖,進入鎖請求佇列

   事務2:

   insert into dtest1 values(11,10);  --申請S鎖,產生了迴圈等待。

  這個過程也是拋磚引玉,希望大家提出更多的想法。建表語句為:

create table dtest1 (id int primary key,num int unique);



  


來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/23718752/viewspace-2144820/,如需轉載,請註明出處,否則將追究法律責任。

相關文章