P99 gRPC message duration 异常

🪐 TiDB 技术问题 性能调优
,
1

【 TiDB 使用环境】生产环境
【 TiDB 版本】V4.0.5
【遇到的问题：问题现象及影响】
线上业务 gRPC message duration 经常变大，分析下来是 Commit log duration 变大的原因（基本 Commit log duration 涨多少 gRPC message duration 也涨多少），看官方有以下说明：

Commit log duration 是 Raftstore 将 Raft 日志提交到相应 Region 的多数成员所花费的时间。如果该指标的值较高且波动较大，可能的原因有：

  • Raftstore 的负载较高
  • append log 较慢
  • Raft 日志由于网络阻塞无法及时提交

自己分析：raftstore.store-pool-size=8，延迟大时也只有 380% 左右，负载不高。append log 延迟监控中没变化也不是。那大概率是网络阻塞的原因了，另外官方也有说 raft 有流控机制可能会限制 tcp 传输，想请教大佬们有哪个指标或者日志能看到流控相关，如果分析的有不对的地方也请教下

raft commit log 慢。TiKV Grafana 的 Raft I/O 和 commit log duration 比较高（4.x 版本的 Grafana 才有该 metric）。每个 Region 对应一个独立的 Raft group，Raft 本身是有流控机制的，类似 TCP 的滑动窗口机制，通过参数 [raftstore] raft-max-inflight-msgs = 256 来控制滑动窗口的大小，如果有热点写入并且 commit log duration 比较高可以适度调大改参数，比如 1024。

image
image1664×960 226 KB

image
image1618×290 79.5 KB

官方文档：
海量 Region 集群调优最佳实践 | TiDB 文档中心 (pingcap.com)

TiDB 磁盘 I/O 过高的处理办法 | TiDB 文档中心 (pingcap.com)

【资源配置】

2

https://docs.pingcap.com/zh/tidb/stable/grafana-overview-dashboard#system-info

这个面板下面的tcp retrans有异常嘛？网络没问题的话，增大滑动窗口确实对小的网络抖动会容忍度高一些，如果网络的问题不解决，只调大滑动窗口，感觉作用有限。

3

配置的原因没有加这个面板。应该也不是服务器网络的原因，因为一般出现这种情况时，restart 这个节点就又恢复正常了。还没调这个参数，不清楚效果如何，想先来问问大家有没有碰到过类似问题

4

commit log 延迟变大时，tikv 的日志如下，看起来是 rcp 连接异常了，但其它时间点也经常有这类错

[2024/10/11 02:34:48.638 +00:00] [WARN] [raft_client.rs:296] [“RPC batch_raft fail”] [err=“Some(RpcFailure(RpcStatus { status: 1-CANCELLED, details: Some("Cancelled") }))”] [sink_err=“Some(RpcFinished(Some(RpcStatus { status: 1-CANC
ELLED, details: Some("Cancelled") })))”] [to_addr=172.16.120.56:20160]
[2024/10/11 02:34:48.638 +00:00] [INFO] [store.rs:2108] [“broadcasting unreachable”] [unreachable_store_id=10659048] [store_id=621378]
[2024/10/11 02:34:48.638 +00:00] [WARN] [raft_client.rs:199] [“send to 172.16.120.56:20160 fail, the gRPC connection could be broken”]
[2024/10/11 02:34:48.639 +00:00] [ERROR] [transport.rs:163] [“send raft msg err”] [err=“Other("[src/server/raft_client.rs:208]: RaftClient send fail")”]
[2024/10/11 02:34:48.639 +00:00] [INFO] [raft_client.rs:48] [“server: new connection with tikv endpoint”] [addr=172.16.120.56:20160]
[2024/10/11 02:34:48.640 +00:00] [INFO] [transport.rs:144] [“resolve store address ok”] [addr=172.16.120.56:20160] [store_id=10659048]
[2024/10/11 02:34:48.654 +00:00] [INFO] [] [“New connected subchannel at 0x7f3c77f1c7d0 for subchannel 0x7f3c84db3e80”]
[2024/10/11 02:34:55.882 +00:00] [INFO] [peer.rs:900] [“failed to schedule peer tick”] [err=“sending on a disconnected channel”] [tick=CHECK_PEER_STALE_STATE] [peer_id=10878347] [region_id=10598774]

[2024/10/11 03:46:30.916 +00:00] [WARN] [raft_client.rs:296] [“RPC batch_raft fail”] [err=“Some(RpcFailure(RpcStatus { status: 1-CANCELLED, details: Some("Cancelled") }))”] [sink_err=“Some(RpcFinished(Some(RpcStatus { status: 1-CANCELLED, details: Some("Cancelled") })))”] [to_addr=172.16.110.110:20160]
[2024/10/11 03:46:30.916 +00:00] [INFO] [store.rs:2108] [“broadcasting unreachable”] [unreachable_store_id=10698785] [store_id=621378]
[2024/10/11 03:46:30.917 +00:00] [WARN] [raft_client.rs:199] [“send to 172.16.110.110:20160 fail, the gRPC connection could be broken”]
[2024/10/11 03:46:30.919 +00:00] [ERROR] [transport.rs:163] [“send raft msg err”] [err=“Other("[src/server/raft_client.rs:208]: RaftClient send fail")”]
[2024/10/11 03:46:30.922 +00:00] [INFO] [transport.rs:144] [“resolve store address ok”] [addr=172.16.110.110:20160] [store_id=10698785]
[2024/10/11 03:46:30.922 +00:00] [INFO] [raft_client.rs:48] [“server: new connection with tikv endpoint”] [addr=172.16.110.110:20160]
[2024/10/11 03:46:30.923 +00:00] [INFO] [transport.rs:144] [“resolve store address ok”] [addr=172.16.110.110:20160] [store_id=10698785]
[2024/10/11 03:46:30.940 +00:00] [INFO] [] [“New connected subchannel at 0x7f3cf7d22cf0 for subchannel 0x7f3c7dccec00”]
[2024/10/11 03:46:52.654 +00:00] [INFO] [size.rs:171] [“approximate size over threshold, need to do split check”] [threshold=150994944] [size=154676072] [region_id=10691942]
[2024/10/11 03:46:53.755 +00:00] [INFO] [split_check.rs:283] [“update approximate size and keys with accurate value”] [keys=2310373] [size=140101646] [region_id=10691942]
[2024/10/11 03:46:53.760 +00:00] [WARN] [mod.rs:89] [“handle task [split check worker] Split Check Task for 10691942, auto_split: true”] [takes=1104]

5

像是bug。最好的办法还是升级，4.0都已经EOL了。实在不行也要尝试升到子版本最新看看。4.0.5还是有点低。

6

历史原因还没法升级，这就很尴尬了 :rofl:

1 个赞