mysql 懸掛事務問題

本文將和大家分享 IDB 在執行事務的過程中出現問題的排查經過,主要包括原理和實踐兩部分。

背景

最近業務系統生產環境的 IDB 在執行事務的過程中出現了 ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 異常。通過相關資料的查詢和了解,發現出現這個問題的原因是產生了懸掛事務。整個排查的過程也比較困難,因此和大家分享下排查問題的經過。如果文中有錯漏的地方,歡迎大家指正。

原理篇

什麼是事務

首先介紹下事務的相關知識。什麼是事務?事務就是用戶定義的一系列數據庫操作,這些操作可以視爲一個完成的邏輯處理工作單元,要麼全部執行,要麼全部不執行,是不可分割的工作單元。

事務的的四大特性:原子性(Atomicity)、一致性 (Consistency)、隔離性 (Isolation)、持久性 (Durability)。

mysql innodb 引擎是如何實現上面四個特性的?

  1. 事務的隔離性由鎖機制 + MVCC 實現。

  2. 事務的原子性、一致性和持久性由事務的 redo 日誌和 undo 日誌來保證。

mysql 的鎖主要分爲 共享鎖(S Lock)、排它鎖(X Lock)

  1. 共享鎖(S Lock):共享鎖又稱爲讀鎖,簡稱 S 鎖,共享鎖就是多個事務對於同一數據可以共享一把鎖,都能訪問到最新數據。但是不能執行 Update、Delete 操作。

  2. 排它鎖(X Lock):排它鎖又稱爲寫鎖,簡稱 X 鎖,排它鎖不能與其它鎖並存,而且只有一個事務能拿到某一數據行的排它鎖,其餘事務不能再獲取該數據行的所有鎖。一旦有一個事務獲取了該數據的排它鎖之後,其餘事務對於該數據的操作將會被阻塞,直至鎖釋放。常見的排他鎖:行鎖、間隙鎖等等。

mysql 的重要日誌:redo log、undo log 和 binlog

  1. redo log:重做日誌,記錄的是事務提交時數據頁的物理修改,是用來實現事務的持久性。該日誌文件由兩部分組成:重做日誌緩衝(redo log buffer)以及重做日誌文件(redo log file), 前者是在內存中,後者在磁盤中。當事務提交之後會把所有修改信息都存到該日誌文件中, 用於在刷新髒頁到磁盤, 發生錯誤時, 進行數據恢復使用。mysql 在進行修改操作的時候並不是直接進行磁盤 IO,因爲那樣效率太低。而是將修改操作寫到緩存區(redo log buffer)中,再在適合的時機進行刷頁。爲了防止緩存區中的數據因爲意外錯誤丟失,所以會將緩衝區的數據寫入到 redo 日誌。

  2. undo log:主要記錄的是數據的邏輯變化,爲了在發生錯誤時回滾之前的操作,需要將之前的操作都記錄下來,然後在發生錯誤時纔可以回滾。undo log 和 redo log 記錄物理日誌不一樣,它是邏輯日誌。可以認爲當 delete 一條記錄時,undo log 中會記錄一條對應的 insert 記錄,反之亦然,當 update 一條記錄時,它記錄一條對應相反的 update 記錄。當執行 rollback 時,就可以從 undo log 中的邏輯記錄讀取到相應的內容並進行回滾。

  3. binlog: 歸檔日誌,屬於邏輯日誌,是以二進制的形式記錄的,用於記錄數據庫執行的寫入性操作 (不包括查詢) 信息。binlog 不僅會記錄 insert 操作,還會記錄對應的反向操作 delete,binlog 提供基於時間點的數據恢復能力。binlog 的主要使用場景:主從複製和數據恢復。對於數據恢復場景,我們可以通過使用 mysqlbinlog 工具來恢復數據。集團內的 IDB 的數據追蹤功能也是利用 binlog 實現的,可用於找回被誤操作的數據。

一次事務的執行過程大致如下:

如上圖所示,事務執行流程步驟(更新操作):

  1. 查詢數據若 Buffer Pool 存在,則輸出,不存在則讀取磁盤中的數據並放入 Buffer Pool;

  2. 更新操作,會先將數據的舊值寫入 undo log,以便回滾。(保證原子性);

  3. 更新 Buffer Pool(內存)數據;

  4. 將更新數據寫入到 Redo Log Buffer(內存中);

  5. 準備提交事務,會調用 fsync 將 Redo Log Buffer 的值刷入到 redo log 日誌文件中,狀態爲 prepare;

  6. 準備提交事務,binlog 日誌寫入磁盤;

  7. binlog 寫入成功後,將 redo log 的狀態變更爲 commit;

  8. 在合適的時間,將 Buffer Pool 的數據刷盤;

