背景

最近業(yè)務(wù)系統(tǒng)生產(chǎn)環(huán)境的IDB在執(zhí)行事務(wù)的過程中出現(xiàn)了ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 異常。通過相關(guān)資料的查詢和了解，發(fā)現(xiàn)出現(xiàn)這個問題的原因是產(chǎn)生了懸掛事務(wù)。整個排查的過程也比較困難，因此和大家分享下排查問題的經(jīng)過。如果文中有錯漏的地方，歡迎大家指正。

原理篇

? 什么是事務(wù)

首先介紹下事務(wù)的相關(guān)知識。什么是事務(wù)？事務(wù)就是用戶定義的一系列數(shù)據(jù)庫操作，這些操作可以視為一個完成的邏輯處理工作單元，要么全部執(zhí)行，要么全部不執(zhí)行，是不可分割的工作單元。

事務(wù)的的四大特性：原子性（Atomicity）、一致性(Consistency)、隔離性(Isolation)、持久性(Durability)。

mysql innodb引擎是如何實現(xiàn)上面四個特性的？

事務(wù)的隔離性由鎖機制+MVCC實現(xiàn)。

事務(wù)的原子性、一致性和持久性由事務(wù)的 redo 日志和undo 日志來保證。

mysql的鎖主要分為 共享鎖（S Lock）、排它鎖（X Lock）

共享鎖（S Lock）：共享鎖又稱為讀鎖，簡稱S鎖，共享鎖就是多個事務(wù)對于同一數(shù)據(jù)可以共享一把鎖，都能訪問到最新數(shù)據(jù)。但是不能執(zhí)行Update、Delete操作。

排它鎖（X Lock）：排它鎖又稱為寫鎖，簡稱X鎖，排它鎖不能與其它鎖并存，而且只有一個事務(wù)能拿到某一數(shù)據(jù)行的排它鎖，其余事務(wù)不能再獲取該數(shù)據(jù)行的所有鎖。一旦有一個事務(wù)獲取了該數(shù)據(jù)的排它鎖之后，其余事務(wù)對于該數(shù)據(jù)的操作將會被阻塞，直至鎖釋放。常見的排他鎖：行鎖、間隙鎖等等。

mysql的重要日志：redo log、undo log和binlog

redo log：重做日志，記錄的是事務(wù)提交時數(shù)據(jù)頁的物理修改，是用來實現(xiàn)事務(wù)的持久性。該日志文件由兩部分組成：重做日志緩沖（redo log buffer）以及重做日志文件（redo log file）,前者是在內(nèi)存中，后者在磁盤中。

當事務(wù)提交之后會把所有修改信息都存到該日志文件中, 用于在刷新臟頁到磁盤,發(fā)生錯誤時, 進行數(shù)據(jù)恢復(fù)使用。mysql在進行修改操作的時候并不是直接進行磁盤IO，因為那樣效率太低。而是將修改操作寫到緩存區(qū)（redo log buffer）中，再在適合的時機進行刷頁。為了防止緩存區(qū)中的數(shù)據(jù)因為意外錯誤丟失，所以會將緩沖區(qū)的數(shù)據(jù)寫入到redo 日志。

undo log：主要記錄的是數(shù)據(jù)的邏輯變化，為了在發(fā)生錯誤時回滾之前的操作，需要將之前的操作都記錄下來，然后在發(fā)生錯誤時才可以回滾。undo log和redo log記錄物理日志不一樣，它是邏輯日志。可以認為當delete一條記錄時，undo log中會記錄一條對應(yīng)的insert記錄，反之亦然，當update一條記錄時，它記錄一條對應(yīng)相反的update記錄。當執(zhí)行rollback時，就可以從undo log中的邏輯記錄讀取到相應(yīng)的內(nèi)容并進行回滾。

binlog: 歸檔日志，屬于邏輯日志，是以二進制的形式記錄的，用于記錄數(shù)據(jù)庫執(zhí)行的寫入性操作(不包括查詢)信息。binlog不僅會記錄insert操作，還會記錄對應(yīng)的反向操作delete，binlog提供基于時間點的數(shù)據(jù)恢復(fù)能力。

binlog的主要使用場景：主從復(fù)制和數(shù)據(jù)恢復(fù)。對于數(shù)據(jù)恢復(fù)場景，我們可以通過使用mysqlbinlog工具來恢復(fù)數(shù)據(jù)。集團內(nèi)的IDB的數(shù)據(jù)追蹤功能也是利用binlog實現(xiàn)的，可用于找回被誤操作的數(shù)據(jù)。

一次事務(wù)的執(zhí)行過程大致如下：

如上圖所示，事務(wù)執(zhí)行流程步驟（更新操作）：

查詢數(shù)據(jù)若Buffer Pool存在，則輸出，不存在則讀取磁盤中的數(shù)據(jù)并放入Buffer Pool；

更新操作，會先將數(shù)據(jù)的舊值寫入undo log，以便回滾。（保證原子性）；

更新Buffer Pool（內(nèi)存）數(shù)據(jù)；

將更新數(shù)據(jù)寫入到Redo Log Buffer（內(nèi)存中）；

