作者：mydb
靳獻旗 ｜ 汽車之家 DBA 1.背景
最近處理了一個 TiDB 叢集寫入慢的問題，雖然問題解決了，但是背後的一些疑問還是沒徹底搞明白，本文算是對本次問題處理的一個總結，同時記錄一下相關疑惑，如果有遇到類似問題的小夥伴，可以幫忙一起看下。
叢集基本資訊：TiDB 4.0.9 版本，9 個 TiKV 執行個體，3 個 TiDB Server，3 個 PD Server，叢集開啟了 Binlog 同步資料到跨機房 TiDB 叢集，伺服器磁盤是普通 SSD ，做的 RAID 10。
2.問題描述
2022 年 5 月 2 号 12:24 DBA 收到 TiDB 叢集告警，緊接着，業務方回報資料庫寫入變慢，消息有堆積。
3.問題分析
3.1基礎分析
習慣性的看下叢集 SQL 99 響應時間，升高非常明顯
檢視 show processlist ，看到大量不同表的，各種各樣的 insert 語句，執行很慢
分析慢日志，排名前 10 的慢 SQL 基本全是各類表的 insert 語句，沒發現任何規律
叢集未出現 Server is busy 異常
3.2熱點分析
分析叢集基礎監控，發現有一台伺服器的 CPU 資源使用很高，而且明顯高于其它伺服器。其它名額，比如記憶體、網卡流量、IO Util 等均正常。
到這裡懷疑是熱點導緻的這台伺服器 CPU 資源明顯高于其它伺服器，繼續看下 raft store cpu 監控，判斷是讀熱點還是寫熱點
從上圖 raft store cpu 監控看到，有2個tikv執行個體的raft store cpu 明顯高于其它 tikv 執行個體，且這2台 tikv 執行個體在同一台伺服器上，一個是 store 1 (192.168.1.1:20180)，一個是 store 2 (192.168.1.1:20181)
到這裡我們初步判斷叢集寫入慢是因為寫入熱點導緻的，是哪個表導緻的寫入熱點？業務是否有刷數？
(1)業務是否有刷數
因為我們部署了 pump ，分析磁盤上産生的 binlog 量，相比前幾天相同時間段并沒有增加；QPS 沒有增加；而且和業務确認沒有刷資料；
(2)哪個表導緻的寫入熱點
通過熱力圖沒發現有熱點現象。
通過以上分析得知，應該不是熱點寫入導緻的叢集寫入慢。
3.3解決問題
在未找到原因的情況下，為了盡快解決叢集寫入慢的問題，再次使用了屢試不爽的 scheduler add evict-leader-scheduler 1 操作，将 192.168.1.1 伺服器上的 2 個 TiKV 的 region leader 做驅逐。做完驅逐操作，十幾分鐘後，叢集恢複正常，業務回報消息無堆積。
scheduler add evict-leader-scheduler 指令很不錯，幾年來多次救叢集于水火之中 3.4推測結論
雖然寫入慢的問題解決了，但是為什麼突然變慢這個問題一直困擾着我，然後反複看叢集監控，叢集日志，作業系統日志，硬體日志等資訊，這裡将分析結論記錄在此，正确性僅供參考。下面主要列一些分析過程中的重點資訊：
從上圖看到，大概 12:30 ，store 1 (192.168.1.1:20180) 上的 region leader 發生了大量切換，導緻 9000 個 leader 瞬間變為 0 了。
具體切換時間通過分析 PD 的日志得知是 12:30:03，日志如下，從 PD 日志中統計的 region 切換個數大概是 9000 個，和上圖一緻。
grep 'from=1' pd-2022-05-05T17-02-15.373.log | grep '2022/05/02 12:30:' | wc -l
到這裡，嚴重懷疑是 192.168.1.1 這台伺服器或者這台伺服器上的 TiKV 出現了什麼問題，接下來重點分析這台伺服器。
從上圖磁盤監控看到，在 IOPS 降低的情況下，寫入延時竟然增加了，平均達到1.48ms。事後對這塊盤使用 fio 工具進行了測試，在 IOPS 達到 8K 的情況下，寫入延遲不到 50 us，說明平時磁盤是 OK 的。
同時檢視了出問題時間段其他 TiKV 伺服器的磁盤 IO 寫入延遲，平均都在 100us 以下。
根據以上提到的所有資訊得出如下推理：
(1)192.168.1.1 伺服器上 store 1 的 region leader 大量切換時間是 12:30:03，和監控圖上 store 1 leader 數量變為 0 的時間吻合。
(2)監控圖上 store 1 raft store cpu 開始升高的時間是 12:24，12:30 達到峰值 182.9%，這個時間和第(1)步中 store 1 大量 region leader 切換時間吻合。
從上面 2 個資訊可以得出結論：因為 store 1 的 raft store cpu 已經達到瓶頸(raft store 預設 2 個線程，本案例峰值已經達到 182.9%)，導緻 raft store 無法及時處理 region 心跳消息，進而導緻的 store 1 region leader 大量切換。
(3)store 1 部署在了 sdb 盤上，12:24 左右開始， sdb iops 從 1000 多降低到 100 左右，但是寫入延遲确從 70us 以下升高到了1ms 以上，這個有點違反常理，為什麼 iops 變少了，寫入延遲反而升高了。sdb 寫入延遲開始升高的時間和第(1)步中 store 1 raft store cpu 開始升高的時間是吻合的。難道磁盤寫入慢影響了 raft store cpu ？磁盤為什麼會寫入突然變慢？這兩個問題一直沒搞明白。
說明：
(1)檢視了出問題這段時間内伺服器磁盤監控，作業系統日志，硬體日志，RAID 卡日志，并提供了 TSR 日志給戴爾廠家，均未發現異常
(2)使用 fio 工具對磁盤進行測試，iops 達到 8K 時寫入延遲 50us 左右，說明平時磁盤正常
(3)當天叢集穩定數個小時後之後，晚上 23 點，将驅逐操作取消後，讓 store 1 接受讀寫，叢集依然正常，截止目前未出現類似問題 以下内容來自官方文檔：
(1)通常在有負載的情況下，如果 Raftstore 的 CPU 使用率達到了 85% 以上，即可視為達到繁忙狀态且成為了瓶頸，同時 propose wait duration 可能會高達百毫秒級别。
(2)Raftstore 的 CPU 使用率是指單線程的情況。如果是多線程 Raftstore，可等比例放大使用率。由于 Raftstore 線程中有 I/O 操作，是以 CPU 使用率不可能達到 100%。 最後，理一下問題的整個過程： 從 12:24 開始，磁盤 iops 降低，磁盤寫入延遲升高，同時伴随着 raft store cpu 升高，到 12:30 ，raft store cpu 達到峰值（出現瓶頸），導緻 raft store 無法及時處理 reigon 心跳，最終導緻了這個 tikv 上所有 region leader 的切換，切換後，raft store cpu 開始稍微下降(依然很高)，然後部分 region leader 又切回到這個 store 1 上，形成惡性循環，叢集持續寫入變慢。此時，DBA 執行了驅逐 store 1 和 2 上的 region leader 操作，随後，之前的惡性循環消失，叢集也恢複正常。
這裡對本文剛開始懷疑的熱點問題再補充說明一下：
叢集剛出現問題時，分析監控看到 store 1 的 raft store cpu 遠遠高于其他 store 的 cpu ，會讓人覺得可能是熱點問題，進而導緻了這台伺服器磁盤 IO 寫入延遲增加，實際上通過分析磁盤監控，iops 并沒有增加，反而減少了。一般情況下，當某個 TiKV 出現寫入熱點時，伴随着的是磁盤 iops 的升高，從這一點來說，也不符合寫入熱點的現象。
4.相關疑惑
問題雖然解決了，但是有兩個疑問一直困擾着我，希望有遇到類似的小夥伴幫忙一起看下。
- 為什麼磁盤 iops 突然降低，而寫入延遲反而升高
- 監控中出現過 write stall，為什麼日志中搜不到 Stalling 關鍵字 在 14:08 時，我執行過 scheduler remove evict-leader-scheduler ，将驅逐操作删除了，随後叢集又出現寫入慢的問題了，檢視監控，在 14:24 叢集出現過 write stall ，但是在 tikv 伺服器相關日志中卻搜不到 Stalling 關鍵字，很郁悶。
5.總結
本文對五一期間遇到的一起 TiDB 叢集寫入慢的詭異問題做了一個總結和回顧，并給出了解決方法，同時提出了兩個一直沒解決的疑問。
值得一提的是，scheduler add evict-leader-scheduler 真是一個很有用的指令，幾年來，多次救叢集于水火，屢試不爽。
由于本人水準有限，分析的内容難免錯誤，請多多包涵。