一次 TiDB GC 阻塞引发的性能问题分析

作者： hey-hoho 原文来源：https://tidb.net/blog/9d17543d

背景

前不久从项目一线同学得到某集群的告警信息，某个时间段 TiDB duration 突然异常升高，持续时间 6 小时左右，需要定位到具体原因。

分析过程

第一招，初步判断

由于项目条件苛刻，历经苦难才拿到监控，在此之前只能靠现场同学的口述排查，oncall 人太难了。。

既然是 duration 升高，那就先看看集群的心电图，试图找出一点线索。一般来说，duration 升高会有以下两种情况。

第一种是高百分位（比如 99、999）明显升高，类似这种：

它的特点是除了高百分位异常，低分位线没有明显波动，这是典型的长尾反应，分位线越高波动越大，说明集群那段时间慢 SQL 变多，重点关注慢查询辅助排查其他监控即可。

第二种是所有分位线都有明显升高，类似这种：

这说明集群内部受到了影响，慢 SQL 不是导致 duration 上升的根本原因，而是集群异常表现出来的结果。但是慢查询依然是我们着手排查的方向之一，慢日志里面记录了慢的一些主要原因，可以作为参考依据。

这个案例碰到的就是第二种。

第二招，用监控还原 SQL 流程

如果暂时没有什么明确排查目标，可以先按 SQL 读写流程看一下主要的监控。通常在一个业务系统里，读请求是明显要多于写请求的，所以可以从读流程开始排查，先是 TiDB 再是 TiKV。

推荐参考社区的 Trouble Shooting 系列文章，非常实用：

• 读性能慢 - 总纲
  

• 读性能慢 -TiDB Server 读流程详解
  

• 读性能慢 -TiKV Server 读流程详解
  

• TiDB 写入慢流程排查系列
  

详细流程不再赘述。把这一招用完，基本就能定位到问题了，再结合一些非数据库因素，查明真相指日可待。

针对本次案例中，说一下监控排查结论：

1、问题时间段 TPS、QPS 相较正常情况无明显波动，各项资源使用率平稳，排除 TiDB Server 的问题

2、问题时间段 TiKV 节点负载变大，CPU、磁盘、出口带宽使用率明显上升，可判定查询压力大

3、当前 GC safe point 无推进，阻塞在约 4 小时前，排查历史监控经常出现类似情况（TiKV Details -> GC -> TiKV Auto GC SafePoint）

初步断定 GC 运行异常导致历史版本堆积，引发查询效率变慢。

下一步找出证据佐证这个猜想。

第三招，确认非预期的操作

慢查询日志里面有两个和 Coprocessor Task 相关的字段可以验证这个猜想，他们是：

Total_keys：表示 Coprocessor 扫过的 key 的数量。

Process_keys：表示 Coprocessor 处理的 key 的数量。相比 total_keys，processed_keys 不包含 MVCC 的旧版本。如果 processed_keys 和 total_keys 相差很大，说明旧版本比较多。

但是介入排查的时候离异常时间已经过去快一天了，用户只保留了 30 个日志文件，并且慢查询阈值调到了 100ms，也就意味着当时产生的 Slow Query Log 已经没有了，难受。。

最后把希望寄托在tidb.log的 Expensive Query 上面，排查问题时间段发现了很多delete where limit 10000000这种操作，表数据量在千万级，和应用端确认后是由手动执行产生。（DBA 看了这种 SQL 想抄起眼前的键盘。。）

在排查了多条 Expensive Query 后发现，Total_keys普遍在几亿数量级，而Process_keys在百万数量级，进一步验证了前面的判断。

下一步，要找出数据旧版本太多的原因。

第四招，日志分析

GC 操作是由 TiDB Server 的gc worker模块发起的，这里排查起来就比较方便，只需要去 TiDB Server 搜索日志即可，最后定位到了如下的异常信息：

从上面可以判断，GC 在正常发起（每隔 10 分钟打印一条日志），但是 safepoint 被一个运行中的会话阻塞了，并且给出了事务的开始时间戳（globalMinStartTS），根据这个信息我们可以找到具体的 session：

select instance,id,time,state,info,txnstart from information_schema.cluster_processlist where txnstart like '%xxxxxx%'

到这里拿到 session id 以后可以根据实际情况判断是否需要 kill，但是也别高兴的太早，因为有可能 kill 不掉。。。

关于 kill 不掉的问题在 asktug 吐槽的不少，据社区大佬说是kill 成功了只是 processlist 查出来会残留显示，经过测试 5.4.2 彻底修复了。

如果真的真的真的 kill 了没效果，就只能等着事务自己提交或回滚，要不然就得上重启大法。

值得一提的是，上面的 processlist 查询结果并不一定能查到根源 SQL，也就是说 info 那一列是空值，这可能是单纯由于事务卡着没有提交，而不是某条慢 SQL 导致，这种情况下就要从应用端着手排查了。

第五招，还原真相

整理一下所有思路，得出以下结论：

• duration 升高的原因是数据的历史版本太多，前面说到的频繁 delete 操作导致 tikv 节点资源压力较大，从而影响其他 SQL（从其他 SQL 的 Coprocessor Task wait_time 可以判定）

• 历史版本堆积是因为 gc safepoint 被阻塞，有一个长期未提交的事务（从 safepoint 监控图也可以验证）

至此就破案了，一个 gc 引发的惨案浮出水面。而且，这种问题还会带来一个连锁反应，一旦 safepoint 恢复推进，大量的历史版本瞬间被 gc 处理资源消耗极大，又要带来第二波性能抖动，本案真实发生。

预防方案

首先从根源上，应用端要避免大事务操作，或者发起长期不提交的事务，及时提交或回滚。

其次，可以对 TiDB GC 做限流，降低 GC 对系统的整体影响：

另外，从 TiDB v5.1 开始（建议使用 5.1.3 及以上），可以开启 GC in Compaction Filter 特性（默认开启，简单来说就是做 Compaction 的时候顺带把 GC 给做了），能够有效降低 GC 带来的性能抖动问题。

总结

生产环境保留事故现场非常重要，对于日志文件和监控数据条件允许的情况下尽量保留时间长一些，这对于后期排查问题起决定性作用。

另外，这个案例也告诉 TiDB DBA，在对集群做巡检的时候，GC 也是一个重要关注指标，一方面要确保 GC 的相关参数符合预期（比如 gc_life_time 临时调大后忘了调回去），另一方面要确保 GC 运行正常，以免发生上述的性能问题。