準備提交事務(wù)，會調(diào)用fsync將Redo Log Buffer的值刷入到redo log日志文件中，狀態(tài)為prepare；

準備提交事務(wù)，binlog 日志寫入磁盤；

binlog寫入成功后，將redo log的狀態(tài)變更為commit；

在合適的時間，將Buffer Pool的數(shù)據(jù)刷盤；

? 什么是懸掛事務(wù)

正常的事務(wù)流程 （人為控制事務(wù)提交）：begin, rollback, commit。正常情況下的流程如下：

試想一下，如果我們開啟一個事務(wù)，但不rollback也不commit這個事務(wù)，會發(fā)生什么現(xiàn)象。答案是：事務(wù)將一直掛起，事務(wù)中獲得的鎖也不會被釋放，其他事務(wù)也無法操作被鎖定的數(shù)據(jù)，此時就產(chǎn)生了懸掛事務(wù)。伴隨著懸掛事務(wù)的產(chǎn)生，通常會出現(xiàn)ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 這個錯誤。下面舉個簡單的例子：

事務(wù)1會獲得id=2的行鎖，然后一直不釋放，事務(wù)1的會話將一直存在。事務(wù)2也要獲得id=2的行鎖，這時，事務(wù)2開始等待id=2的行鎖釋放，到了默認的超時時間50s（mysql的默認超時時間參數(shù)：

innodb_lock_wait_timeout=50），事務(wù)2拋出異常：ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 。事務(wù)1除了人為commit或者殺死該進程，否則事務(wù)1的進程永遠處于掛起狀態(tài)（即sleep狀態(tài)）。

? 懸掛事務(wù)產(chǎn)生的問題

如果一個數(shù)據(jù)庫連接中開啟事務(wù)且未顯式提交或回滾，在不考慮其他因素的前提下，只有在連接斷開的時候才會回滾或者將該事務(wù)的進程殺死，該事務(wù)才會被回滾。這樣一來，懸掛事務(wù)將會帶來兩個非常嚴重的問題。

懸掛事務(wù)不回滾，隨著用戶操作越來越多，懸掛事務(wù)也會不斷堆積，整張表被鎖的數(shù)據(jù)行也會越來越多。最終會導(dǎo)致這個表被完全鎖住。所有的后續(xù)事務(wù)都無法獲取鎖而導(dǎo)致獲取鎖超時，整個系統(tǒng)徹底崩潰。

懸掛事務(wù)回滾，當前這段時間內(nèi)，用戶提交的數(shù)據(jù)是無法找回的。參考上面的事務(wù)執(zhí)行過程，這個事務(wù)其實是被認為失敗了，被rollback掉了，也無法通過binlog找回丟失的數(shù)據(jù)。

實踐篇

在前半部分，我分享了有關(guān)懸掛事物的相關(guān)知識。下面我將分享一例生產(chǎn)環(huán)境中的關(guān)于懸掛事務(wù)的案例。

?起因

某日中午，釘釘報警群里面開始零星出現(xiàn) Lock wait timeout exceeded; try restarting transaction異常（如下圖所示）。立即開始排查問題，到了下午的時候，釘釘報警群開始大量出現(xiàn)無法獲得數(shù)據(jù)庫鏈接和獲取鎖超時異常，系統(tǒng)開始出現(xiàn)用戶無法提交數(shù)據(jù)的情況。我立即和團隊內(nèi)的小伙伴的開始緊急處理這個問題。

一開始的時候，通過查閱相關(guān)資料，已經(jīng)定位到產(chǎn)生問題的原因是產(chǎn)生了懸掛事務(wù)。那么懸掛事務(wù)怎么產(chǎn)生的呢？Spring提供了兩種實現(xiàn)事務(wù)的方式，@Transactional 注解 和 調(diào)用事務(wù)管理器的getTransaction方法。值得注意的是getTransaction需要自己控制commit和rollback邏輯。

而@Transactional注解則不需要。我們立即排查了最近上線的幾個需求是否使用了getTransaction這種人工控制事務(wù)的方式，因為手動控制事務(wù)的方式，極有可能會出現(xiàn)事務(wù)不commit的情況。通過排查，最近上線的需求沒有使用getTransaction這種人工控制事務(wù)，初步排除是最近上線的需求導(dǎo)致的。

我們再次開始排查系統(tǒng)中使用了getTransaction這種人工控制事務(wù)的方式的代碼，系統(tǒng)中大概有7-8處使用了這種方式，這些代碼最后一次提交日期大概是2020年，大致走查下來，也沒發(fā)現(xiàn)什么問題。其實很難通過這種方式排查出原因。

隨著時間的流逝，由于懸掛事務(wù)的存在導(dǎo)致其他正常的事務(wù)也無法執(zhí)行，數(shù)據(jù)庫中的活躍會話越來越多，越來越多的用戶無法提交數(shù)據(jù)。我們可以從活躍會話得到當前正在執(zhí)行的sql，導(dǎo)致這些sql無法提交的原因是前面的懸掛事務(wù)導(dǎo)致的，無法從當前眾多的活躍會話中提取到更多的有效信息。

