[[344555]]

本文轉(zhuǎn)載自微信公眾號「程序員歷小冰」，作者歷小冰 。轉(zhuǎn)載本文請聯(lián)系程序員歷小冰公眾號。  

前言

MySQL 死鎖異常是我們經(jīng)常會遇到的線上異常類別，一旦線上業(yè)務(wù)日間復(fù)雜，各種業(yè)務(wù)操作之間往往會產(chǎn)生鎖沖突，有些會導(dǎo)致死鎖異常。這種死鎖異常一般要在特定時間特定數(shù)據(jù)和特定業(yè)務(wù)操作才會復(fù)現(xiàn)，并且分析解決時還需要了解 MySQL 鎖沖突相關(guān)知識，所以一般遇到這些偶爾出現(xiàn)的死鎖異常，往往一時沒有頭緒，不好處理。

本篇文章會講解一下如果線上發(fā)生了死鎖異常，如何去排查和處理。除了系列前文講解的有關(guān)加鎖和鎖沖突的原理還，還需要對 MySQl 死鎖日志和 binlog 日志進行分析。

正文日常工作中，應(yīng)對各類線上異常都要有我們自己的 SOP (標準作業(yè)流程) ，這樣不僅能夠提高自己的處理問題效率，也有助于將好的處理流程推廣到團隊，提高團隊的整體處理異常能力。

所以，面對線上偶發(fā)的 MySQL 死鎖問題，我的排查處理過程如下：

1. 線上錯誤日志報警發(fā)現(xiàn)死鎖異常
2. 查看錯誤日志的堆棧信息
3. 查看 MySQL 死鎖相關(guān)的日志
4. 根據(jù) binlog 查看死鎖相關(guān)事務(wù)的執(zhí)行內(nèi)容
5. 根據(jù)上述信息找出兩個相互死鎖的事務(wù)執(zhí)行的 SQL 操作，根據(jù)本系列介紹的鎖相關(guān)理論知識，進行分析推斷死鎖原因
6. 修改業(yè)務(wù)代碼

根據(jù)1，2步驟可以找到死鎖異常時進行回滾事務(wù)的具體業(yè)務(wù)，也就能夠找到該事務(wù)執(zhí)行的 SQL 語句。然后我們需要通過 3，4步驟找到死鎖異常時另外一個事務(wù)，也就是最終獲得鎖的事務(wù)所執(zhí)行的 SQL 語句，然后再進行鎖沖突相關(guān)的分析。

第一二步的線上錯誤日志和堆棧信息一般比較容易獲得，第五步的分析 SQL 鎖沖突原因中涉及的鎖相關(guān)的理論在系列文章中都有介紹，沒有了解的同學(xué)可以自行去閱讀以下。

下面我們就來重點說一下其中的第三四步驟，也就是如何查看死鎖日志和 binlog 日志來找到死鎖相關(guān)的 SQL 操作。

死鎖日志的獲取

發(fā)生死鎖異常后，我們可以直接使用 show engine innodb status 命令獲取死鎖信息，但是該命令只能獲取最近一次的死鎖信息。所以，我們可以通過開啟 InnoDB 的監(jiān)控機制來獲取實時的死鎖信息，它會周期性(每隔 15 秒)打印 InnoDb 的運行狀態(tài)到 mysqld 服務(wù)的錯誤日志文件中。

InnoDb 的監(jiān)控較為重要的有標準監(jiān)控(Standard InnoDB Monitor)和 鎖監(jiān)控(InnoDB Lock Monitor)，通過對應(yīng)的系統(tǒng)參數(shù)可以將其開啟。

另外，MySQL 提供了一個系統(tǒng)參數(shù) innodb_print_all_deadlocks 專門用于記錄死鎖日志，當(dāng)發(fā)生死鎖時，死鎖日志會記錄到 MySQL 的錯誤日志文件中。

另外，MySQL 提供了一個系統(tǒng)參數(shù) innodb_print_all_deadlocks 專門用于記錄死鎖日志，當(dāng)發(fā)生死鎖時，死鎖日志會記錄到 MySQL 的錯誤日志文件中。

set GLOBAL innodb_print_all_deadlocks=ON;

死鎖日志的分析

