insert帶來的TiDB集羣hang死血案

insert帶來的TiDB集羣hang死血案

1、背景

業務在週四 6 月18 日中午12 點 30 左右，開始將數據往以前新建物理分表導數據，指定了shard_row_id_bit 以及 pre_split_region來避免熱點。幾天後的凌晨，集羣出現qps驟降和 duration 耗時異常。
集羣配置

集羣版本：v3.0.5
集羣配置：普通SSD磁盤，128G內存，40 核cpu
tidb21 TiDB/PD/pump/prometheus/grafana/CCS
tidb22 TiDB/PD/pump
tidb23 TiDB/PD/pump
tidb01 TiKV
tidb02 TiKV
tidb03 TiKV
tidb04 TiKV
tidb05 TiKV
tidb06 TiKV
tidb07 TiKV
tidb08 TiKV
tidb09 TiKV
tidb10 TiKV
tidb11 TiKV
tidb12 TiKV
tidb13 TiKV
tidb14 TiKV
tidb15 TiKV
tidb16 TiKV
tidb17 TiKV
tidb18 TiKV
tidb19 TiKV
tidb20 TiKV
wtidb29 TiKV
wtidb30 TiKV

2、現象

分析以下：
在 6 月 21 日凌晨 01：24分左右，qps大幅驟降，durtation大幅增高，報警包含以下三類：

集羣region數量和大小上漲緩慢，且此時沒有大規模region balance：

pd監控顯示各節點磁盤消耗停滯

tidb --> kv error 監控面板下面出現下述的告警信息：


上面有反饋server is busy，這多是raftsotore線程卡了，致使消息沒有及時處理，也多是寫入的事物過多，TiKV進行寫入流控，多是查詢量過大，產生了堆積。

經過監控咱們定位到server is busy的節點，是ip爲218結尾的這臺機器出現了問題：


218這個節點的pending commands不正常

其scheduler worker cpu也遠高於其餘節點
日誌大概看了下未見異常，將其重啓。

重啓問題節點218後，能看到pending command和worker cpu轉移了：

對TiKV的日誌進行過濾

cat 218.log| grep conflict | awk -F 'tableID=' '{print $2}' 都過濾下寫衝突的 tableid 
select * from information_schema.tables where tidb_table_id='93615';
 
["commit failed"] [conn=250060] ["finished txn"="Txn{state=invalid}"] [error="[kv:9007]Write conflict, txnStartTS=417517629610917903, conflictStartTS=417517692315762921, conflictCommitTS=417517692315762921, key={tableID=93643, indexID=1, indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} primary={tableID=93643, indexID=1, indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} [try again later]"]
 
 [kv:9007]Write conflict, txnStartTS=417517629610917903, conflictStartTS=417517692315762921, conflictCommitTS=417517692315762921, key={tableID=93643, indexID=1, indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} primary={tableID=93643, indexID=1, indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} [try again later]"] [errorVerbose="[kv:9007]Write conflict, txnStartTS=417517629610917903, conflictStartTS=417517692315762921, conflictCommitTS=417517692315762921, key={tableID=93643, indexID=1, indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} primary={tableID=93643, indexID=1, indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} [try again later]
10 分鐘的日誌，這個表的衝突出現了 1147 次

[kv:9007]Write conflict：表示出現了寫寫衝突
txnStartTS=417517629610917903：表示當前事務的 start_ts 時間戳，能夠經過 pd-ctl 工具將時間戳轉換爲具體時間
conflictStartTS=417517692315762921：表示衝突事務的 start_ts 時間戳，能夠經過 pd-ctl 工具將時間戳轉換爲具體時間
conflictCommitTS=417517692315762921：表示衝突事務的 commit_ts 時間戳，能夠經過 pd-ctl 工具將時間戳轉換爲具體時間
key={tableID=93643, indexID=1, indexValues={string, }}：表示當前事務中衝突的數據，tableID 表示發生衝突的表的 ID，indexID 表示是索引數據發生了衝突。若是是數據發生了衝突，會打印 handle=x 表示對應哪行數據發生了衝突，indexValues 表示發生衝突的索引數據
primary={tableID=93643, indexID=1, indexValues={string, }}：表示當前事務中的 Primary Key 信息

