TiDB丨一次TiDB GC阻塞引发的“惨案”......

女爷i 2023-10-02 23:03 39阅读 0赞

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

于是乎，我们就来一场关于TiDB GC阻塞的排查......

###  ***分析过程***  ###

#### ***第一招 初步判断*** ####

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

***\# 1* 高百分位（比如99、999）明显升高**

类似这种：

![7172f6d5644d2b2a00cffa5f88d49359.png][]

它的特点是除了高百分位异常，低分位线也没有明显波动，这是典型的长尾反应。

分位线越高波动越大，说明集群那段时间慢SQL变多，重点关注慢查询辅助排查其他监控即可。

***\# 2*  所有分位线都有明显升高**

类似这种：

![3e5d7a90a17ab9c6eb4528560b60b33a.png][]

上图说明集群内部受到了影响，慢SQL不是导致duration上升的根本原因，而是集群异常表现出来的结果。

但是慢查询依然是我们着手排查的方向之一，慢日志里面记录了慢的一些主要原因，可以作为参考依据。

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

#### *第二招 用监控还原SQL流程*  ####

如果暂时没有明确的排查目标，可以先按SQL读写流程查看主要的监控。

通常在一个业务系统里，读请求是明显要多于写请求的，所以可以从读流程开始排查，先是TiDB再是TiKV。

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

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

*  *问题时间段TPS、QPS相较正常情况无明显波动，各项资源使用率平稳，排除TiDB Server的问题*
 *  *问题时间段TiKV节点负载变大，CPU、磁盘、出口带宽使用率明显上升，可判定查询压力大*
 *  *当前GC safe point无推进，阻塞在约4小时前，排查历史监控经常出现类似情况（TiKV Details -> GC -> TiKV Auto GC SafePoint）*

![19ebd1f020d221ea568355256c87439e.png][]

**初步断定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在百万数量级，进一步验证了前面的判断**。

![248906e6722218d745ba7eae03e06e04.png][]

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

#### *第四招 日志分析*  ####

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

![e303481a0fb26d5c34e90261e9161818.png][]

从上面可以判断，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对系统的整体影响：

![e45f3de069540d2f0c385d64dbd29eca.png][]

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

### ***总结***  ###

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

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

[7172f6d5644d2b2a00cffa5f88d49359.png]: https://img-blog.csdnimg.cn/img_convert/7172f6d5644d2b2a00cffa5f88d49359.png
[3e5d7a90a17ab9c6eb4528560b60b33a.png]: https://img-blog.csdnimg.cn/img_convert/3e5d7a90a17ab9c6eb4528560b60b33a.png
[19ebd1f020d221ea568355256c87439e.png]: https://img-blog.csdnimg.cn/img_convert/19ebd1f020d221ea568355256c87439e.png
[248906e6722218d745ba7eae03e06e04.png]: https://img-blog.csdnimg.cn/img_convert/248906e6722218d745ba7eae03e06e04.png
[e303481a0fb26d5c34e90261e9161818.png]: https://img-blog.csdnimg.cn/img_convert/e303481a0fb26d5c34e90261e9161818.png
[e45f3de069540d2f0c385d64dbd29eca.png]: https://img-blog.csdnimg.cn/img_convert/e45f3de069540d2f0c385d64dbd29eca.png