tikv region split疑似卡住

Timber · 2022 年5 月 31 日 10:02

【 TiDB 使用环境`】生产环境
【 TiDB 版本】tikv 5.3.1
【遇到的问题】应用中使用cdc组件(Puller)拉取tikv数据用于同步。在拉取过程中cdc卡住，tikv不断尝试region split但未能成功，导致cdc无法继续拉取region数据
【复现路径】不断往tikv中入数据，应用的cdc组件监听这些数据，在不断入数据过程中发现应用无新增数据
【问题现象及影响】现象：应用无法获取tikv region的数据同步，tikv日志和pd日志如下，看起来是region6025多次尝试split但没能成功。请问有什么排查思路吗，非常期待解答，感谢！

【附件】
版本信息
tikv v5.3.1
pd同tikv
tiflow v0.0.0-20220323044833

pd.txt (39.5 KB) tikv.txt (112.2 KB)

neilshen · 2022 年5 月 31 日 12:27

麻烦提供下 TiCDC 的日志以便问题诊断，谢谢！

Timber · 2022 年5 月 31 日 12:50

cdc.txt (8.0 KB)
应用内使用cdc组件的日志已上传附件，感谢查看！

Timber · 2022 年6 月 1 日 02:28

如果应用重启，会直接去用cdc获取tikv的全量数据，这样是不会有问题的，也就是说tikv的split本身应该没问题，但是cdc的组件有几率会在split过程中卡住。

lxzkenney · 2022 年6 月 1 日 03:32

你看下监控， CDC 节点cpu压力是不是特别大，截个图。

neilshen · 2022 年6 月 1 日 03:59

不管有没有 TiCDC，TiKV split 本身不会卡住。
TiCDC “卡住” 一般有以下几种可能

上游写入流量大于下游最大写入流量，导致 checkpoint 推进缓慢。
上游有热点写入，导致 TiKV 频繁 split，leader 频繁切换，导致 checkpoint 推进缓慢。
上游 TiDB/TiKV 突然宕机，导致有事务上的锁残留，导致 checkpoint 推进缓慢。

在解除以上三种情况后，TiCDC 都能自行恢复同步。

Timber · 2022 年6 月 1 日 06:42

好奇pd和tikv日志频繁报日志提示这个region在split且未能成功是怎么回事呢？从cdc上面看这个卡住的情况是没有自动消除的。

neilshen · 2022 年6 月 2 日 07:14

方便贴一下是哪行日志吗？

Timber · 2022 年6 月 2 日 07:21

pd里的 [pd.rs:814] [“try to batch split region”] [task=batch_split] [region="id: 6025
tikv里的 cluster_worker.go:220] [“region batch split, generate new regions”] [region-id=6025]
帖子的附件中有日志原件 : )

neilshen · 2022 年6 月 2 日 14:56

看了下 pd 日志中类似的日志

[2022/05/31 08:59:25.895 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7001 start_key:\"0000000000000000FF0000000600000181FF18F2F9234CA0FBE8FF6BEC000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195690EB4CA0FBEBFFF53A000000000000F9\" region_epoch:<conf_ver:1 version:31 > peers:<id:7002 store_id:1 >"] [total=1]
[2022/05/31 09:00:46.455 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7003 start_key:\"0000000000000000FF0000000700000181FF195690EB4CA0FBEBFFF53A000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195791D24CA0FBEDFF5048000000000000F9\" region_epoch:<conf_ver:1 version:32 > peers:<id:7004 store_id:1 >"] [total=1]
[2022/05/31 09:01:45.568 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7005 start_key:\"0000000000000000FF0000000700000181FF195791D24CA0FBEDFF5048000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195881714CA0FBEEFFAB56000000000000F9\" region_epoch:<conf_ver:1 version:33 > peers:<id:7006 store_id:1 >"] [total=1]
[2022/05/31 09:02:47.631 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7007 start_key:\"0000000000000000FF0000000700000181FF195881714CA0FBEEFFAB56000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195992E54CA0FBF0FF0664000000000000F9\" region_epoch:<conf_ver:1 version:34 > peers:<id:7008 store_id:1 >"] [total=1]
[2022/05/31 09:04:09.733 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7009 start_key:\"0000000000000000FF0000000700000181FF195992E54CA0FBF0FF0664000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195AC2DB4CA0FBF1FF6172000000000000F9\" region_epoch:<conf_ver:1 version:35 > peers:<id:7010 store_id:1 >"] [total=1]
[2022/05/31 09:05:00.685 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7011 start_key:\"0000000000000000FF0000000700000181FF195AC2DB4CA0FBF1FF6172000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195BE9794CA0FBF2FFBC80000000000000F9\" region_epoch:<conf_ver:1 version:36 > peers:<id:7012 store_id:1 >"] [total=1]
[2022/05/31 09:06:23.132 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7013 start_key:\"0000000000000000FF0000000700000181FF195BE9794CA0FBF2FFBC80000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195CFB8D4CA0FBF4FF178E000000000000F9\" region_epoch:<conf_ver:1 version:37 > peers:<id:7014 store_id:1 >"] [total=1]
[2022/05/31 09:07:34.953 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7015 start_key:\"0000000000000000FF0000000700000181FF195CFB8D4CA0FBF4FF178E000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195E03594CA0FBF5FF729C000000000000F9\" region_epoch:<conf_ver:1 version:38 > peers:<id:7016 store_id:1 >"] [total=1]
[2022/05/31 09:08:59.183 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7017 start_key:\"0000000000000000FF0000000700000181FF195E03594CA0FBF5FF729C000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF195EF7E94CA0FBF6FFCDAA000000000000F9\" region_epoch:<conf_ver:1 version:39 > peers:<id:7018 store_id:1 >"] [total=1]
[2022/05/31 09:09:50.048 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7019 start_key:\"0000000000000000FF0000000700000181FF195EF7E94CA0FBF6FFCDAA000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF19605E104CA0FBF8FF28B8000000000000F9\" region_epoch:<conf_ver:1 version:40 > peers:<id:7020 store_id:1 >"] [total=1]
[2022/05/31 09:11:01.477 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7021 start_key:\"0000000000000000FF0000000700000181FF19605E104CA0FBF8FF28B8000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF196154D94CA0FBF9FF83C6000000000000F9\" region_epoch:<conf_ver:1 version:41 > peers:<id:7022 store_id:1 >"] [total=1]
[2022/05/31 09:12:54.641 +00:00] [INFO] [cluster_worker.go:220] ["region batch split, generate new regions"] [region-id=6025] [origin="id:7023 start_key:\"0000000000000000FF0000000700000181FF196154D94CA0FBF9FF83C6000000000000F9\" end_key:\"0000000000000000FF0000000700000181FF1962B1F14CA0FBFAFFDED4000000000000F9\" region_epoch:<conf_ver:1 version:42 > peers:<id:7024 store_id:1 >"] [total=1]

这些日志说明了 ID 为 6025 的 region 是一个写入热点，所以在不断 split。可以看日志中的 start key，在不断变化。

在有写入热点的时候，TiCDC 也能正常工作，但有很大可能会因为下游写入不及上游写入，导致 checkpoint 推进缓慢，lag 不断增加。一般热点写入停止后，过一段时间 checkpoint 就能追上。

Timber · 2022 年6 月 5 日 06:47

非常有用的分析，感谢。现在应用中即使上游停止入数据，下游消费数据卡住的问题还存在。我先继续排查一下看有没有其他的问题

Timber · 2022 年6 月 16 日 06:43

该问题最后结论是应用内部设计有问题，应用内部的死锁导致无法继续消费到cdc的数据。对提出问题耽误了oncall人员的时间表示非常抱歉，非常感谢关注和耐心的解答

system · 2022 年10 月 31 日 19:07

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。