通過上述手段，我們可以拿到死鎖日志，下圖是我做實驗觸發(fā)死鎖異常時獲取的日志(省略的部分信息)。

該日志會列出死鎖發(fā)生的時間，死鎖相關(guān)的事務(wù)，并顯示出兩個事務(wù)(可惜，多事務(wù)發(fā)生死鎖時，也只顯示兩個事務(wù))在發(fā)生死鎖時執(zhí)行的 SQL 語句、持有或等待的鎖信息和最終回滾的事務(wù)。

下面，我們來一段一段的解讀該日志中給出的信息，我們按照圖中標注的順序來介紹：

TRANSACTION 2078, ACTIVE 74 sec starting index read // -1 事務(wù)一的基礎(chǔ)信息，包括事務(wù)ID、活躍時間，當(dāng)前運行狀態(tài) 

表示的是 ACTIVE 74 sec 表示事務(wù)活動時間，starting index read 為事務(wù)當(dāng)前正在運行的狀態(tài)，可能的事務(wù)狀態(tài)有：fetching rows，updating，deleting，inserting, starting index read 等狀態(tài)。

其中第一行，tables in use 1 表示有一個表被使用，locked 1 表示有一個表鎖。第二行中的 LOCK WAIT 表示事務(wù)正在等待鎖，3 lock struct(s) 表示該事務(wù)的鎖鏈表的長度為 3，每個鏈表節(jié)點代表該事務(wù)持有的一個鎖結(jié)構(gòu)，包括表鎖，記錄鎖或 autoinc 鎖等。heap size 1136 為事務(wù)分配的鎖堆內(nèi)存大小。

第二行后半段中，2 row lock(s) 表示當(dāng)前事務(wù)持有的行鎖個數(shù)，通過遍歷上面提到的 11 個鎖結(jié)構(gòu)，找出其中類型為 LOCK_REC 的記錄數(shù)。undo log entries 1 表示當(dāng)前事務(wù)有 1 個 undo log 記錄，說明該事務(wù)已經(jīng)更新了 1條記錄。

下面就是死鎖日志中最為重要的持有或者待獲取鎖信息，如圖中-5和-6行所示，通過它可以分析鎖的具體類型和涉及的表，這些信息能輔助你按照系列文章的鎖相關(guān)的知識來分析 SQL 的鎖沖突。

在 《鎖類型和加鎖原理》 一文中我們說過，一共有四種類型的行鎖：記錄鎖，間隙鎖，Next-key 鎖和插入意向鎖。這四種鎖對應(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 表上的記錄鎖，并且等待另一個記錄鎖。

通過死鎖日志，我們可以找到最終獲得鎖事務(wù)最后執(zhí)行的 SQL，但是如果該事務(wù)執(zhí)行了多條 SQL，這些信息就可能不夠用的啦，我們需要完整的了解該事務(wù)所有執(zhí)行的 SQL語句。這時，我們就需要從 binlog 日志中獲取。

binlog的獲取和分析

binlog 日志會完整記錄事務(wù)執(zhí)行的所有 SQL，借助它，我們就能找到最終獲取鎖事務(wù)所執(zhí)行的全部 SQL。然后再進行具體的鎖沖突分析。

我們可以使用 MySQL 的命令行工具 Mysqlbinlog 遠程獲取線上數(shù)據(jù)庫的 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 運維也都是把 binlog 日志設(shè)置為 row 模式，所以這點限制也就無傷大雅。-v 則表示將行事件重構(gòu)成被注釋掉的偽SQL語句。

我們可以通過死鎖日志中死鎖發(fā)生的具體事件和最終獲取鎖事務(wù)正在執(zhí)行的SQL的參數(shù)信息找到 binlog 中該事務(wù)的對應(yīng)信息，比如我們可以直接通過死鎖日志截圖中的具體的時間 10點57分和 Tom1、Teddy2 等 SQL 的具體數(shù)據(jù)信息在 binlog 找到對應(yīng)的位置，具體如下圖所示。

根據(jù) binlog 的具體信息，我們可以清晰的找到最終獲取鎖事務(wù)所執(zhí)行的所有 SQL 語句，也就能找到其對應(yīng)的業(yè)務(wù)代碼，接下來我們就能進行具體的鎖沖突分析。