線上發(fā)生死鎖異常了，該怎么辦
本文轉(zhuǎn)載自微信公眾號(hào)「程序員歷小冰」，作者歷小冰 。轉(zhuǎn)載本文請(qǐng)聯(lián)系程序員歷小冰公眾號(hào)。
前言
MySQL 死鎖異常是我們經(jīng)常會(huì)遇到的線上異常類別，一旦線上業(yè)務(wù)日間復(fù)雜，各種業(yè)務(wù)操作之間往往會(huì)產(chǎn)生鎖沖突，有些會(huì)導(dǎo)致死鎖異常。這種死鎖異常一般要在特定時(shí)間特定數(shù)據(jù)和特定業(yè)務(wù)操作才會(huì)復(fù)現(xiàn)，并且分析解決時(shí)還需要了解 MySQL 鎖沖突相關(guān)知識(shí)，所以一般遇到這些偶爾出現(xiàn)的死鎖異常，往往一時(shí)沒有頭緒，不好處理。
本篇文章會(huì)講解一下如果線上發(fā)生了死鎖異常，如何去排查和處理。除了系列前文講解的有關(guān)加鎖和鎖沖突的原理還，還需要對(duì) MySQl 死鎖日志和 binlog 日志進(jìn)行分析。
正文日常工作中，應(yīng)對(duì)各類線上異常都要有我們自己的 SOP (標(biāo)準(zhǔn)作業(yè)流程) ，這樣不僅能夠提高自己的處理問題效率，也有助于將好的處理流程推廣到團(tuán)隊(duì)，提高團(tuán)隊(duì)的整體處理異常能力。
所以，面對(duì)線上偶發(fā)的 MySQL 死鎖問題，我的排查處理過程如下：
- 線上錯(cuò)誤日志報(bào)警發(fā)現(xiàn)死鎖異常
- 查看錯(cuò)誤日志的堆棧信息
- 查看 MySQL 死鎖相關(guān)的日志
- 根據(jù) binlog 查看死鎖相關(guān)事務(wù)的執(zhí)行內(nèi)容
- 根據(jù)上述信息找出兩個(gè)相互死鎖的事務(wù)執(zhí)行的 SQL 操作，根據(jù)本系列介紹的鎖相關(guān)理論知識(shí)，進(jìn)行分析推斷死鎖原因
- 修改業(yè)務(wù)代碼
根據(jù)1，2步驟可以找到死鎖異常時(shí)進(jìn)行回滾事務(wù)的具體業(yè)務(wù)，也就能夠找到該事務(wù)執(zhí)行的 SQL 語(yǔ)句。然后我們需要通過 3，4步驟找到死鎖異常時(shí)另外一個(gè)事務(wù)，也就是最終獲得鎖的事務(wù)所執(zhí)行的 SQL 語(yǔ)句，然后再進(jìn)行鎖沖突相關(guān)的分析。
第一二步的線上錯(cuò)誤日志和堆棧信息一般比較容易獲得，第五步的分析 SQL 鎖沖突原因中涉及的鎖相關(guān)的理論在系列文章中都有介紹，沒有了解的同學(xué)可以自行去閱讀以下。
下面我們就來(lái)重點(diǎn)說一下其中的第三四步驟，也就是如何查看死鎖日志和 binlog 日志來(lái)找到死鎖相關(guān)的 SQL 操作。
死鎖日志的獲取
發(fā)生死鎖異常后，我們可以直接使用 show engine innodb status 命令獲取死鎖信息，但是該命令只能獲取最近一次的死鎖信息。所以，我們可以通過開啟 InnoDB 的監(jiān)控機(jī)制來(lái)獲取實(shí)時(shí)的死鎖信息，它會(huì)周期性(每隔 15 秒)打印 InnoDb 的運(yùn)行狀態(tài)到 mysqld 服務(wù)的錯(cuò)誤日志文件中。
InnoDb 的監(jiān)控較為重要的有標(biāo)準(zhǔn)監(jiān)控(Standard InnoDB Monitor)和 鎖監(jiān)控(InnoDB Lock Monitor)，通過對(duì)應(yīng)的系統(tǒng)參數(shù)可以將其開啟。
另外，MySQL 提供了一個(gè)系統(tǒng)參數(shù) innodb_print_all_deadlocks 專門用于記錄死鎖日志，當(dāng)發(fā)生死鎖時(shí)，死鎖日志會(huì)記錄到 MySQL 的錯(cuò)誤日志文件中。
另外，MySQL 提供了一個(gè)系統(tǒng)參數(shù) innodb_print_all_deadlocks 專門用于記錄死鎖日志，當(dāng)發(fā)生死鎖時(shí)，死鎖日志會(huì)記錄到 MySQL 的錯(cuò)誤日志文件中。
set GLOBAL innodb_print_all_deadlocks=ON;
死鎖日志的分析
通過上述手段，我們可以拿到死鎖日志，下圖是我做實(shí)驗(yàn)觸發(fā)死鎖異常時(shí)獲取的日志(省略的部分信息)。
該日志會(huì)列出死鎖發(fā)生的時(shí)間，死鎖相關(guān)的事務(wù)，并顯示出兩個(gè)事務(wù)(可惜，多事務(wù)發(fā)生死鎖時(shí)，也只顯示兩個(gè)事務(wù))在發(fā)生死鎖時(shí)執(zhí)行的 SQL 語(yǔ)句、持有或等待的鎖信息和最終回滾的事務(wù)。
下面，我們來(lái)一段一段的解讀該日志中給出的信息，我們按照?qǐng)D中標(biāo)注的順序來(lái)介紹：
- TRANSACTION 2078, ACTIVE 74 sec starting index read // -1 事務(wù)一的基礎(chǔ)信息，包括事務(wù)ID、活躍時(shí)間，當(dāng)前運(yùn)行狀態(tài)
表示的是 ACTIVE 74 sec 表示事務(wù)活動(dòng)時(shí)間，starting index read 為事務(wù)當(dāng)前正在運(yùn)行的狀態(tài)，可能的事務(wù)狀態(tài)有：fetching rows，updating，deleting，inserting, starting index read 等狀態(tài)。
其中第一行，tables in use 1 表示有一個(gè)表被使用，locked 1 表示有一個(gè)表鎖。第二行中的 LOCK WAIT 表示事務(wù)正在等待鎖，3 lock struct(s) 表示該事務(wù)的鎖鏈表的長(zhǎng)度為 3，每個(gè)鏈表節(jié)點(diǎn)代表該事務(wù)持有的一個(gè)鎖結(jié)構(gòu)，包括表鎖，記錄鎖或 autoinc 鎖等。heap size 1136 為事務(wù)分配的鎖堆內(nèi)存大小。
第二行后半段中，2 row lock(s) 表示當(dāng)前事務(wù)持有的行鎖個(gè)數(shù)，通過遍歷上面提到的 11 個(gè)鎖結(jié)構(gòu)，找出其中類型為 LOCK_REC 的記錄數(shù)。undo log entries 1 表示當(dāng)前事務(wù)有 1 個(gè) undo log 記錄，說明該事務(wù)已經(jīng)更新了 1條記錄。
下面就是死鎖日志中最為重要的持有或者待獲取鎖信息，如圖中-5和-6行所示，通過它可以分析鎖的具體類型和涉及的表，這些信息能輔助你按照系列文章的鎖相關(guān)的知識(shí)來(lái)分析 SQL 的鎖沖突。
在 《鎖類型和加鎖原理》 一文中我們說過，一共有四種類型的行鎖：記錄鎖，間隙鎖，Next-key 鎖和插入意向鎖。這四種鎖對(duì)應(yīng)的死鎖日志各不相同，如下：
- 記錄鎖(LOCK_REC_NOT_GAP): lock_mode X locks rec but not gap
- 間隙鎖(LOCK_GAP): lock_mode X locks gap before rec
- Next-key 鎖(LOCK_ORNIDARY): lock_mode X
- 插入意向鎖(LOCK_INSERT_INTENTION): lock_mode X locks gap before rec insert intention
所以，按照死鎖日志，我們發(fā)現(xiàn)事務(wù)一持有了 test.t 表上的記錄鎖，并且等待另一個(gè)記錄鎖。
通過死鎖日志，我們可以找到最終獲得鎖事務(wù)最后執(zhí)行的 SQL，但是如果該事務(wù)執(zhí)行了多條 SQL，這些信息就可能不夠用的啦，我們需要完整的了解該事務(wù)所有執(zhí)行的 SQL語(yǔ)句。這時(shí)，我們就需要從 binlog 日志中獲取。
binlog的獲取和分析
binlog 日志會(huì)完整記錄事務(wù)執(zhí)行的所有 SQL，借助它，我們就能找到最終獲取鎖事務(wù)所執(zhí)行的全部 SQL。然后再進(jìn)行具體的鎖沖突分析。
我們可以使用 MySQL 的命令行工具 Mysqlbinlog 遠(yuǎn)程獲取線上數(shù)據(jù)庫(kù)的 binlog 日志。具體命令如下所示：
- Mysqlbinlog -h127.0.0.1 -u root -p --read-from-remote-server binlog.000001 --base64-output=decode-rows -v
其中 --base64-output=decode-rows 表示 row 模式 binlog日志，所以該方法只適用于 row 模式的 binlog日志，但是目前主流 MySQL 運(yùn)維也都是把 binlog 日志設(shè)置為 row 模式，所以這點(diǎn)限制也就無(wú)傷大雅。-v 則表示將行事件重構(gòu)成被注釋掉的偽SQL語(yǔ)句。
我們可以通過死鎖日志中死鎖發(fā)生的具體事件和最終獲取鎖事務(wù)正在執(zhí)行的SQL的參數(shù)信息找到 binlog 中該事務(wù)的對(duì)應(yīng)信息，比如我們可以直接通過死鎖日志截圖中的具體的時(shí)間 10點(diǎn)57分和 Tom1、Teddy2 等 SQL 的具體數(shù)據(jù)信息在 binlog 找到對(duì)應(yīng)的位置，具體如下圖所示。
根據(jù) binlog 的具體信息，我們可以清晰的找到最終獲取鎖事務(wù)所執(zhí)行的所有 SQL 語(yǔ)句，也就能找到其對(duì)應(yīng)的業(yè)務(wù)代碼，接下來(lái)我們就能進(jìn)行具體的鎖沖突分析。
