ticdc 延迟非常高后台一直刷 The resolvedTs is fallen back in kvclient

leoones · 2022 年8 月 29 日 11:21

【概述】场景 + 问题概述
tidb&pd 混部 3个节点，ticdc 2个节点，tikv 11个
下午tidb集群3个tidb节点 oom。导致ticdc 很多任务停滞。后台一直刷日志
The resolvedTs is fallen back in kvclient

【背景】做过哪些操作
重启过整个集群
单独重启过tikv所有节点，
单独重启过cdc服务

【问题】当前遇到的问题
ticdc还在一直刷日志。

【业务影响】
影响数据推送，业务数据延迟。影响用户。
【TiDB 版本】
V5.4.0

【附件】相关日志及监控（https://metricstool.pingcap.com/)

xiaohetao · 2022 年8 月 29 日 11:58

你重启tikv 前ticdc 是什么状态？

leoones · 2022 年8 月 29 日 12:37

cdc任务是normal状态

leoones · 2022 年8 月 29 日 13:03

有什么办法可以解决么

tidb狂热爱好者 · 2022 年8 月 29 日 14:07

环境

集群版本：v5.1.2

Tidb server：16c 32g 7 台

Ticdc 机器：16c 64g 2 台高可用

问题发生版本：v4.0.9 v4.0.13 v5.1.2

Tidb server 发生 oom 后，ticdc checkpointTs 不向前推进，尝试 pause changefeed 后未恢复，尝试使用 tiup 重启 cdc 组件后未恢复。

检查 ticdc 日志出现大量 warning 日志：

[2022/01/30 11:17:55.761 +08:00] [WARN] [region_worker.go:377] [“region not receiving resolved event from tikv or resolved ts is not pushing for too long time, try to resolve lock”] [regionID=40982339] [span=”[7480000000000016ffa05f72f000000019ff3a9b7b0000000000fa, 7480000000000016ffa05f72f000000019ff7319ad0000000000fa)“] [duration=17m21.65s] [lastEvent=93.273628ms] [resolvedTs=430836713476849684]

[2022/01/30 11:17:55.771 +08:00] [WARN] [region_worker.go:743] [“The resolvedTs is fallen back in kvclient”] [“Event Type”=RESOLVED] [resolvedTs=430836713699672811] [lastResolvedTs=430836984350245604] [regionID=31134532]

TiDB server oom 监控

Tidb cdc 监控

问题排查

TiDB server oom 原因排查

从相关慢查询中

初步排查结果是研发当时查询 dashboard 慢查询页面导致 tidb server 发生 oom

dashboard 的慢查询页面导致 oom，从 4.0 版本到 5.1.2 版本，曾经多次发生，目前版本还存在该问题，在未来的版本中会得到修复。

目前的缓解方案：

尽可能减少 slow-log 文件的数量比如定期做 slow log 的归档删除或设置 log.file.max-days，调大 slow query 的阈值 log.slow-threshold。
在查询时选择时间范围选小一点，比如一小时以内，并尽量避免多人并发查询 slow query 。
查询时尽量不要使用 order by 排序功能。

目前 tidb 在分析 oom 问题上提供了一个 oom tracker 工具，能将当时的 top memory sql 以及 heap 统计到 tidb server 的 tmp 目录下以供分析，较以前版本来说，排查问题相对简单容易很多。

TiCDC 问题排查

从监控中可以看到，在 tidb server oom 后，部分 tikv 节点中 resolved-lag 增大

通过 cdc 研发人员确认，tidb 在事务中对相关表加乐观或悲观锁，当 tidb server oom 后，相关锁未正常释放，且 region merge 会阻塞 resolveLock 功能，导致 lock 无法释放

在最新的 5.1.4 版本中，已经修复了该问题

问题处理

5.1.4 版本及之后版本

tidb server oom 后 cdc 进程 checkpointTs 不向前推进问题可以得到解决，不需要特别进行处理。

5.1.4 之前的版本需要手动处理

Workaround：

上一次出现类似问题，使用 select count(*) from tb_name，通过对表做 count 操作来释放相关锁。

也有可能会遇到 count 表后没有恢复的情况。

如果是悲观锁的话，select count 无法解锁，也有可能锁存在于 index 上，select 需要使用 use index，即每一个 index 都 count 一次。

如何判断 count 后锁是否被释放

当 count(*) 后启动 changefeed 进程且 cdc log 中出现大量 ”The resolvedTs is fallen back in kvclient” 日志时，说明锁未被释放。释放锁之前建议暂停问题链路，问题链路会导致正常链路 checkpointTs 也不向前推进的情况。

问题修复：kv client 触发 resolved lock 的逻辑有问题，不能及时触发，详见：

https://github.com/pingcap/tiflow/issues/2867

ticdc 延迟非常高 后台一直刷 The resolvedTs is fallen back in kvclient

环境