背景
前不久从项目一线同学得到某集群的告警信息,某个时间段 TiDB duration 突然异常升高,持续时间6小时左右,需要定位到具体原因。
分析过程
第一招,初步判断
由于项目条件苛刻,历经苦难才拿到监控,在此之前只能靠现场同学的口述排查,oncall人太难了。。
既然是duration升高,那就先看看集群的心电图,试图找出一点线索。一般来说,duration升高会有以下两种情况。
第一种是高百分位(比如99、999)明显升高,类似这种:
它的特点是除了高百分位异常,低分位线没有明显波动,这是典型的长尾反应,分位线越高波动越大,说明集群那段时间慢SQL变多,重点关注慢查询辅助排查其他监控即可。
第二种是所有分位线都有明显升高,类似这种:
这说明集群内部受到了影响,慢SQL不是导致duration上升的根本原因,而是集群异常表现出来的结果。但是慢查询依然是我们着手排查的方向之一,慢日志里面记录了慢的一些主要原因,可以作为参考依据。
这个案例碰到的就是第二种。
第二招,用监控还原SQL流程
如果暂时没有什么明确排查目标,可以先按SQL读写流程看一下主要的监控。通常在一个业务系统里,读请求是明显要多于写请求的,所以可以从读流程开始排查,先是TiDB再是TiKV。
推荐参考社区的Trouble Shooting系列文章,非常实用:
详细流程不再赘述。把这一招用完,基本就能定位到问题了,再结合一些非数据库因素,查明真相指日可待。
针对本次案例中,说一下监控排查结论:
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运行正常,以免发生上述的性能问题。