经常报wait response is cancelled

HACK · 2022 年7 月 21 日 15:15

【 TiDB 使用环境】线上、测试、调研
【 TiDB 版本】
【遇到的问题】

查看tidb.log，发现经常报一些如下WARN内容：
2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx20160] [cause=“context canceled”]
[2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:04:26.993 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx20161] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:07:47.716 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:07:47.751 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]
[2022/07/21 22:07:47.751 +08:00] [WARN] [client_batch.go:625] [“wait response is cancelled”] [to=xxx.xxx.xxx.xxx:20160] [cause=“context canceled”]

to=xxx.xxx.xxx.xxx的地址都是tikv节点的地址，这个是什么问题呀？

【复现路径】做过哪些操作出现的问题
【问题现象及影响】

【附件】

请提供各个组件的 version 信息，如 cdc/tikv，可通过执行 cdc version/tikv-server --version 获取。

HACK · 2022 年7 月 21 日 15:22

看到一个这个帖子，是不是跟dumpling有关系：

有遇到这个问题的吗?

张雨齐0720 · 2022 年7 月 22 日 00:43

wait response is cancelled 。请求发送到 TiKV 后超时未收到 TiKV 响应。需要排查对应地址 TiKV 的响应时间和对应 Region 在当时的 PD 和 KV 日志，确定为什么 KV 未及时响应。

HACK · 2022 年7 月 22 日 03:29

跟踪了一下，我把dumpling的任务停止以后，就不再报这个警告信息了，估计是bug吧

db_user · 2022 年7 月 22 日 03:34

不能算bug，观测下dumpling的时候的集群压力，负载高，iops高，那指定响应慢,看看kv和pd的情况，高负载响应慢是正常情况

HACK · 2022 年7 月 22 日 03:38

我的库非常小，如下是备份所需的时间记录：

===== 开始备份数据库 [dzdz] =====

[2022/07/21 01:00:01.910 +08:00] [INFO] [config.go:158] [“detect server type”] [type=TiDB]

[2022/07/21 01:00:01.910 +08:00] [INFO] [config.go:176] [“detect server version”] [version=4.0.6]

[2022/07/21 01:00:50.422 +08:00] [INFO] [main.go:216] [“dump data successfully, dumpling will exit now”]

不到1分钟就完事了。

HACK · 2022 年7 月 22 日 03:39

我们所有的tidb集群dumpling备份的时间点，都有这个WARN的信息

db_user · 2022 年7 月 22 日 03:42

那辛苦把对应时间段的pd和tikv的日志脱敏导出下吧

HACK · 2022 年7 月 22 日 04:32

我这边tikv节点有点多，我把其中一个实例日志下载下来了，你看看能从里面发现什么线索吗。

补充内容：我的dumpling定时任务是每天凌晨1点开始，在中控机上面，连接到一个tidb server 实例的4000端口，然后进行备份。

出现警告信息的就是那个4000端口的tidb server节点。

cs58_dba · 2022 年7 月 22 日 11:31

是不是正好有大事务，之前mysql 遇到过这种情况，ftwl获取锁的时候，获取不到，备份有问题

HACK · 2022 年7 月 22 日 11:58

应该不是，每次备份的时候都有这个警告信息。

cs58_dba · 2022 年7 月 23 日 02:46

换个时间点备份试一下，或者手动备份看能不能重现错误

HACK · 2022 年7 月 25 日 04:25

你好，请问这个有新的发现吗？

db_user · 2022 年7 月 25 日 05:33

可以拿一部分tikv日志或者pd日志用zip压缩么，我公司电脑这解压不了rar

HACK · 2022 年7 月 25 日 05:35

信息.zip (2.3 MB)

我转换了一下

db_user · 2022 年7 月 25 日 06:01

你好,tikv的日志能辛苦截取下2022/07/21 22:04:26这个附近的日志么，上面的文件没有这个附近的日志，另外请问下pd就三台，如果不是的话，辛苦再截取下pd leader的日志，另外也确定下备份阶段的资源，包括io,网络是否达到极限,如果不是极限的话也有可能是锁的问题

HACK · 2022 年7 月 25 日 06:06

你好,tikv的日志能辛苦截取下2022/07/21 22:04:26这个附近的日志么，上面的文件没有这个附近的日志，

我给你提取一下吧，稍等。

另外请问下pd就三台，如果不是的话，辛苦再截取下pd leader的日志，

pd就三台，附件里面有pd leader的节点的日志。

另外也确定下备份阶段的资源，包括io,网络是否达到极限,如果不是极限的话也有可能是锁的问题。

资源方面没有瓶颈，我这个库很小。

HACK · 2022 年7 月 25 日 06:40

tikv的日志我现在暂时拿不下来，我在服务器上看了几个节点的tikv.log，在那个时间点前后没有报错信息。

我这所有的集群都是这个现象，只要一开始进行dumpling备份，就会有这个警告信息。

system · 2022 年9 月 23 日 06:40

该主题在最后一个回复创建后60天后自动关闭。不再允许新的回复。