Jjuicefs使用 tikv,kv_batch_rollback 有极高的QPS并且调度时间极其长

请用 Clinic 采集并上传一下 2022/05/26 10:30 ~ 11:30 的数据吧(请注意需要包含 tikv.log。上次采集的数据里没有 tikv.log)。

cleanup.go 用递归来进行重试goruotine暴涨, 是不是需要改成循环控制好上限。 这里为啥不去优化了,从我们倒出的堆栈里面上万个goroutine都是go-tikv 在反复重试递归。 感觉还是得限制下,而不是通过递归无上限的去重试。

日志一致在狂刷,我们只提供了一个日志文件

引用

首先确认一点, 正常情况 peer is not leader for region 2260808 这种提示,肯定是这个region的leader发生了变化, 并且epoch也会变化, 但是我们的日志每秒狂刷上万条get snapshot failed, not leader. 为了验证这个问题,我们都把balance region和balance leader 都关闭了, 并且我们定期dump region 然后分析了下目前每个tikv节点都会有两个region 都说not leader, 然后我们分析对比了下这个region的epoch几乎没变化, 并且leader 也没变化, 但是日志还是在一直狂刷这种日志。 我觉得是这里可能有bug https://github.com/tikv/tikv/blob/v5.3.0/src/storage/txn/scheduler.rs#L515。

[2022/05/26 10:08:49.662 +08:00] [INFO] [scheduler.rs:515] [“get snapshot failed”] [err=“Error(Request(message: "peer is not leader for region 2260808, leader may Some(id: 2337963 store_id: 23)" not_leader { region_id: 2260808 leader { id: 2337963 store_id: 23 } }))”] [cid=746956240]
tikv-2022-5-28-09.zip (131.0 KB)

Leader 变化并不会导致 region epoch 变化。Epoch 主要是反映 raft group 成员的变化以及 region range 的变化。见 https://pingcap.com/zh/blog/tikv-source-code-reading-20。
你所说的随着 leader 变化而变化的应该是 raft term?

之前提供的日志,包括最新这份日志,都是只有 snapshot 拉取端。我需要看一下对端的日志(在最新的这份日志里,对端是 store_id: 23

Clinic 可以自动采集 tikv.log 啊,并不需要人工收集。而且可能需要结合 metrics 一起分析
所以最好是用 Clinic 一起采集上来

上限是有控制的,不过不是控制次数,而是通过 backoff 控制最长 20 秒。见 https://github.com/tikv/client-go/blob/v2.0.0-rc/txnkv/transaction/2pc.go#L1087

goroutine 暴涨跟递归与否无关。不过这可能是另一个问题。见 https://github.com/tikv/client-go/issues/342

最后,TiKV 包括 client-go 都是开源的。如果觉得这个优化很重要,可以考虑自己动手啊。

对,我这里说错了,如果leader发生变化, 应该是raft term +1, 而region 成员变化epoch +1.
好的,我明天看看这个怎么采集。 在跟您同步一个信息,我觉得我们的拓扑结构肯跟不均衡 rack 下面的host数据不均衡。

rack1
jfs001:20160
jfs001:20161

rack2
jfs002:20161
jfs002:20160
jfs007:20160
jfs007:20161

rack3
jfs003:20161
jfs003:20160
jfs008:20160
jfs008:20161

rack4
jfs004:20161
jfs004:20160

rack5
jfs005:20161
jfs005:20160

20s时间应该够。
这个 见 https://github.com/tikv/client-go/issues/342 目前有修复方案吗? 我也看看这块哈。

我们通过clinic 收集的数量级大小是2G+,上传不到平台,因此我们截取了其中一个的tikv日志,
我这里上传了storeid 23 的对应日志
tikv.log.2022-05-26-10.zip (5.6 MB) tikv.log.2022-05-26-11.zip (5.7 MB)

目前应该没有。欢迎在 issue 里一起讨论。

结合前后几次的日志和 metrics,我判断打印 “get snapshot failed” 的原因是这样的:

  1. 这个 get snapshot 是读请求(kv_get、kv_batch_get 等,包括 resolve_lock)处理过程中的一个步骤, 主要是完成 Raft read (见 https://pingcap.com/zh/blog/lease-read)
  2. 在 Raft read 过程中会检查本 peer 是否是 leader。如果不是,会返回 NotLeader 错误 (https://github.com/tikv/tikv/blob/v5.3.0/components/raftstore/src/store/fsm/peer.rs#L3700)
  3. 这时,scheduler 就会打印出类似 “peer is not leader for region 2260661, leader may Some(id: 2337847 store_id: 1079296)” 这行信息
  4. NotLeader 错误会返回到 client。client 收到这个错误信息后,会向新的 leader 重新发起请求 (https://github.com/tikv/client-go/blob/v2.0.0-rc/internal/locate/region_request.go#L1367)

在 TiKV 运行过程中,会由于负载均衡等原因进行 leader 迁移,因此 not leader 错误总是会发生
在这个集群中,由于当时请求量很大、处理延迟比较高,因此,请求 client 在发出请求的时候这个 peer 还是 leader,但等得到调度,leader 已经迁移走了。就会出现 get snapshot failed, peer is not leader

不过,最新的两个日志里全都是 peer is not leader for region 2260661,持续了至少 40 分钟
这个时长有点匪夷所思。这个时段这台机器的 99% gRPC message duration (https://docs.pingcap.com/zh/tidb/v5.3/grafana-tikv-dashboard#grpc) ,有观察到这么长的处理延迟吗?

Raw KV可以使用falllow读的方式么?

TiDB上是可以开启的:
开启 TiDB 的 Follower Read 功能,将变量 tidb_replica_read 的值设置为 followerleader-and-follower 即可:

set [session | global] tidb_replica_read = '<目标值>';

Raw KV 是指 非事务KV ?
非事务KV client-go 目前不支持,但应该是可以实现的
Github 上提个 feature request 吧

ps. 与本帖无关,请新开一贴讨论吧

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