扫码阅读
手机扫码阅读

TiDB丨一次TiDB GC阻塞引发的大排查......

314 2023-09-08


TiDB

神州数码云基地

在 TiDB 上的尝试、调研与分享



TiDB GC 阻塞大排查

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



分析过程

第一招  初步判断

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

# 1

高百分位(比如99、999)明显升高

类似这种:

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

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

# 2

所有分位线都有明显升高

类似这种:

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

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

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

第二招  用监控还原SQL流程

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

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

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

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

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

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

  • 当前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.logExpensive 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运行正常,以免发生上述的性能问题。


关于TiDB GC故障排查

就分享到这儿

希望对遇到类似问题的你

能够有所帮助~~


本期作者

何傲


原文链接: http://mp.weixin.qq.com/s?__biz=Mzg5MzUyOTgwMQ==&mid=2247512661&idx=1&sn=61d9685f84143130c103facdd1aa82a2&chksm=c02f89f3f75800e5143f4e43d66bee43dfc1be0e65c973b9d50516b96a317be4a8647c43b154#rd