wfxxh
(倔强的蜗牛)
1
【TiDB 使用环境】生产环境
【TiDB 版本】v6.5.3
我们有一个单纯的tikv集群,用作kv数据存储,用spark调用tikv-client-java包往里写数据时,有一个节点的leader会突然降到0
tikv日志:
[2025/07/04 16:10:00.666 +08:00] [INFO] [mod.rs:2271] ["get snapshot failed"] [err="Error(Txn(Error(Engine(Error(Request(message: \"peer is not leader for region 274942, leader may Some(id: 274944 store_id: 10)\" not_leader { region_id: 274942 leader { id: 274944 store_id: 10 } }))))))"] [tag=raw_put] [thread_id=89]
[2025/07/04 16:10:00.667 +08:00] [INFO] [mod.rs:2271] ["get snapshot failed"] [err="Error(Txn(Error(Engine(Error(Request(message: \"peer is not leader for region 226633, leader may Some(id: 226636 store_id: 10)\" not_leader { region_id: 226633 leader { id: 226636 store_id: 10 } }))))))"] [tag=raw_put] [thread_id=93]
[2025/07/04 16:10:00.667 +08:00] [INFO] [mod.rs:2271] ["get snapshot failed"] [err="Error(Txn(Error(Engine(Error(Request(message: \"peer is not leader for region 289116, leader may Some(id: 289118 store_id: 2)\" not_leader { region_id: 289116 leader { id: 289118 store_id: 2 } }))))))"] [tag=raw_put] [thread_id=93]
tikv配置如下:
最终任务会失败,日志为:
有猫万事足
2
最好能提供一个完整的tikv日志。这个info信息看不出来什么。
你看看这个类似的,含有
peer is not leader
这段字符的issue。
https://github.com/tikv/tikv/issues/18005
处理的也是error报错。
wfxxh
(倔强的蜗牛)
3
完整的太大了传不上来。
[2025/07/07 13:50:59.111 +08:00] [INFO] [raft.rs:1944] ["[term 17] starts to transfer leadership to 289638"] [lead_transferee=289638] [term=17] [raft_id=2740
55] [region_id=274052] [thread_id=247]
[2025/07/07 13:50:59.111 +08:00] [INFO] [raft.rs:1957] ["sends MsgTimeoutNow to 289638 immediately as 289638 already has up-to-date log"] [lead_transferee=28
9638] [raft_id=274055] [region_id=274052] [thread_id=247]
[2025/07/07 13:50:59.111 +08:00] [INFO] [peer.rs:3946] ["transfer leader"] [peer="id: 294400 store_id: 19"] [peer_id=294402] [region_id=294399] [thread_id=24
7]
[2025/07/07 13:50:59.111 +08:00] [INFO] [raft.rs:1944] ["[term 10] starts to transfer leadership to 294400"] [lead_transferee=294400] [term=10] [raft_id=2944
02] [region_id=294399] [thread_id=247]
[2025/07/07 13:50:59.111 +08:00] [INFO] [raft.rs:1957] ["sends MsgTimeoutNow to 294400 immediately as 294400 already has up-to-date log"] [lead_transferee=29
4400] [raft_id=294402] [region_id=294399] [thread_id=247]
[2025/07/07 13:50:59.112 +08:00] [INFO] [peer.rs:3946] ["transfer leader"] [peer="id: 7609 store_id: 2"] [peer_id=276006] [region_id=7607] [thread_id=247]
[2025/07/07 13:50:59.112 +08:00] [INFO] [raft.rs:1944] ["[term 17] starts to transfer leadership to 7609"] [lead_transferee=7609] [term=17] [raft_id=276006]
[region_id=7607] [thread_id=247]
[2025/07/07 13:50:59.112 +08:00] [INFO] [raft.rs:1957] ["sends MsgTimeoutNow to 7609 immediately as 7609 already has up-to-date log"] [lead_transferee=7609]
[raft_id=276006] [region_id=7607] [thread_id=247]
[2025/07/07 13:50:59.112 +08:00] [INFO] [raft.rs:1386] ["received a message with higher term from 294400"] ["msg type"=MsgRequestVote] [message_term=11] [ter
m=10] [from=294400] [raft_id=294402] [region_id=294399] [thread_id=246]
[2025/07/07 13:50:59.112 +08:00] [INFO] [raft.rs:1151] ["became follower at term 11"] [term=11] [raft_id=294402] [region_id=294399] [thread_id=246]
[2025/07/07 13:50:59.112 +08:00] [INFO] [raft.rs:1605] ["[logterm: 10, index: 12204, vote: 0] cast vote for 294400 [logterm: 10, index: 12204] at term 11"] [
"msg type"=MsgRequestVote] [term=11] [msg_index=12204] [msg_term=10] [from=294400] [vote=0] [log_index=12204] [log_term=10] [raft_id=294402] [region_id=29439
9] [thread_id=246]
[2025/07/07 13:50:59.112 +08:00] [INFO] [endpoint.rs:784] ["deregister observe region"] [observe_id=ObserveId(3684)] [region_id=294399] [store_id=Some(3)] [t
hread_id=205]
[2025/07/07 13:50:59.113 +08:00] [INFO] [raft.rs:1386] ["received a message with higher term from 289638"] ["msg type"=MsgRequestVote] [message_term=18] [ter
m=17] [from=289638] [raft_id=274055] [region_id=274052] [thread_id=246]
[2025/07/07 13:50:59.113 +08:00] [INFO] [raft.rs:1151] ["became follower at term 18"] [term=18] [raft_id=274055] [region_id=274052] [thread_id=246]
[2025/07/07 13:50:59.113 +08:00] [INFO] [raft.rs:1605] ["[logterm: 17, index: 21084, vote: 0] cast vote for 289638 [logterm: 17, index: 21084] at term 18"] [
"msg type"=MsgRequestVote] [term=18] [msg_index=21084] [msg_term=17] [from=289638] [vote=0] [log_index=21084] [log_term=17] [raft_id=274055] [region_id=27405
2] [thread_id=246]
[2025/07/07 13:50:59.113 +08:00] [INFO] [endpoint.rs:784] ["deregister observe region"] [observe_id=ObserveId(2326)] [region_id=274052] [store_id=Some(3)] [t
hread_id=205]
[2025/07/07 13:50:59.115 +08:00] [INFO] [mod.rs:2271] ["get snapshot failed"] [err="Error(Txn(Error(Engine(Error(Request(message: \"peer is not leader for re
gion 44071, leader may Some(id: 277215 store_id: 1)\" not_leader { region_id: 44071 leader { id: 277215 store_id: 1 } }))))))"] [tag=raw_put] [thread_id=91]
[2025/07/07 13:50:59.119 +08:00] [INFO] [mod.rs:2271] ["get snapshot failed"] [err="Error(Txn(Error(Engine(Error(Request(message: \"peer is not leader for re
gion 304307, leader may Some(id: 304309 store_id: 10)\" not_leader { region_id: 304307 leader { id: 304309 store_id: 10 } }))))))"] [tag=raw_put] [thread_id=
87]
[2025/07/07 13:50:59.120 +08:00] [INFO] [mod.rs:2271] ["get snapshot failed"] [err="Error(Txn(Error(Engine(Error(Request(message: \"peer is not leader for re
gion 23232, leader may Some(id: 23235 store_id: 10)\" not_leader { region_id: 23232 leader { id: 23235 store_id: 10 } }))))))"] [tag=raw_put] [thread_id=89]
[2025/07/07 13:50:59.121 +08:00] [INFO] [pd.rs:1526] ["try to transfer leader"] [to_peers="[id: 297503 store_id: 1, id: 287041 store_id: 2]"] [to_peer="id: 2
87041 store_id: 2"] [from_peer="id: 287043 store_id: 3"] [region_id=287040] [thread_id=40]
[2025/07/07 13:50:59.121 +08:00] [INFO] [pd.rs:1526] ["try to transfer leader"] [to_peers="[id: 293234 store_id: 2, id: 293233 store_id: 19]"] [to_peer="id:
293233 store_id: 19"] [from_peer="id: 293235 store_id: 3"] [region_id=293232] [thread_id=40]
[2025/07/07 13:50:59.121 +08:00] [INFO] [pd.rs:1526] ["try to transfer leader"] [to_peers="[id: 301331 store_id: 1, id: 301329 store_id: 2]"] [to_peer="id: 3
01329 store_id: 2"] [from_peer="id: 301330 store_id: 3"] [region_id=301328] [thread_id=40]
[2025/07/07 13:50:59.122 +08:00] [INFO] [peer.rs:3946] ["transfer leader"] [peer="id: 297503 store_id: 1"] [peer_id=287043] [region_id=287040] [thread_id=246
]
[2025/07/07 13:50:59.122 +08:00] [INFO] [raft.rs:1944] ["[term 13] starts to transfer leadership to 297503"] [lead_transferee=297503] [term=13] [raft_id=2870
43] [region_id=287040] [thread_id=246]
[2025/07/07 13:50:59.122 +08:00] [INFO] [raft.rs:1957] ["sends MsgTimeoutNow to 297503 immediately as 297503 already has up-to-date log"] [lead_transferee=29
7503] [raft_id=287043] [region_id=287040] [thread_id=246]
[2025/07/07 13:50:59.122 +08:00] [INFO] [mod.rs:2271] ["get snapshot failed"] [err="Error(Txn(Error(Engine(Error(Request(message: \"peer is not leader for re
gion 299198, leader may Some(id: 299199 store_id: 19)\" not_leader { region_id: 299198 leader { id: 299199 store_id: 19 } }))))))"] [tag=raw_put] [thread_id=
89]
[2025/07/07 13:50:59.123 +08:00] [INFO] [peer.rs:3946] ["transfer leader"] [peer="id: 293233 store_id: 19"] [peer_id=293235] [region_id=293232] [thread_id=24
7]
[2025/07/07 13:50:59.123 +08:00] [INFO] [raft.rs:1944] ["[term 10] starts to transfer leadership to 293233"] [lead_transferee=293233] [term=10] [raft_id=2932
35] [region_id=293232] [thread_id=247]
[2025/07/07 13:50:59.123 +08:00] [INFO] [raft.rs:1957] ["sends MsgTimeoutNow to 293233 immediately as 293233 already has up-to-date log"] [lead_transferee=29
3233] [raft_id=293235] [region_id=293232] [thread_id=247]
[2025/07/07 13:50:59.123 +08:00] [INFO] [mod.rs:2271] ["get snapshot failed"] [err="Error(Txn(Error(Engine(Error(Request(message: \"peer is not leader for re
gion 22770, leader may Some(id: 22772 store_id: 2)\" not_leader { region_id: 22770 leader { id: 22772 store_id: 2 } }))))))"] [tag=raw_put] [thread_id=91]
[2025/07/07 13:50:59.123 +08:00] [INFO] [peer.rs:3946] ["transfer leader"] [peer="id: 301331 store_id: 1"] [peer_id=301330] [region_id=301328] [thread_id=246
]
[2025/07/07 13:50:59.123 +08:00] [INFO] [raft.rs:1944] ["[term 7] starts to transfer leadership to 301331"] [lead_transferee=301331] [term=7] [raft_id=301330
] [region_id=301328] [thread_id=246]
[2025/07/07 13:50:59.123 +08:00] [INFO] [raft.rs:1957] ["sends MsgTimeoutNow to 301331 immediately as 301331 already has up-to-date log"] [lead_transferee=30
1331] [raft_id=301330] [region_id=301328] [thread_id=246]
[2025/07/07 13:50:59.124 +08:00] [INFO] [raft.rs:1386] ["received a message with higher term from 293233"] ["msg type"=MsgRequestVote] [message_term=11] [ter
m=10] [from=293233] [raft_id=293235] [region_id=293232] [thread_id=247]
[2025/07/07 13:50:59.124 +08:00] [INFO] [raft.rs:1151] ["became follower at term 11"] [term=11] [raft_id=293235] [region_id=293232] [thread_id=247]
[2025/07/07 13:50:59.124 +08:00] [INFO] [raft.rs:1605] ["[logterm: 10, index: 55991, vote: 0] cast vote for 293233 [logterm: 10, index: 55991] at term 11"] [
"msg type"=MsgRequestVote] [term=11] [msg_index=55991] [msg_term=10] [from=293233] [vote=0] [log_index=55991] [log_term=10] [raft_id=293235] [region_id=29323
2] [thread_id=247]
[2025/07/07 13:50:59.124 +08:00] [INFO] [endpoint.rs:784] ["deregister observe region"] [observe_id=ObserveId(2108)] [region_id=293232] [store_id=Some(3)] [t
hread_id=205]
[2025/07/07 13:50:59.124 +08:00] [INFO] [raft.rs:1386] ["received a message with higher term from 297503"] ["msg type"=MsgRequestVote] [message_term=14] [ter
m=13] [from=297503] [raft_id=287043] [region_id=287040] [thread_id=247]
[2025/07/07 13:50:59.124 +08:00] [INFO] [raft.rs:1151] ["became follower at term 14"] [term=14] [raft_id=287043] [region_id=287040] [thread_id=247]
[2025/07/07 13:50:59.124 +08:00] [INFO] [raft.rs:1605] ["[logterm: 13, index: 10997, vote: 0] cast vote for 297503 [logterm: 13, index: 10997] at term 14"] [
"msg type"=MsgRequestVote] [term=14] [msg_index=10997] [msg_term=13] [from=297503] [vote=0] [log_index=10997] [log_term=13] [raft_id=287043] [region_id=28704
0] [thread_id=247]
[2025/07/07 13:50:59.124 +08:00] [INFO] [endpoint.rs:784] ["deregister observe region"] [observe_id=ObserveId(4011)] [region_id=287040] [store_id=Some(3)] [t
hread_id=205]
有猫万事足
4
[2025/07/07 13:50:59.112 +08:00] [INFO] [raft.rs:1151] [“became follower at term 11”] [term=11] [raft_id=294402] [region_id=294399] [thread_id=246]
[2025/07/07 13:50:59.123 +08:00] [INFO] [raft.rs:1944] [“[term 7] starts to transfer leadership to 301331”] [lead_transferee=301331] [term=7] [raft_id=301330
] [region_id=301328] [thread_id=246]
这个日志看起来没什么问题,类似上面这种transfer leader的情况很多,所以会有peer is not leader一点也不奇怪。
要硬说的话,java-client应该能自己处理这个错误,从pd更新对应region的信息并放入缓存,然后自己重试访问正确的tikv才对。不应该直接报错抛出异常。最起码之前看go-client应该就是这么处理的。
我个人感觉更像是java-client的bug,或者java-client的版本的问题。从tikv侧,我觉得没啥问题。
https://github.com/tikv/client-java/issues/687
这个是个类似的问题,报错的调用堆栈和你上面的差不多,就是行数不太一样。
有猫万事足
6
你提醒我了,你说的对。我忘了有一个tikv leader都掉0了。这个肯定不正常。
把transfer leader很多和有一个tikv leader掉0结合一起来看的话,建议查查带宽是不是被打满了。
之前碰到过,rawkv写入太猛,导致带宽被打满了。
然后就各种奇怪的问题,查了半天。 
随缘天空
(Ti D Ber Ivw R7o Pj)
7
查看下该tikv节点状态是否正常,以及网络带宽是否满了,还有写热点问题
有猫万事足
9
如果tikv的日志上看不到什么问题,还有个思路就是查查pd为什么要这么调度。
看看pd Scheduler相关的监控找找看。
wfxxh
(倔强的蜗牛)
11
我的系统盘性能很低,虽然系统盘和tikv数据盘是独立的两个盘。观察到写入tikv时,当某一tikv leader 降到0的时候,系统盘 io 也是打满的。
1 个赞
有猫万事足
12
找找看是不是那个leader掉0的这个slow store score比较高?看看故障时间段的监控。
wfxxh
(倔强的蜗牛)
13
好像不太一样啊,61 和 62 都很高,但只有62的leader降到了0
有猫万事足
14
但只有62的leader降到了0
这个是符合预期的,因为如果2个tikv的leader都evict,那某些raft组的多数派就没办法维持了。所以2个都高的情况下只能evict一个。
这么看的话leader掉0的主要原因,就是evict slow store。如果确定你的盘很慢,我感觉可以考虑去掉evict slow store 这个scheduler。
你可以看看这个帖子,里面对于slow store的讨论是比较全面的。从判断机制,到解决方法。
以往掉0,我会第一时间感觉是slow store的问题。这次我没有第一时间怀疑是slow store,主要是以往碰到的都是瞬间掉下去,很快又回来。你这个leader掉0持续10几分钟的,比较少见。你后面不提一句盘性能不行,我真没往这个方向上想过。 
1 个赞
wfxxh
(倔强的蜗牛)
15
刚才说错了,系统盘io不高,是其它服务的盘io很高,但是这个曲线的确能对的上,难道pd调度的时候还会检测其它非tikv盘的io情况吗
1 个赞
有猫万事足
16
你注意翻我发的那个帖子。
里面讲的比较清楚的,判断机制是,readpool的排队时间上升,grpc的RPS(每秒请求数)下降。当这2个事件同时发生,就认为这个store是slow store。
换句话说,不管你怎么看io,这个store一定是grpc请求也下滑了,排队时间也上升了。才会导致被evict leader。
system
(system)
关闭
17
此话题已在最后回复的 7 天后被自动关闭。不再允许新回复。