MySQL打印死鎖日志
前言：
在 MySQL 運(yùn)維過(guò)程中，難免會(huì)遇到 MySQL 死鎖的情況，一旦線上業(yè)務(wù)日漸復(fù)雜，各種業(yè)務(wù)操作之間往往會(huì)產(chǎn)生鎖沖突，有些會(huì)導(dǎo)致死鎖異常。這種死鎖異常一般要在特定時(shí)間特定數(shù)據(jù)和特定業(yè)務(wù)操作才會(huì)復(fù)現(xiàn)，有時(shí)候處理起來(lái)毫無(wú)頭緒，一般只能從死鎖日志下手。本篇文章我們一起來(lái)看下 MySQL 的死鎖日志。
? 1.手動(dòng)打印死鎖日志
當(dāng)業(yè)務(wù)發(fā)生死鎖時(shí)，首先是線上錯(cuò)誤日志報(bào)警發(fā)現(xiàn)死鎖異常，也會(huì)提示一些堆棧信息，然后會(huì)反饋到數(shù)據(jù)庫(kù)層面進(jìn)行排查。我們一般會(huì)在命令行執(zhí)行 show engine innodb status\G 來(lái)輸出死鎖日志，\G 的作用是將查詢到的結(jié)果，每行顯示一個(gè)字段和字段值，方便查看。
show engine innodb status 是 MySQL 提供的一個(gè)用于查看 innodb 引擎系統(tǒng)信息的工具。它會(huì)輸出大量的內(nèi)部信息，內(nèi)容分為很多小段，每一段對(duì)應(yīng) innodb 存儲(chǔ)引擎不同部分的信息，其中 LATEST DETECTED DEADLOCK 部分顯示的最近一次的死鎖信息。
下面我們手動(dòng)制造一次死鎖，來(lái)看一下死鎖日志相關(guān)信息：
------------------------
LATEST?DETECTED?DEADLOCK
------------------------
2021-11-10?17:03:10?0x7fb040672700
***?(1)?TRANSACTION:
TRANSACTION?46913,?ACTIVE?142?sec?starting?index?read
mysql?tables?in?use?1,?locked?1
LOCK?WAIT?4?lock?struct(s),?heap?size?1136,?3?row?lock(s),?undo?log?entries?1
MySQL?thread?id?2997198,?OS?thread?handle?140394973071104,?query?id?9145673?localhost?root?updating
update?test_tb?set?stu_name?=?'lisi'?where?stu_id?=?1006
***?(1)?WAITING?FOR?THIS?LOCK?TO?BE?GRANTED:
RECORD?LOCKS?space?id?224?page?no?4?n?bits?80?index?uk_stu_id?of?table?`testdb`.`test_tb`?trx?id?46913?lock_mode?X?locks?rec?but?not?gap?waiting
Record?lock,?heap?no?7?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
?0:?len?4;?hex?800003ee;?asc?????;;
?1:?len?4;?hex?80000006;?asc?????;;
***?(2)?TRANSACTION:
TRANSACTION?46914,?ACTIVE?103?sec?starting?index?read
mysql?tables?in?use?1,?locked?1
4?lock?struct(s),?heap?size?1136,?3?row?lock(s),?undo?log?entries?1
MySQL?thread?id?2997201,?OS?thread?handle?140394971473664,?query?id?9145681?localhost?root?updating
update?test_tb?set?age?=?21??where?stu_id?=?1005
***?(2)?HOLDS?THE?LOCK(S):
RECORD?LOCKS?space?id?224?page?no?4?n?bits?80?index?uk_stu_id?of?table?`testdb`.`test_tb`?trx?id?46914?lock_mode?X?locks?rec?but?not?gap
Record?lock,?heap?no?7?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
?0:?len?4;?hex?800003ee;?asc?????;;
?1:?len?4;?hex?80000006;?asc?????;;
***?(2)?WAITING?FOR?THIS?LOCK?TO?BE?GRANTED:
RECORD?LOCKS?space?id?224?page?no?4?n?bits?80?index?uk_stu_id?of?table?`testdb`.`test_tb`?trx?id?46914?lock_mode?X?locks?rec?but?not?gap?waiting
Record?lock,?heap?no?6?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
?0:?len?4;?hex?800003ed;?asc?????;;
?1:?len?4;?hex?80000005;?asc?????;;
***?WE?ROLL?BACK?TRANSACTION?(2)
#?以上為原文?下面增加個(gè)人分析
------------------------
LATEST?DETECTED?DEADLOCK
------------------------
2021-11-10?17:03:10?0x7fb040672700?#這里顯示了最近一次發(fā)生死鎖的日期和時(shí)間
***?(1)?TRANSACTION:?#死鎖相關(guān)的第一個(gè)事務(wù)
TRANSACTION?46913,?ACTIVE?142?sec?starting?index?read
#這行表示事務(wù)id為46913，事務(wù)處于活躍狀態(tài)142s，starting?index?read表示正在使用索引讀取數(shù)據(jù)行
mysql?tables?in?use?1,?locked?1
#這行表示該事務(wù)正在使用1個(gè)表，且涉及鎖的表有1個(gè)
LOCK?WAIT?4?lock?struct(s),?heap?size?1136,?3?row?lock(s),?undo?log?entries?1
#這行表示在等待4把鎖，占用內(nèi)存1136字節(jié)，涉及3行記錄
MySQL?thread?id?2997198,?OS?thread?handle?140394973071104,?query?id?9145673?localhost?root?updating
#這行表示該事務(wù)的線程ID信息，操作系統(tǒng)句柄信息，連接來(lái)源、用戶
update?test_tb?set?stu_name?=?'lisi'?where?stu_id?=?1006
#這行表示事務(wù)執(zhí)行的最后一條SQL信息
***?(1)?WAITING?FOR?THIS?LOCK?TO?BE?GRANTED:?#事務(wù)1想要獲取的鎖
RECORD?LOCKS?space?id?224?page?no?4?n?bits?80?index?uk_stu_id?of?table?`testdb`.`test_tb`?trx?id?46913?lock_mode?X?locks?rec?but?not?gap?waiting
#這行信息表示等待的鎖是一個(gè)record?lock，空間id是224，頁(yè)編號(hào)為4，大概位置在頁(yè)的80位處，鎖發(fā)生在表testdb.test_tb的uk_stu_id索引上，是一個(gè)X鎖，但是不是gap?lock，waiting表示正在等待鎖
Record?lock,?heap?no?7?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
?0:?len?4;?hex?800003ee;?asc?????;;
?1:?len?4;?hex?80000006;?asc?????;;
***?(2)?TRANSACTION:?#死鎖相關(guān)的第一個(gè)事務(wù)
TRANSACTION?46914,?ACTIVE?103?sec?starting?index?read
#這行表示事務(wù)2的id為46914，事務(wù)處于活躍狀態(tài)103s
mysql?tables?in?use?1,?locked?1
#正在使用1個(gè)表，涉及鎖的表有1個(gè)
4?lock?struct(s),?heap?size?1136,?3?row?lock(s),?undo?log?entries?1
#涉及4把鎖，3行記錄
MySQL?thread?id?2997201,?OS?thread?handle?140394971473664,?query?id?9145681?localhost?root?updating
#事務(wù)2的線程ID信息，操作系統(tǒng)句柄信息，連接來(lái)源、用戶
update?test_tb?set?age?=?21??where?stu_id?=?1005
#第二個(gè)事務(wù)的SQL
***?(2)?HOLDS?THE?LOCK(S):?#?事務(wù)2持有的鎖?正是事務(wù)1想要獲取的鎖
RECORD?LOCKS?space?id?224?page?no?4?n?bits?80?index?uk_stu_id?of?table?`testdb`.`test_tb`?trx?id?46914?lock_mode?X?locks?rec?but?not?gap
Record?lock,?heap?no?7?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
?0:?len?4;?hex?800003ee;?asc?????;;
?1:?len?4;?hex?80000006;?asc?????;;
***?(2)?WAITING?FOR?THIS?LOCK?TO?BE?GRANTED:
RECORD?LOCKS?space?id?224?page?no?4?n?bits?80?index?uk_stu_id?of?table?`testdb`.`test_tb`?trx?id?46914?lock_mode?X?locks?rec?but?not?gap?waiting
Record?lock,?heap?no?6?PHYSICAL?RECORD:?n_fields?2;?compact?format;?info?bits?0
?0:?len?4;?hex?800003ed;?asc?????;;
?1:?len?4;?hex?80000005;?asc?????;;
#上面這部分是事務(wù)二正在等待的鎖，從信息上看，等待的是同一個(gè)表，同一個(gè)索引，同一個(gè)page上的record?lock?X鎖，但是heap?no位置不同，即不同的行上的鎖
***?WE?ROLL?BACK?TRANSACTION?(2)?#表示事務(wù)2被回滾從死鎖日志中可以看到關(guān)聯(lián)的兩個(gè)事務(wù)相關(guān)信息，當(dāng)一個(gè)事務(wù)持有了其他事務(wù)需要的鎖，同時(shí)又想獲得其他事務(wù)持有的鎖時(shí)，等待關(guān)系上就會(huì)產(chǎn)生循環(huán)，Innodb 不會(huì)顯示所有持有和等待的鎖，但死鎖日志也顯示了相關(guān)的信息來(lái)幫你確定，排查死鎖發(fā)生的索引，這對(duì)于你確定能否避免死鎖有較大的價(jià)值。
? 2.自動(dòng)保存死鎖日志
從上面內(nèi)容我們知道 MySQL 的死鎖可以通過(guò) show engine innodb status 來(lái)查看，但是這個(gè)命令需要手動(dòng)執(zhí)行并且只能顯示最新的一條死鎖，該方式無(wú)法完全捕獲到系統(tǒng)發(fā)生的死鎖信息。那有沒(méi)有辦法記錄所有的死鎖日志呢，我們來(lái)看下 MySQL 的系統(tǒng)參數(shù)。
MySQL 系統(tǒng)內(nèi)部提供一個(gè) innodb_print_all_deadlocks 參數(shù)，該參數(shù)默認(rèn)是關(guān)閉的，開(kāi)啟后可以將死鎖信息自動(dòng)記錄到 MySQL 的錯(cuò)誤日志中。下面我們來(lái)看下這個(gè)參數(shù)的作用：
#?查看參數(shù)是否開(kāi)啟
mysql>?show?variables?like?'innodb_print_all_deadlocks';
+----------------------------+-------+
|?Variable_name??????????????|?Value?|
+----------------------------+-------+
|?innodb_print_all_deadlocks?|?OFF???|
+----------------------------+-------+
#?開(kāi)啟innodb_print_all_deadlocks,此參數(shù)是全局參數(shù)，可以動(dòng)態(tài)調(diào)整。記得要加入到配置文件中
mysql>?set?global?innodb_print_all_deadlocks?=?1;
Query?OK,?0?rows?affected?(0.00?sec)
mysql>?show?variables?like?'innodb_print_all_deadlocks';
+----------------------------+-------+
|?Variable_name??????????????|?Value?|
+----------------------------+-------+
|?innodb_print_all_deadlocks?|?ON????|
+----------------------------+-------+建議將 innodb_print_all_deadlocks 參數(shù)設(shè)置為 1 ，這樣每次發(fā)生死鎖后，系統(tǒng)會(huì)自動(dòng)將死鎖信息輸出到錯(cuò)誤日志中，需要注意的是打開(kāi)此參數(shù)后，只會(huì)記錄死鎖部分信息而不會(huì)記錄 innodb 其他相關(guān)信息，即只會(huì)記錄 show engine innodb status 中的 LATEST DETECTED DEADLOCK 部分。
其實(shí) InnoDB 存儲(chǔ)引擎還提供有 InnoDB Monitor 監(jiān)視器，可以定期將 InnoDB 的狀態(tài)信息輸出到錯(cuò)誤日志中，主要由 innodb_status_output 和 innodb_status_output_locks 參數(shù)控制，這兩個(gè)系統(tǒng)變量是用來(lái)啟用標(biāo)準(zhǔn) InnoDB 監(jiān)控和 InnoDB 鎖監(jiān)控的，開(kāi)啟后會(huì)將監(jiān)控結(jié)果輸出錯(cuò)誤日志中，大約每隔 15 秒產(chǎn)生一次輸出，輸出內(nèi)容與 show engine innodb status 一致。不過(guò)這會(huì)導(dǎo)致錯(cuò)誤日志暴增，一般不建議開(kāi)啟這兩個(gè)參數(shù)。
總結(jié)：
本篇文章介紹了 MySQL 死鎖日志的獲取方法，發(fā)生死鎖后，可以根據(jù)死鎖日志還獲取相關(guān)信息。開(kāi)啟 innodb_print_all_deadlocks 參數(shù)可以自動(dòng)將死鎖信息輸出到錯(cuò)誤日志中，有助于我們及時(shí)發(fā)現(xiàn)并處理死鎖異常。
推薦閱讀
（點(diǎn)擊標(biāo)題可跳轉(zhuǎn)閱讀）