什麼是懸掛事務

正常的事務流程 (人爲控制事務提交):begin, rollback, commit。正常情況下的流程如下:

beginTransaction();
----一頓操作-------
if(操作成功) {
  commit();
}else {
  rollback();
}

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

//事務1
set @@autocommit=0;
BEGIN;
UPDATE student SET age = 11 WHERE id = 2;
//事務2
set @@autocommit=0;
BEGIN;
UPDATE student SET age = 11 WHERE id = 2;

事務 1 會獲得 id=2 的行鎖,然後一直不釋放,事務 1 的會話將一直存在。事務 2 也要獲得 id=2 的行鎖,這時,事務 2 開始等待 id=2 的行鎖釋放,到了默認的超時時間 50s(mysql 的默認超時時間參數:innodb_lock_wait_timeout=50),事務 2 拋出異常:ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 。事務 1 除了人爲 commit 或者殺死該進程,否則事務 1 的進程永遠處於掛起狀態(即 sleep 狀態)。

懸掛事務產生的問題

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

  1. 懸掛事務不回滾,隨着用戶操作越來越多,懸掛事務也會不斷堆積,整張表被鎖的數據行也會越來越多。最終會導致這個表被完全鎖住。所有的後續事務都無法獲取鎖而導致獲取鎖超時,整個系統徹底崩潰。

  2. 懸掛事務回滾,當前這段時間內,用戶提交的數據是無法找回的。參考上面的事務執行過程,這個事務其實是被認爲失敗了,被 rollback 掉了,也無法通過 binlog 找回丟失的數據。

實踐篇

在前半部分,我分享了有關懸掛事物的相關知識。下面我將分享一例生產環境中的關於懸掛事務的案例。

▐  起因

某日中午,釘釘報警羣裏面開始零星出現 Lock wait timeout exceeded; try restarting transaction 異常(如下圖所示)。立即開始排查問題,到了下午的時候,釘釘報警羣開始大量出現無法獲得數據庫鏈接和獲取鎖超時異常,系統開始出現用戶無法提交數據的情況。我立即和團隊內的小夥伴的開始緊急處理這個問題。

▐  排查經過

  1. 一開始的時候,通過查閱相關資料,已經定位到產生問題的原因是產生了懸掛事務。那麼懸掛事務怎麼產生的呢?Spring 提供了兩種實現事務的方式,@Transactional 註解 和 調用事務管理器的 getTransaction 方法。值得注意的是 getTransaction 需要自己控制 commit 和 rollback 邏輯。而 @Transactional 註解則不需要。我們立即排查了最近上線的幾個需求是否使用了 getTransaction 這種人工控制事務的方式,因爲手動控制事務的方式,極有可能會出現事務不 commit 的情況。通過排查,最近上線的需求沒有使用 getTransaction 這種人工控制事務,初步排除是最近上線的需求導致的。

  2. 我們再次開始排查系統中使用了 getTransaction 這種人工控制事務的方式的代碼,系統中大概有 7-8 處使用了這種方式,這些代碼最後一次提交日期大概是 2020 年,大致走查下來,也沒發現什麼問題。其實很難通過這種方式排查出原因。

  3. 隨着時間的流逝,由於懸掛事務的存在導致其他正常的事務也無法執行,數據庫中的活躍會話越來越多,越來越多的用戶無法提交數據。我們可以從活躍會話得到當前正在執行的 sql,導致這些 sql 無法提交的原因是前面的懸掛事務導致的,無法從當前衆多的活躍會話中提取到更多的有效信息。我們立即聯繫 DBA,協助解決問題。DBA 確認了懸掛事務的存在(部分事務執行了 3 個多小時一直未提交),由於這些進程處於 sleep 狀態,DBA 也無法找出關聯的 sql。事後,查閱了相關資料,發現下面的方法可以找出 “可能” 的懸掛事務。我們請求 DBA 將這些懸掛事務的進程全部殺掉(即使不殺掉,這些事務也無法被 commit)。

    //查詢mysql當前的所有進程
    SHOW PROCESSLIST;
    //查詢出執行時間超過10s未提交的事務
    SELECT t.trx_mysql_thread_id
    ,t.trx_state
    ,t.trx_tables_in_use
    ,t.trx_tables_locked
    ,t.trx_query
    ,t.trx_rows_locked
    ,t.trx_rows_modified
    ,t.trx_lock_structs
    ,t.trx_started
    ,t.trx_isolation_level
    ,p.time
    ,p.user
    ,p.host
    ,p.db
    ,p.command
    FROM   information_schema.innodb_trx t
    INNER JOIN information_schema.processlist p
    ON t.trx_mysql_thread_id = p.id
    WHERE  t.trx_state = 'RUNNING'
    AND p.time > 10
    AND p.command = 'Sleep'
  4. 隨着懸掛事務的進程被清理掉之後,數據庫活躍會話開始逐漸減少,系統開始正常工作。然而,好景不長,因爲一直沒找到產生懸掛事務的根源,大約 10 分鐘後又開始出現了 Lock wait timeout exceeded; try restarting transaction 異常。我嘗試從 SLS 日誌(我們系統的所有日誌均會被採集到 SLS 日誌系統中)出發,看看能否找到錯誤日誌從而定位到問題。我重點查看了系統恢復到再次發生問題的這段時間的所有日誌,終於發現下圖這個異常。其實這段時間內系統的亂七八糟異常信息很多。能重點注意到這個異常的主要的原因主要是在第 2 步的時候,我對這段代碼(AddServiceToCart)有點印象,記得這段代碼好像使用的是手動事務控制事務的。 

  5. 重點查看 AddServiceToCart 這段代碼,立即發現問題。這段代碼大致下面這樣的方式實現的。

    //參數校驗
    DefaultTransactionDefinition definition = new DefaultTransactionDefinition();
    TransactionStatus status = transactionManager.getTransaction(definition);
    Long quota = jsonObject.getLong("quota");
    transactionManager.commit(status);