經過pd工具能夠換算出時間
./pd-ctl -u https://{PDIP}:2379 tso {TIMESTAMP}

經過 tableID 查找具體的表名：
curl http://{TiDBIP}:10080/db-table/{tableID}

經過 indexID 查找具體的索引名：
SELECT * FROM INFORMATION_SCHEMA.TIDB_INDEXES WHERE TABLE_SCHEMA='{table_name}' AND TABLE_NAME='{table_name}' AND INDEX_ID={indexID};

版本差別
在 v3.0.8 版本以前，TiDB 默認採用樂觀事務模型，在事務執行過程當中並不會作衝突檢測，而是在事務最終 COMMIT 提交時觸發兩階段提交，並檢測是否存在寫寫衝突。當出現寫寫衝突，而且開啓了事務重試機制，則 TiDB 會在限定次數內進行重試，最終重試成功或者達到重試次數上限後，會給客戶端返回結果。所以，若是 TiDB 集羣中存在大量的寫寫衝突狀況，容易致使集羣的 Duration 比較高。

另外在 v3.0.8 及以後版本默認使用悲觀事務模式，從而避免在事務提交的時候由於衝突而致使失敗，無需修改應用程序。悲觀事務模式下會在每一個 DML 語句執行的時候，加上悲觀鎖，用於防止其餘事務修改相同 Key，從而保證在最後提交的 prewrite 階段不會出現寫寫衝突的狀況。

出現寫寫衝突的緣由
TiDB 中使用 Percolator 事務模型來實現 TiDB 中的事務。Percolator 整體上就是一個二階段提交的實現。具體的二階段提交過程可參考樂觀事務文檔。
當客戶端發起 COMMIT 請求的時候，TiDB 開始兩階段提交：

1. TiDB 從全部要寫入的 Key 中選擇一個做爲當前事務的 Primary Key
2. TiDB 向全部的本次提交涉及到的 TiKV 發起 prewrite 請求，TiKV 判斷是否全部 Key 均可以 prewrite 成功
3. TiDB 收到全部 Key 都 prewrite 成功的消息
4. TiDB 向 PD 請求 commit_ts
5. TiDB 向 Primary Key 發起第二階段提交。Primary Key 所在的 TiKV 收到 commit 操做後，檢查數據合法性，清理 prewrite 階段留下的鎖
6. TiDB 收到兩階段提交成功的信息
   寫寫衝突發生在 prewrite 階段，當發現有其餘的事務在寫當前 Key (data.commit_ts > txn.start_ts)，則會發生寫寫衝突。
   TiDB 會根據 tidb_disable_txn_auto_retry 和 tidb_retry_limit 參數設置的狀況決定是否進行重試，若是設置了不重試，或者重試次數達到上限後仍是沒有 prewrite 成功，則向 TiDB 返回 Write Conflict 錯誤

3、排查步驟

監控
從監控信息，初步排查是由於 tikv 比較繁忙，出現了 server is busy 的狀況。導出了 21 日異常時間段的 tidb 以及 tikv-details 的監控信息，開始進行排查。
TiDB 
Query Details
寫寫衝突在 21 日 01:15 出現了一個陡升的現象：

KV Duration
KV duration 耗時都集中在 store 16 ，store 16 IP 地址爲 218，而且結合 KV Error 的監控，可能從 01:15 左右開始218 就出現響應超時的報錯：
TiKV - Details
Erros 
經過下述監控面板，server is busy直接能定位到218機器，在 raftstore error 監控面板中，01:15 左右 218 出現了大量的 not leader,這是由於region 由於衝突特別繁忙，沒有辦法響應請求了

Grpc
經過 grpc message count 以及 message duration 兩個監控項看下，從 01:15 左右開始，整個tikv-details 處理消息的數量大幅下降，而且處理 prewrite 的耗時，翻倍上漲，整個寫入速度大幅下降。

Thread CPU
raftstore cpu 以及 async apply cpu 利用率一樣在 01:15 開始利用率大幅降低，與 grcp 相關監控吻合，集羣此時，處理寫入的速度確實下降了。

