insert带来的TiDB集群性能瓶颈排障

原创

360技术 2021-07-07 10:10:47 ©著作权

©著作权归作者所有：来自51CTO博客作者360技术的原创作品，请联系作者获取转载授权，否则将追究法律责任

本文通过分析TiDB线上集群的一次业务问题，整理了故障排查的思路，结合这个案例也可以让有类似潜在威胁的同学提前规避。

问题背景

线上某业务将数据导入新建物理分表，指定了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 开始两阶段提交：

TiDB 从所有要写入的 Key 中选择一个作为当前事务的 Primary Key
TiDB 向所有的本次提交涉及到的 TiKV 发起 prewrite 请求，TiKV 判断是否所有 Key 都可以 prewrite 成功
TiDB 收到所有 Key 都 prewrite 成功的消息
TiDB 向 PD 请求 commit_ts
TiDB 向 Primary Key 发起第二阶段提交。Primary Key 所在的 TiKV 收到 commit 操作后，检查数据合法性，清理 prewrite 阶段留下的锁
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 的监控信息，开始进行排查。

Query Details

写写冲突在 21 日 01:15 出现了一个陡升的现象：

KV Duration

3KV duration 耗时都集中在 store 16 ，store 16 IP 地址为 218，并且结合 KV Error 的监控，可能从 01:15 左右开始218 就出现响应超时的报错

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 耗时太长导致。

总结

问题的原因是写写冲突导致的 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 恢复正常：