TiDB binlog故障處理之drainer週期性罷工

balahoho發表於2023-11-16

背景

前段時間使用者反饋某生產環境 TiDB 叢集 drainer 頻繁發生故障,要麼服務崩潰無法啟動,要麼資料跑著跑著就丟失了,很是折磨人。該叢集跑的是離線分析業務,資料量20T ,v4版本,有多個 drainer 往下游同步資料,目標端包括kafka、file、tidb多種形態。

兩天前剛恢復過一次,這會又故障重現,不得不來一次根因排查。

故障現象

接業務端反饋,某下游kafka幾個小時沒收到 TiDB 資料了,但是 pump 和 drainer 節點狀態都顯示正常,同樣在幾天前也收到類似的反饋,當時是因為 binlog 發生未知異常導致 TiDB server 停止寫入,需要透過以下 API 驗證 binlog 狀態:

curl http://{tidb-server ip}:{status_port}/info/all

該 API 會返回所有 TiDB server 的元資訊,其中就包括每個例項 binlog 的寫入狀態(binlog_status欄位),如果 TiDB server設定了ignore-error,那麼在 binlog 故障時通常是 skipping,正常情況下是 on

經確認7個 TiDB server 的 binlog_status 均為 skipping狀態,和此前是一樣的問題。

處理方法比較簡單,重啟 TiDB server 即可,但是避免後續重複出現需要搞清楚原因後再重啟。

分析過程

資料不同步了相信大家都會第一時間懷疑是 drainer 的問題, 最常見的原因就是大事務導致 drainer 崩潰panic,但是登入到 drainer 所在的機器上分析日誌,並沒有發現異常現象,日誌顯示 savepoint 正常寫入,checkpoint 正常推進,例項狀態up,說明並不是 drainer的問題。

根據 binlog skip 狀態,轉頭去分析 TiDB server監控,在 TiDB->Server->Skip Binlog Count皮膚可以看到被跳過的 binlog 數量:

企業微信截圖_20230824110827.png

從監控看到,在8月18號下午6點左右 Skip Count 突然從高位掉到0,正是因為上一次重啟 TiDB server 修復了故障。往後到21號早上左右,Skip Count 又開始出現,那麼就要重點分析這個時間點的日誌。

進一步分析監控,發現 Skip Count 上升趨勢和 Critical Error 相吻合,說明在21號早上07:06左右開始出現大量的 binlog 寫入異常,接下來根據這個時間點去排查 pump 的日誌。

企業微信截圖_20230824110703.png

根據精確的時間點,很快就在 pump 日誌中定位到了panic的位置,在panic之後日誌發現了一個非常有用的資訊:

企業微信截圖_20230824111305.png

日誌顯示,binlog 確實停止寫入了,同時指出停止寫入的原因是磁碟空間不夠,這裡有個關鍵資訊StopWriteAtAvailableSpace,也就是說 pump 所在的磁碟可用空間小於這個引數時就會停止寫入。我們用edit-config看一下 pump 的配置引數:

  pump:
    gc: 2
    heartbeat-interval: 2
    security:
      ssl-ca: ""
      ssl-cert: ""
      ssl-key: ""
    storage:
      stop-write-at-available-space: 1 gib

發現日誌和配置引數可以對應上,確實是磁碟不夠了。反手就是一個df -h看看什麼情況:

企業微信截圖_20230824111549.png

意外的是,上圖顯示 pump 的資料盤只用了1%,還有大把的空間沒被使用,貌似和日誌報錯原因不符。

到這裡我忽略了一個重要的時間因素,就是介入排查的時候離 pump 故障已經過去了3天(從前面第一章監控圖可以看到),而 pump gc時間設定的是2天,那麼意味著在排查的時候 pump 之前記錄的binlog 已經被 gc 掉了,至於這些 binlog 有沒有被 drainer正常消費還不得而知。好在 Grafana 監控裡面有一個皮膚記錄了 pump storage 的變化情況,路徑是:Binlog->pump->Storage Size

企業微信截圖_20230824110954.png

從上面這個曲線聯想最近兩次的故障,貌似問題一下子清楚了:18號下午6點左右重啟 TiDB Server 恢復 binlog 寫入,pump 可用空間開始變少,到21號早上7點左右幾乎被使用完畢,觸發StopWriteAtAvailableSpace異常,binlog 停止寫入變成 skipping狀態,但與此同時 pump gc 還在工作,且沒有新的 binlog 進來,兩天後存量資料被 gc 完畢在23號早上7點左右恢復到空盤水平,持續到現在。

半途接手的叢集,各種背景資訊也不是很瞭解,經常奇奇怪怪問題一查就是查半天,這就是oncall人的日常。。?

解決方案

到這裡問題已經很明確了,是磁碟空間不夠導致的,那麼只有兩條路擺在面前:要麼開源、要麼節流。

經過和使用者溝通,加盤是不可能加的,直接就把 pump gc 縮短到1天。不過縮短 gc 也是存在風險的,如果哪次 drainer 故障超過1天那就要丟資料了。最終在24號下午6點左右把 gc 調整和 TiDB server 重啟剛好一起做了,binlog 同步恢復正常。

企業微信截圖_20230916115308.png

企業微信截圖_20230828180700.png

企業微信截圖_20230828180605.png

觀察幾天後發現,pump 磁碟使用率穩定在一半左右,評估不會再出現類似問題,可以睡個安穩覺了。

好在下游 kafka 對丟資料不敏感,可以接受隨時從當前時間重新同步,省了好多事,要不然得崩潰。

吐槽時間

不得不說要重啟 TiDB server 才能恢復 binlog 真的太難受了,生產環境不是想重啟就能重啟的,好在後面發現了還有個 API 能恢復 binlog,下次碰到了試一下。

curl http://{tidb-server ip}:{status_port}/binlog/recover

文件隱蔽工作做的太好了,這些走後門的方法不知道 TiDB 還隱藏了多少。?

再就是在文件上看到的 binlog 主從故障恢復方法,真是瑟瑟發抖,誰用誰996。↓↓↓

企業微信截圖_20230916105034.png

根據使用經驗來看,設定了ignore-error後發生 critical error的可能性非常高,binlog 同步真的是太脆了,一言不合就罷工。每次都要全備+ 恢復+重啟 TiDB server,對於動輒幾十T的叢集那絕對是災難,時間成本不說,這麼大資料量出錯的機率也高,想想都後背發涼。

被折磨的人應該不少。

總結

從這個案例中我總結到,在引數設定上要留有一些buffer,給後續出問題時有緩衝時間來處理。比如在本案中可以把stop-write-at-available-space設大一點,在出現磁碟空間不足時可以快速把值調小,這樣 binlog 還能恢復繼續同步,也能留出時間去做磁碟擴容,或者制定其他方案。

另外一點要注意 pump gc 的影響,它不會管 drainer 有沒有正常消費,gc 設定上也要給 drainer 故障處理留出一些時間。

最後,沒事多研究下監控指標,在排查問題時能少走很多彎路。

不好意思,標題讓 drainer 背鍋了。?

作者介紹:hey-hoho,來自神州數碼鈦合金戰隊,是一支致力於為企業提供分散式資料庫TiDB整體解決方案的專業技術團隊。團隊成員擁有豐富的資料庫從業背景,全部擁有TiDB高階資格證書,並活躍於TiDB開源社群,是官方認證合作伙伴。目前已為10+客戶提供了專業的TiDB交付服務,涵蓋金融、證券、物流、電力、政府、零售等重點行業。

相關文章