scheduler worker cpu 在 01:15 也下降了，可是 218的 scheduler 的 cpu 異常高於其餘 tikv ，而且出現上漲是在 00:45 左右。這是由於該節點衝突嚴重，scheduler在反覆調度，處理pending task。

由於上面的 scheduler worker cpu 的異常現象，排查熱點相關的問題，發如今出現問題時，
各個 tikv 節點接收的消息較爲均衡，熱點現象排除。

Storage
查看 async write duration ，發現從 01:15 開始 async write duration 很是低，故再也不查看propose wait ，append，apply wait 以及 apply 耗時，整個寫入慢的問題不是發生在這個階段，極可能是發生在 scheduler 階段。rocksdb-kv 相關的監控也驗證了這一點。

RocksDB - KV
查看 rocksdb-kv 中 wal 以及 write duration 自 01:15 開始耗時降低，與 storage 處的猜想吻合，不是 raftstore ，apply 以及 rocksdb 慢，多是慢在了 scheduler 。

Scheduler - prewrite
接着查看了 scheduler - prewrite 監控面板，出現 command 以及 latch wait duration 逐漸上漲
的狀況，與 grpc 監控 prewrite 耗時增加相匹配。此時，基本肯定，寫入慢是由於 scheduler -
prewrite 耗時太長致使。

分析小結：

1. 自 21 日 01:15 開始，整個集羣的寫入速度驟降。
2. 排除了 scheduler cpu 異常致使熱點的可能性。
3. 排除了 raftstore ，apply 以及 rocksdb-kv 寫入慢的可能性。
4. 初步懷疑，寫入慢在了 scheduler 部分。
   Scheduler
   查看 scheduler 監控，發現 async request error 集中在 not leader，而且 scheduler pending
   commands 在 01:15 陡升，而且主要集中在 218。
   分析小結：
5. 除調整寫入的表外，業務以及 qps 沒有調整，因此不太多是
   scheduler-pending-write-threshold 超過 100MB 致使。
6. scheduler 以及 scheduler - prewrite 監控面板中 pending commands 的數量以及
   commands 、latch wait duration 的耗時基本肯定寫入慢是慢在了 scheduler。
7. pending commands 主要集中在 218，極大多是寫寫衝突比較嚴重，而且都集
   中在 218 ，致使 latch 耗時增加。
   處理動做：
   ● 決定將 218 重啓，將部分 leader 切換至其餘 tikv 節點，看下是否能夠緩解這個現
   象
   處理反饋：
   把218重啓後，如今就換了一個節點開始pending commands上漲，此時爲 138。可能寫
   寫衝突至關嚴重，而且集中在某幾個 region：

TiKV 日誌
由於重啓 218 後，scheduler pending 會轉移，故過濾了 218 的 log ，發現大量的出
現以下信息, 而且都集中在某幾個 region 上 7365862 ，7257865：

[2020/06/21 09:40:43.011 +08:00] [INFO] [process.rs:188] ["get snapshot failed"]
[err="Request(message: \"peer is not leader for region 7365862, leader may Some(id:
7365863 store_id: 16)\" not_leader { region_id: 7365862 leader { id: 7365863 store_id: 16
} })"] [cid=50406655291]
[2020/06/21 09:40:43.023 +08:00] [INFO] [process.rs:188] ["get snapshot failed"]
[err="Request(message: \"peer is not leader for region 7257865, leader may Some(id:
7257868 store_id: 16)\" not_leader { region_id: 7257865 leader { id: 7257868 store_id: 16
} })"] [cid=50406655292]

查看 region 7257865 信息以下：

TiDB 日誌
查看 TiDB 的日誌，出現 218 連接無效，server is timeout , 而且 region cache 須要 refill
的現象,多是 218 tikv 的 scheduler 太繁忙，而且由於寫寫衝突嚴重，都集中在某幾個
region，沒法響應。這個與 tikv 監控以及日誌顯示的結論基本一致：

