分享IDB在執(zhí)行事務(wù)的過程中出現(xiàn)問題的排查經(jīng)過

背景

最近業(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)這個(gè)問題的原因是產(chǎn)生了懸掛事務(wù)。整個(gè)排查的過程也比較困難，因此和大家分享下排查問題的經(jīng)過。如果文中有錯(cuò)漏的地方，歡迎大家指正。

原理篇

? 什么是事務(wù)

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

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

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

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

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

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

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

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

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

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

當(dāng)事務(wù)提交之后會(huì)把所有修改信息都存到該日志文件中, 用于在刷新臟頁到磁盤,發(fā)生錯(cuò)誤時(shí), 進(jìn)行數(shù)據(jù)恢復(fù)使用。mysql在進(jìn)行修改操作的時(shí)候并不是直接進(jìn)行磁盤IO，因?yàn)槟菢有侍?。而是將修改操作寫到緩存區(qū)（redo log buffer）中，再在適合的時(shí)機(jī)進(jìn)行刷頁。為了防止緩存區(qū)中的數(shù)據(jù)因?yàn)橐馔忮e(cuò)誤丟失，所以會(huì)將緩沖區(qū)的數(shù)據(jù)寫入到redo 日志。

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

實(shí)踐篇

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

?起因

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

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

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

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

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

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

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

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

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

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

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

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

?復(fù)盤

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

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

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

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

ThreadLocal中的變量什么時(shí)候會(huì)被清除呢？當(dāng)commit和rollback的時(shí)候，ThreadLocal中的變量會(huì)被清理掉。

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

總結(jié)

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

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



審核編輯：劉清