我們立即聯(lián)系DBA，協(xié)助解決問題。DBA確認了懸掛事務(wù)的存在（部分事務(wù)執(zhí)行了3個多小時一直未提交），由于這些進程處于sleep狀態(tài)，DBA也無法找出關(guān)聯(lián)的sql。事后，查閱了相關(guān)資料，發(fā)現(xiàn)下面的方法可以找出“可能”的懸掛事務(wù)。我們請求DBA將這些懸掛事務(wù)的進程全部殺掉（即使不殺掉，這些事務(wù)也無法被 commit）。

隨著懸掛事務(wù)的進程被清理掉之后，數(shù)據(jù)庫活躍會話開始逐漸減少，系統(tǒng)開始正常工作。然而，好景不長，因為一直沒找到產(chǎn)生懸掛事務(wù)的根源，大約10分鐘后又開始出現(xiàn)了Lock wait timeout exceeded; try restarting transaction異常。

我嘗試從SLS日志（我們系統(tǒng)的所有日志均會被采集到SLS日志系統(tǒng)中）出發(fā)，看看能否找到錯誤日志從而定位到問題。我重點查看了系統(tǒng)恢復(fù)到再次發(fā)生問題的這段時間的所有日志，終于發(fā)現(xiàn)下圖這個異常。其實這段時間內(nèi)系統(tǒng)的亂七八糟異常信息很多。

能重點注意到這個異常的主要的原因主要是在第2步的時候，我對這段代碼（AddServiceToCart）有點印象，記得這段代碼好像使用的是手動事務(wù)控制事務(wù)的。

重點查看AddServiceToCart這段代碼，立即發(fā)現(xiàn)問題。這段代碼大致下面這樣的方式實現(xiàn)的。

在jsonObject.getLong("quota")時，quota不是Long型，jsonObject.getLong拋出RuntimeException，由于異常沒有被捕獲，事務(wù)的rollback和commit都沒被執(zhí)行，這樣這個事務(wù)就會一直存在。除了應(yīng)用重啟和人工殺掉該事務(wù)的進程，讓這個事務(wù)回滾，沒有其他辦法。

而這樣做帶來的后果是這段時間內(nèi)用戶提交的數(shù)據(jù)都會丟失。如果想要找回，可能只能自己通過應(yīng)用日志，自己將丟失的數(shù)據(jù)找回，然后人工將數(shù)據(jù)重新錄入。通過mysql的binlog是無法直接找回的。

?復(fù)盤

從前面的實踐篇章節(jié)中，我們很容易知道兩個事務(wù)要操作相同行的數(shù)據(jù)會產(chǎn)生鎖等待的情況。那么是不是意味著上面的代碼只會影響到自己事務(wù)里面的表呢？現(xiàn)在假設(shè)上面的代碼只會用到A表，那么是不是同一數(shù)據(jù)庫中的其他的B、C、D表是不是不受影響呢。先揭曉答案：會受到影響，B、C、D表的數(shù)據(jù)行也會被鎖。這是為啥？

首先介紹一下Spring的事務(wù)的實現(xiàn)機制。

Spring事務(wù)是如何保證iBatis執(zhí)行sql時，這些sql用的是相同的Connection？答案是：ThreadLocal。在執(zhí)行完doBegin方法后，其實是通過bindResouce方法將從DruidDataSource連接池中獲得的鏈接放入當前線程的TheadLocal,這里的TheadLocal中存放的是一個Map, key是dataSouce，value是connectionHolder（connectionHolder中持有Connection的引用。近似認為connectionHolder和Connection是一回事）。

IBatis在執(zhí)行sql時，通過DataSourceUtils.getConnection獲取數(shù)據(jù)庫鏈接。這里會優(yōu)先從當前線程的ThreadLocal中獲取，如果獲取不到，從數(shù)據(jù)源中獲取。

ThreadLocal中的變量什么時候會被清除呢？當commit和rollback的時候，ThreadLocal中的變量會被清理掉。

從上面的分析過程中，可以看出，當事務(wù)沒有被commit和rollback的時候，當前線程可能會有上次殘留的ThreadLocal的。因為當前線程是從線程池中獲取的，線程是會被復(fù)用的。如果當前線程之前執(zhí)行的事務(wù)沒有被正確commit或者rollback的話，現(xiàn)在繼續(xù)要獲取鏈接并執(zhí)行sql，由于上次是開啟了事務(wù)且未提交，這次的sql也會被認為進入事務(wù)，這些sql也會鎖住相應(yīng)的數(shù)據(jù)行，這樣就造成數(shù)據(jù)庫中大面積的表被鎖。

總結(jié)

盡量不使用getTransaction這種人工控制事務(wù)（這種方式比較容易埋坑，推薦使用@Transactional ），如果要使用，請務(wù)必要try catch。一定注意提前return的問題（由于提前return導(dǎo)致rollback和commit都沒被執(zhí)行，這種case也很常見）。否則萬一出問題，可能真的很頭大；

參數(shù)校驗一定要嚴謹，任何類型轉(zhuǎn)化的地方不做類型檢查可能都會產(chǎn)生異常；



審核編輯：劉清