MySQL死鎖系列-線上死鎖問題排查思路

程式設計師歷小冰發表於2020-10-19
MySql

前言

MySQL 死鎖異常是我們經常會遇到的線上異常類別，一旦線上業務日間複雜，各種業務操作之間往往會產生鎖衝突，有些會導致死鎖異常。這種死鎖異常一般要在特定時間特定資料和特定業務操作才會復現，並且分析解決時還需要了解 MySQL 鎖衝突相關知識，所以一般遇到這些偶爾出現的死鎖異常，往往一時沒有頭緒，不好處理。

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

正文

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

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

  1. 線上錯誤日誌報警發現死鎖異常

  2. 檢視錯誤日誌的堆疊資訊

  3. 檢視 MySQL 死鎖相關的日誌

  4. 根據 binlog 檢視死鎖相關事務的執行內容

  5. 根據上述資訊找出兩個相互死鎖的事務執行的 SQL 操作，根據本系列介紹的鎖相關理論知識，進行分析推斷死鎖原因

  6. 修改業務程式碼

根據1，2步驟可以找到死鎖異常時進行回滾事務的具體業務，也就能夠找到該事務執行的 SQL 語句。然後我們需要通過 3，4步驟找到死鎖異常時另外一個事務，也就是最終獲得鎖的事務所執行的 SQL 語句，然後再進行鎖衝突相關的分析。

第一二步的線上錯誤日誌和堆疊資訊一般比較容易獲得，第五步的分析 SQL 鎖衝突原因中涉及的鎖相關的理論在系列文章中都有介紹，沒有了解的同學可以自行去閱讀以下。

下面我們就來重點說一下其中的第三四步驟，也就是如何檢視死鎖日誌和 binlog 日誌來找到死鎖相關的 SQL 操作。

死鎖日誌的獲取

發生死鎖異常後，我們可以直接使用 show engine innodb status 命令獲取死鎖資訊，但是該命令只能獲取最近一次的死鎖資訊。所以，我們可以通過開啟 InnoDB 的監控機制來獲取實時的死鎖資訊，它會週期性（每隔 15 秒）列印 InnoDb 的執行狀態到 mysqld 服務的錯誤日誌檔案中。

InnoDb 的監控較為重要的有標準監控（Standard InnoDB Monitor）和 鎖監控（InnoDB Lock Monitor），通過對應的系統引數可以將其開啟。

-- 開啟標準監控
set GLOBAL innodb_status_output=ON;
-- 關閉標準監控
set GLOBAL innodb_status_output=OFF;
-- 開啟鎖監控
set GLOBAL innodb_status_output_locks=ON;
-- 關閉鎖監控
set GLOBAL innodb_status_output_locks=OFF;

另外，MySQL 提供了一個系統引數 innodb_print_all_deadlocks 專門用於記錄死鎖日誌，當發生死鎖時，死鎖日誌會記錄到 MySQL 的錯誤日誌檔案中。

set GLOBAL innodb_print_all_deadlocks=ON;

死鎖日誌的分析

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

該日誌會列出死鎖發生的時間，死鎖相關的事務，並顯示出兩個事務(可惜，多事務發生死鎖時，也只顯示兩個事務)在發生死鎖時執行的 SQL 語句、持有或等待的鎖資訊和最終回滾的事務。

下面，我們來一段一段的解讀該日誌中給出的資訊，我們按照圖中標註的順序來介紹：

TRANSACTION 2078, ACTIVE 74 sec starting index read // -1 事務一的基礎資訊，包括事務ID、活躍時間，當前執行狀態

表示的是 ACTIVE 74 sec 表示事務活動時間，starting index read 為事務當前正在執行的狀態，可能的事務狀態有：fetching rows，updating，deleting，inserting, starting index read 等狀態。

mysql tables in use 1, locked 1  // -2 使用一個table，並且有一個表鎖
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1  // -3 涉及的鎖結構和記憶體大小

tables in use 1 表示有一個表被使用，locked 1 表示有一個表鎖。LOCK WAIT 表示事務正在等待鎖，3 lock struct(s) 表示該事務的鎖連結串列的長度為 3，每個連結串列節點代表該事務持有的一個鎖結構，包括表鎖，記錄鎖或 autoinc 鎖等。heap size 1136 為事務分配的鎖堆記憶體大小。

2 row lock(s) 表示當前事務持有的行鎖個數，通過遍歷上面提到的 11 個鎖結構，找出其中型別為 LOCK_REC 的記錄數。undo log entries 1 表示當前事務有 1 個 undo log 記錄，說明該事務已經更新了 1條記錄。

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

RECORD LOCKS space id 2 page no 4 n bits 80 index PRIMARY of table `test`.`t` trx id 2078 lock_mode X locks rec but not gap  // -5 具體持有鎖的資訊
RECORD LOCKS space id 2 page no 4 n bits 80 index PRIMARY of table `test`.`t` trx id 2078 lock_mode X locks rec but not gap waiting // -6 等待獲取鎖的資訊

在 《鎖型別和加鎖原理》 一文中我們說過，一共有四種型別的行鎖：記錄鎖，間隙鎖，Next-key 鎖和插入意向鎖。這四種鎖對應的死鎖日誌各不相同，如下：

  • 記錄鎖（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

所以，按照死鎖日誌，我們發現事務一持有了 test.t 表上的記錄鎖，並且等待另一個記錄鎖。

通過死鎖日誌，我們可以找到最終獲得鎖事務最後執行的 SQL，但是如果該事務執行了多條 SQL，這些資訊就可能不夠用的啦，我們需要完整的瞭解該事務所有執行的 SQL語句。這時，我們就需要從 binlog 日誌中獲取。

binlog的獲取和分析

binlog 日誌會完整記錄事務執行的所有 SQL，藉助它，我們就能找到最終獲取鎖事務所執行的全部 SQL。然後再進行具體的鎖衝突分析。

我們可以使用 MySQL 的命令列工具 Mysqlbinlog 遠端獲取線上資料庫的 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 日誌設定為 row 模式，所以這點限制也就無傷大雅。-v 則表示將行事件重構成被註釋掉的偽SQL語句。

我們可以通過死鎖日誌中死鎖發生的具體事件和最終獲取鎖事務正在執行的SQL的引數資訊找到 binlog 中該事務的對應資訊，比如我們可以直接通過死鎖日誌截圖中的具體的時間 10點57分和 Tom1、Teddy2 等 SQL 的具體資料資訊在 binlog 找到對應的位置，具體如下圖所示。

根據 binlog 的具體資訊，我們可以清晰的找到最終獲取鎖事務所執行的所有 SQL 語句，也就能找到其對應的業務程式碼，接下來我們就能進行具體的鎖衝突分析。

小節

死鎖系列終於告一段落，如果大夥有什麼疑問或者文中有什麼錯誤，歡迎在下方留言討論。也希望大家繼續持續關注。

個人部落格，歡迎來玩

相關文章