在 jsonObject.getLong("quota") 時,quota 不是 Long 型,jsonObject.getLong 拋出 RuntimeException,由於異常沒有被捕獲,事務的 rollback 和 commit 都沒被執行,這樣這個事務就會一直存在。除了應用重啓和人工殺掉該事務的進程,讓這個事務回滾,沒有其他辦法。而這樣做帶來的後果是這段時間內用戶提交的數據都會丟失。如果想要找回,可能只能自己通過應用日誌,自己將丟失的數據找回,然後人工將數據重新錄入。通過 mysql 的 binlog 是無法直接找回的。

▐  覆盤

從前面的實踐篇章節中,我們很容易知道兩個事務要操作相同行的數據會產生鎖等待的情況。那麼是不是意味着上面的代碼只會影響到自己事務裏面的表呢?現在假設上面的代碼只會用到 A 表,那麼是不是同一數據庫中的其他的 B、C、D 表是不是不受影響呢。先揭曉答案:會受到影響,B、C、D 表的數據行也會被鎖。這是爲啥?

首先介紹一下 Spring 的事務的實現機制。

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

IBatis 在執行 sql 時,通過 DataSourceUtils.getConnection 獲取數據庫鏈接。這裏會優先從當前線程的 ThreadLocal 中獲取,如果獲取不到,從數據源中獲取。

ThreadLocal 中的變量什麼時候會被清除呢?當 commit 和 rollback 的時候,ThreadLocal 中的變量會被清理掉。

從上面的分析過程中,可以看出,當事務沒有被 commit 和 rollback 的時候,當前線程可能會有上次殘留的 ThreadLocal 的。因爲當前線程是從線程池中獲取的,線程是會被複用的。如果當前線程之前執行的事務沒有被正確 commit 或者 rollback 的話,現在繼續要獲取鏈接並執行 sql,由於上次是開啓了事務且未提交,這次的 sql 也會被認爲進入事務,這些 sql 也會鎖住相應的數據行,這樣就造成數據庫中大面積的表被鎖。

總結

  1. 儘量不使用 getTransaction 這種人工控制事務(這種方式比較容易埋坑,推薦使用 @Transactional ),如果要使用,請務必要 try catch。一定注意提前 return 的問題(由於提前 return 導致 rollback 和 commit 都沒被執行,這種 case 也很常見)。否則萬一出問題,可能真的很頭大;

  2. 參數校驗一定要嚴謹,任何類型轉化的地方不做類型檢查可能都會產生異常;

團隊介紹

我們是阿里巴巴大淘寶技術的新品平臺技術團隊, 依託於淘寶天貓正在建立一套完整的涵蓋消費者洞察、宏觀及細分市場分析、競爭分析、市場策略研究、產品創新機制等的新品研發和創新孵化平臺, 爲品牌、商家及行業提供規模化的新品孵化和運營能力, 沉澱新品孵化機制和運營策略, 最終建立起一套基於數據驅動的從市場研究、新品研發到新品投放營銷的全鏈路新品運營平臺。

作者 | 羅輝(皓輝)

編輯 | 橙子君

本文由 Readfog 進行 AMP 轉碼,版權歸原作者所有。
來源https://mp.weixin.qq.com/s/d339-bmhBMGmKTE9RCTx5g