[2020/06/21 09:40:47.001 +08:00] [INFO] [region_cache.go:894] ["mark store's regions
need be refill"] [store=xx.xx.xx.218:20160]
[2020/06/21 09:40:47.001 +08:00] [INFO] [region_cache.go:393] ["switch region peer to
next due to send request fail"] [current="region ID: 7901120, meta: id:7901120
start_key:\"t\\200\\000\\000\\000\\000\\001m\\313_i\\200\\000\\000\\000\\000\\000\\000\\00
1\\001f4ee30f3\\377b1663596\\377040a2655\\377c7f7a44f\\377\\000\\000\\000\\000\\000\\
000\\000\\000\\367\\001autodisc\\377over.bil\\377lielourd\\377.net\\000\\000\\000\\000\\37
3\"
end_key:\"t\\200\\000\\000\\000\\000\\001m\\313_i\\200\\000\\000\\000\\000\\000\\000\\002
\" region_epoch:<conf_ver:623 version:60959 > peers:<id:7903456 store_id:5 >

由於定位是寫寫衝突致使，那麼過濾了 21 日 10 分鐘 tidb 的監控，發現下表同一個 key 的衝
突出現了 1100 屢次：

衝突日誌以下：

["commit failed"] [conn=250060] ["finished txn"="Txn{state=invalid}"] [error="[kv:9007]Write
conflict, txnStartTS=417517629610917903, conflictStartTS=417517692315762921,
conflictCommitTS=417517692315762921, key={tableID=93643, indexID=1,
indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }}
primary={tableID=93643, indexID=1,
indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} [try again later]"]
[kv:9007]Write conflict, txnStartTS=417517629610917903,
conflictStartTS=417517692315762921, conflictCommitTS=417517692315762921,
key={tableID=93643, indexID=1, indexValues={f73732b3d9f35742e39e6bba8e401192,
www.baidu.com, }} primary={tableID=93643, indexID=1,
indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} [try again later]"]
[errorVerbose="[kv:9007]Write conflict, txnStartTS=417517629610917903,
conflictStartTS=417517692315762921, conflictCommitTS=417517692315762921,
key={tableID=93643, indexID=1, indexValues={f73732b3d9f35742e39e6bba8e401192,
www.baidu.com, }} primary={tableID=93643, indexID=1,
indexValues={f73732b3d9f35742e39e6bba8e401192, www.baidu.com, }} [try again later]
表索引信息以下，UNIQUE KEY `idx_cert_md5_host` (`cert_md5`,`host`) 爲 uk：

4、總結回顧

肯定是由於寫寫衝突致使的 tikv scheduler latch 等待，而且集中在某幾個 key 和region ，scheduler 的 slot 有限排隊等待嚴重，進而出現集中請求的 region 所在的tikv 很繁忙，出現 server is timeout 的報錯。
處理辦法：
由於寫寫衝突都是集中在某個 key 和某個 region 上，而且衝突比較嚴重，嘗試開啓 tidb txn-local-latches，讓 latch 等待集中在 tidb ，緩解 tikv 的壓力。
處理結果：
調整參數後，並無緩解。
業務邏輯：
與開發溝通後，瞭解到，業務端的惟一鍵檢查主要靠數據庫的 uk 來保證，應用端沒有實現相關機制，當數據庫報錯後，業務再去作相應的報錯處理。
由於這樣的緣由，出現某個 key 的衝突嚴重。可是這個邏輯在 19 年就已經有了，只是在 21 號爆發了。
多是 21 號某種業務行爲，致使某條數據，會頻繁的出現，並進行 insert ，寫寫衝突爆發。
後續調整爲，在知足業務邏輯的前提下，將 insert 語句改造爲 insert ignore，當出現相同的數據時，報
1062，並返回 tidb。用戶反饋，調整語句後，現象消失，qps 以及 duration 恢復正常：

感謝感謝PingCap高振嬌女神幫忙排查和定位故障，爲360雲平臺TiDB集羣運維提供了大力支持~也幫助和提高了我故障解決問題的能力，這篇文章分享給你們，通讀這篇文章能夠很好地掌握故障排查的思路，結合這個案例也可讓有相似潛在威脅的同窗提早規避。