背景
前段時間使用者反饋某生產環境 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 數量:
從監控看到,在8月18號下午6點左右 Skip Count 突然從高位掉到0,正是因為上一次重啟 TiDB server 修復了故障。往後到21號早上左右,Skip Count 又開始出現,那麼就要重點分析這個時間點的日誌。
進一步分析監控,發現 Skip Count 上升趨勢和 Critical Error 相吻合,說明在21號早上07:06左右開始出現大量的 binlog 寫入異常,接下來根據這個時間點去排查 pump 的日誌。
根據精確的時間點,很快就在 pump 日誌中定位到了panic的位置,在panic之後日誌發現了一個非常有用的資訊:
日誌顯示,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
看看什麼情況:
意外的是,上圖顯示 pump 的資料盤只用了1%,還有大把的空間沒被使用,貌似和日誌報錯原因不符。
到這裡我忽略了一個重要的時間因素,就是介入排查的時候離 pump 故障已經過去了3天(從前面第一章監控圖可以看到),而 pump gc時間設定的是2天,那麼意味著在排查的時候 pump 之前記錄的binlog 已經被 gc 掉了,至於這些 binlog 有沒有被 drainer正常消費還不得而知。好在 Grafana 監控裡面有一個皮膚記錄了 pump storage 的變化情況,路徑是:Binlog->pump->Storage Size
。
從上面這個曲線聯想最近兩次的故障,貌似問題一下子清楚了: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 同步恢復正常。
觀察幾天後發現,pump 磁碟使用率穩定在一半左右,評估不會再出現類似問題,可以睡個安穩覺了。
好在下游 kafka 對丟資料不敏感,可以接受隨時從當前時間重新同步,省了好多事,要不然得崩潰。
吐槽時間
不得不說要重啟 TiDB server 才能恢復 binlog 真的太難受了,生產環境不是想重啟就能重啟的,好在後面發現了還有個 API 能恢復 binlog,下次碰到了試一下。
curl http://{tidb-server ip}:{status_port}/binlog/recover
文件隱蔽工作做的太好了,這些走後門的方法不知道 TiDB 還隱藏了多少。?
再就是在文件上看到的 binlog 主從故障恢復方法,真是瑟瑟發抖,誰用誰996。↓↓↓
根據使用經驗來看,設定了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交付服務,涵蓋金融、證券、物流、電力、政府、零售等重點行業。