一次TiDB GC阻塞引發的效能問題分析

balahoho發表於2022-12-20

背景

前不久從專案一線同學得到某叢集的告警資訊,某個時間段 TiDB duration 突然異常升高,持續時間6小時左右,需要定位到具體原因。

分析過程

第一招,初步判斷

由於專案條件苛刻,歷經苦難才拿到監控,在此之前只能靠現場同學的口述排查,oncall人太難了。。

既然是duration升高,那就先看看叢集的心電圖,試圖找出一點線索。一般來說,duration升高會有以下兩種情況。

第一種是高百分位(比如99、999)明顯升高,類似這種:

企業微信截圖_20221026104829.png

它的特點是除了高百分位異常,低分位線沒有明顯波動,這是典型的長尾反應,分位線越高波動越大,說明叢集那段時間慢SQL變多,重點關注慢查詢輔助排查其他監控即可。

第二種是所有分位線都有明顯升高,類似這種:

企業微信截圖_20221026110952.png

這說明叢集內部受到了影響,慢SQL不是導致duration上升的根本原因,而是叢集異常表現出來的結果。但是慢查詢依然是我們著手排查的方向之一,慢日誌裡面記錄了慢的一些主要原因,可以作為參考依據。

這個案例碰到的就是第二種。

第二招,用監控還原SQL流程

如果暫時沒有什麼明確排查目標,可以先按SQL讀寫流程看一下主要的監控。通常在一個業務系統裡,讀請求是明顯要多於寫請求的,所以可以從讀流程開始排查,先是TiDB再是TiKV。

推薦參考社群的Trouble Shooting系列文章,非常實用:

詳細流程不再贅述。把這一招用完,基本就能定位到問題了,再結合一些非資料庫因素,查明真相指日可待。

針對本次案例中,說一下監控排查結論:

1、問題時間段TPS、QPS相較正常情況無明顯波動,各項資源使用率平穩,排除TiDB Server的問題

2、問題時間段TiKV節點負載變大,CPU、磁碟、出口頻寬使用率明顯上升,可判定查詢壓力大

3、當前GC safe point無推進,阻塞在約4小時前,排查歷史監控經常出現類似情況(TiKV Details -> GC -> TiKV Auto GC SafePoint)

企業微信截圖_20221026160916.png

初步斷定GC執行異常導致歷史版本堆積,引發查詢效率變慢。

下一步找出證據佐證這個猜想。

第三招,確認非預期的操作

慢查詢日誌裡面有兩個和Coprocessor Task 相關的欄位可以驗證這個猜想,他們是:

Total_keys:表示 Coprocessor 掃過的 key 的數量。

Process_keys:表示 Coprocessor 處理的 key 的數量。相比 total_keys,processed_keys 不包含 MVCC 的舊版本。如果 processed_keys 和 total_keys 相差很大,說明舊版本比較多。

但是介入排查的時候離異常時間已經過去快一天了,使用者只保留了30個日誌檔案,並且慢查詢閾值調到了100ms,也就意味著當時產生的Slow Query Log已經沒有了,難受。。

最後把希望寄託在tidb.log的 Expensive Query 上面,排查問題時間段發現了很多delete where limit 10000000這種操作,表資料量在千萬級,和應用端確認後是由手動執行產生。(DBA看了這種SQL想抄起眼前的鍵盤。。)

在排查了多條 Expensive Query 後發現,Total_keys普遍在幾億數量級,而Process_keys在百萬數量級,進一步驗證了前面的判斷。

企業微信截圖_20221026150724.png

下一步,要找出資料舊版本太多的原因。

第四招,日誌分析

GC操作是由TiDB Server的gc worker模組發起的,這裡排查起來就比較方便,只需要去TiDB Server搜尋日誌即可,最後定位到了如下的異常資訊:

企業微信截圖_20221025174935.png

從上面可以判斷,GC在正常發起(每隔10分鐘列印一條日誌),但是safepoint被一個執行中的會話阻塞了,並且給出了事務的開始時間戳(globalMinStartTS),根據這個資訊我們可以找到具體的session:

select instance,id,time,state,info,txnstart from information_schema.cluster_processlist where txnstart like '%xxxxxx%'

到這裡拿到session id以後可以根據實際情況判斷是否需要kill,但是也別高興的太早,因為有可能kill不掉。。。

關於kill不掉的問題在asktug吐槽的不少,據社群大佬說是kill成功了只是processlist查出來會殘留顯示,經過測試5.4.2徹底修復了。

如果真的真的真的kill了沒效果,就只能等著事務自己提交或回滾,要不然就得上重啟大法。

值得一提的是,上面的processlist查詢結果並不一定能查到根源SQL,也就是說info那一列是空值,這可能是單純由於事務卡著沒有提交,而不是某條慢SQL導致,這種情況下就要從應用端著手排查了。

第五招,還原真相

整理一下所有思路,得出以下結論:

  • duration升高的原因是資料的歷史版本太多,前面說到的頻繁delete操作導致tikv節點資源壓力較大,從而影響其他SQL(從其他SQL的Coprocessor Task wait_time可以判定)
  • 歷史版本堆積是因為gc safepoint被阻塞,有一個長期未提交的事務(從safepoint監控圖也可以驗證)

至此就破案了,一個gc引發的慘案浮出水面。而且,這種問題還會帶來一個連鎖反應,一旦safepoint恢復推進,大量的歷史版本瞬間被gc處理資源消耗極大,又要帶來第二波效能抖動,本案真實發生。

預防方案

首先從根源上,應用端要避免大事務操作,或者發起長期不提交的事務,及時提交或回滾。

其次,可以對TiDB GC做限流,降低GC對系統的整體影響:

企業微信截圖_20221026161711.png

另外,從TiDB v5.1開始(建議使用5.1.3及以上),可以開啟 GC in Compaction Filter 特性(預設開啟,簡單來說就是做Compaction的時候順帶把GC給做了),能夠有效降低GC帶來的效能抖動問題。

總結

生產環境保留事故現場非常重要,對於日誌檔案和監控資料條件允許的情況下儘量保留時間長一些,這對於後期排查問題起決定性作用。

另外,這個案例也告訴TiDB DBA,在對叢集做巡檢的時候,GC也是一個重要關注指標,一方面要確保GC的相關引數符合預期(比如gc_life_time臨時調大後忘了調回去),另一方面要確保GC執行正常,以免發生上述的效能問題。

相關文章