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

2

集群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的日志进行过滤：

从上面日志过滤和分析可以看到：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工具可以换算出时间：

通过 tableID 查找具体的表名：

通过 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 的监控信息，开始进行排查。

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

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

通过下述监控面板，server is busy直接能定位到218机器，在 raftstore error 监控面板中，01:15 左右 218 出现了大量的 not leader,这是因为region 因为冲突特别繁忙，没有办法响应请求了。

通过 grpc message count 以及 message duration 两个监控项看下，从 01:15 左右开始，整个tikv-details 处理消息的数量大幅降低，并且处理 prewrite 的耗时，翻倍上涨，整个写入速度大幅降低。

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 节点接收的消息较为均衡，热点现象排除。

查看 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 监控面板，出现 command 以及 latch wait duration 逐渐上涨
的情况，与 grpc 监控 prewrite 耗时增长相匹配。此时，基本确定，写入慢是因为 scheduler-prewrite 耗时太长导致。

4

处理办法：
因为写写冲突都是集中在某个 key 和某个 region 上，并且冲突比较严重，尝试开启 tidb txn-local-latches，让 latch 等待集中在 tidb ，缓解 tikv 的压力。
处理结果：
调整参数后，并没有缓解。
业务逻辑：
与开发沟通后，了解到，业务端的唯一键检查主要靠数据库的 uk 来保证，应用端没有实现相关机制，当数据库报错后，业务再去做相应的报错处理。
因为这样的原因，出现某个 key 的冲突严重。但是这个逻辑在 19 年就已经有了，只是在 21 号爆发了。
可能是 21 号某种业务行为，导致某条数据，会频繁的出现，并进行 insert ，写写冲突爆发。
后续调整为，在满足业务逻辑的前提下，将 insert 语句改造为 insert ignore，当出现相同的数据时，报
1062，并返回 tidb。用户反馈，调整语句后，现象消失，qps 以及 duration 恢复正常：