写点什么

insert 引发的 TiDB hang 死血案(案情一)

  • 2022 年 7 月 11 日
  • 本文字数:6176 字

    阅读完需:约 20 分钟

作者: dbapower 原文来源:https://tidb.net/blog/99ff8264

insert 带来的 TiDB 集群 hang 死血案

一、背景


业务在周四 6 月 18 日中午 12 点 30 左右,开始将数据往之前新建物理分表导数据,指定了 shard_row_id_bit 以及 pre_split_region 来避免热点。几天后的凌晨,集群出现 qps 骤降和 duration 耗时异常。


集群配置


集群版本:v3.0.5集群配置:普通SSD磁盘,128G内存,40 核cputidb21 TiDB/PD/pump/prometheus/grafana/CCStidb22 TiDB/PD/pumptidb23 TiDB/PD/pumptidb01 TiKVtidb02 TiKVtidb03 TiKVtidb04 TiKVtidb05 TiKVtidb06 TiKVtidb07 TiKVtidb08 TiKVtidb09 TiKVtidb10 TiKVtidb11 TiKVtidb12 TiKVtidb13 TiKVtidb14 TiKVtidb15 TiKVtidb16 TiKVtidb17 TiKVtidb18 TiKVtidb19 TiKVtidb20 TiKVwtidb29 TiKVwtidb30 TiKV
复制代码


二、现象



分析如下:


在 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 错误


三、排查步骤


监控


从监控信息,初步排查是因为 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 部分。

  5. Scheduler

  6. 查看 scheduler 监控,发现 async request error 集中在 not leader,并且 scheduler pending

  7. commands 在 01:15 陡升,并且主要集中在 218。

  8. 分析小结:

  9. 除调整写入的表外,业务以及 qps 没有调整,所以不太可能是

  10. scheduler-pending-write-threshold 超过 100MB 导致。

  11. scheduler 以及 scheduler - prewrite 监控面板中 pending commands 的数量以及

  12. commands 、latch wait duration 的耗时基本确定写入慢是慢在了 scheduler。

  13. pending commands 主要集中在 218,极大可能是写写冲突比较严重,并且都集

  14. 中在 218 ,导致 latch 耗时增长。

  15. 处理动作:

  16. ● 决定将 218 重启,将部分 leader 切换至其他 tikv 节点,看下是否可以缓解这个现

  17. 处理反馈:

  18. 把 218 重启后,现在就换了一个节点开始 pending commands 上涨,此时为 138。可能写

  19. 写冲突相当严重,并且集中在某几个 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 regionsneed 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 tonext due to send request fail"] [current="region ID: 7901120, meta: id:7901120start_key:\""t\"\"200\"\"000\"\"000\"\"000\"\"000\"\"001m\"\"313_i\"\"200\"\"000\"\"000\"\"000\"\"000\"\"000\"\"000\"\"001\"\"001f4ee30f3\"\"377b1663596\"\"377040a2655\"\"377c7f7a44f\"\"377\"\"000\"\"000\"\"000\"\"000\"\"000\"\"000\"\"000\"\"000\"\"367\"\"001autodisc\"\"377over.bil\"\"377lielourd\"\"377.net\"\"000\"\"000\"\"000\"\"000\"\"373\""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]Writeconflict, 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:
复制代码



四、总结回顾


确定是因为写写冲突导致的 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 集群运维提供了大力支持~ 也帮助和提升了我故障解决问题的能力,这篇文章分享给大家,通读这篇文章可以很好地掌握故障排查的思路,结合这个案例也可以让有类似潜在威胁的同学提前规避。这个案例后面还引发了另外两个案例,以后有时间也会一一总结分享给大家~


发布于: 刚刚阅读数: 3
用户头像

TiDB 社区官网:https://tidb.net/ 2021.12.15 加入

TiDB 社区干货传送门是由 TiDB 社区中布道师组委会自发组织的 TiDB 社区优质内容对外宣布的栏目,旨在加深 TiDBer 之间的交流和学习。一起构建有爱、互助、共创共建的 TiDB 社区 https://tidb.net/

评论

发布
暂无评论
insert引发的TiDB hang死血案(案情一)_故障排查/诊断_TiDB 社区干货传送门_InfoQ写作社区