天天看點

Tidb duration 耗時異常上升案例

作者:顧大偉

背景

360網盾Tidb叢集擁有120TB 的存儲量,運維複雜度很高,平時出問題排查比較困難,8月24号開發回報業務阻塞了好久了,大約8.19号開始的,回報消費很慢,業務最近隻是例行删除了幾T資料,以往經驗過幾天就自己恢複了,影響不大,但是這次持續一周響應耗時還是逐漸增加,排查分析最終通過調優Tikv 參數解決

=》問題排查過程

①看監控

開發回報的業務阻塞監控,19号開始業務消費一直很慢,24号到達最高峰

Tidb duration 耗時異常上升案例

檢視80 duration 耗時占用達到幾百ms,明顯較高存在問題\

Tidb duration 耗時異常上升案例

檢視最近30天的TiDB-Statement OPS ,顯示并沒有明顯的變化,說明業務确實沒上新\

Tidb duration 耗時異常上升案例

檢視TIKV-Trouble-Shooting -Server is Busy\

Tidb duration 耗時異常上升案例

看上去是49 這台機器相對負載比較高,登陸機器檢視确實系統負載比較高,同時tikv 日志顯示存在大量的[error-response] [err="Key is locked (will clean up) primary_lock,存在索引寫寫沖突,本身tikv 每個節點region 已經20多w,官方建議不超過每個tikv 3w,超過就會出各種奇葩問題,data容量達到4TB 以上,是以系統負載一直不低,沒辦法機器資源不夠,目前一直在删資料中…繼續看監控\

Tidb duration 耗時異常上升案例

上面49節點顯示commit log耗時達到2s以上,apply log 也很慢,說明Tikv 層面寫入存在瓶頸,檢視本節點region 個數并不存在超多現象,磁盤和cpu記憶體名額和其它機器一樣,業務硬體問題,但是commit log 耗時嚴重,說明在二階段送出的時候存在耗時嚴重問題,大機率和業務邏輯存在寫寫沖突有關系,但是目前tidb 4.x 預設是已經是悲觀鎖了已經很大程度降低這種情況了

版本差異

在 v3.0.8 版本之前,TiDB 預設采用樂觀事務模型,在事務執行過程中并不會做沖突檢測,而是在事務最終 COMMIT 送出時觸發兩階段送出,并檢測是否存在寫寫沖突。當出現寫寫沖突,并且開啟了事務重試機制,則 TiDB 會在限定次數内進行重試,最終重試成功或者達到重試次數上限後,會給用戶端傳回結果。是以,如果 TiDB 叢集中存在大量的寫寫沖突情況,容易導緻叢集的 Duration 比較高。

另外在 v3.0.8 及之後版本預設使用悲觀事務模式,進而避免在事務送出的時候因為沖突而導緻失敗,無需修改應用程式。悲觀事務模式下會在每個 DML 語句執行的時候,加上悲觀鎖,用于防止其他事務修改相同 Key,進而保證在最後送出的 prewrite 階段不會出現寫寫沖突的情況。

②慢日志分析

發現大量的insert 耗時超過10s,主要耗時在prewrite 階段和commit 階段,這也和監控顯示基本相符

Tidb duration 耗時異常上升案例

③ 根據監控現象查詢官方文檔和asktug

​​https://docs.pingcap.com/zh/tidb/stable/tidb-troubleshooting-map​​

對照官方建議的參數調優,調整[raftstore] raft-max-inflight-msgs =2048 來增大raft的滑動視窗大小,Raft 本身是有流控機制的,當達到限制的時候會導緻commit log 放緩,延時增高,預設256,是以嘗試增加來看看效果

指定節點reload TIKV 參數

tiup cluster reload tidb_shbt_01 -R tikv -N xxxx

恰巧周五晚上,修改完成後,看上去duration 在逐漸降低,周末兩天觀察

周一業務回報已經完全恢複了?,監控80 duation 耗時确實顯著下降了

Tidb duration 耗時異常上升案例

該叢集同時存在大量的唯一索引寫寫沖突後期經過優化insert 耗時也明顯提升,同時經過更新為5.7.25-TiDB-v5.0.4 後,整體叢集性能提升了不止一個檔次,是以建議大家及時更新到5.x的穩定版,對“内功”确實有很大提升,目前的duration 監控如下

感謝pingcap 蘇丹老師在問題進行中提供的幫助,給我提供了一些問題處理思路,通過類似次問題處理,更加熟悉了Tidb,對使用運維Tidb 更有信心