Continuous high cpu utilisation #1747
Description
System information
Geth version: 1.10.3-stable
OS & Version: Alpine:3.15
Expected behaviour
Quorum should not continuously utilise high cpu when there are no active transactions happening in the network.
Actual behaviour
Quorum is continuously utilising high cpu when there are no active transactions happening in the network and the only way to recover is killing the node.
Steps to reproduce the behaviour
- 35+ node network setup
- Raft consensus is used - The network has been setup before quorum has stable support for ibft, qbft etc. Hence the only stable choice at that time was raft consensus.
- No active transactions are happening at the time when cpu spikes.
Backtrace
raft2025/05/09 06:45:00.315991 INFO: 1d received MsgVoteResp from 1d at term 112627
raft2025/05/09 06:45:00.316017 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 8 at term 112627
raft2025/05/09 06:45:00.316025 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to f at term 112627
2025-05-09 06:45:00,316 DEBG 'geth' stdout output:
raft2025/05/09 06:45:00.316033 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 14 at term 112627
raft2025/05/09 06:45:00.316047 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 22 at term 112627
raft2025/05/09 06:45:00.316054 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 7 at term 112627
raft2025/05/09 06:45:00.316068 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to b at term 112627
raft2025/05/09 06:45:00.316074 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 11 at term 112627
raft2025/05/09 06:45:00.316080 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 1a at term 112627
raft2025/05/09 06:45:00.316090 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 1 at term 112627
raft2025/05/09 06:45:00.316100 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 19 at term 112627
raft2025/05/09 06:45:00.316108 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 18 at term 112627
raft2025/05/09 06:45:00.316113 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 20 at term 112627
raft2025/05/09 06:45:00.316118 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 21 at term 112627
raft2025/05/09 06:45:00.316122 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 3 at term 112627
raft2025/05/09 06:45:00.316132 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 5 at term 112627
raft2025/05/09 06:45:00.316138 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 10 at term 112627
raft2025/05/09 06:45:00.316143 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 13 at term 112627
raft2025/05/09 06:45:00.316159 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 2 at term 112627
raft2025/05/09 06:45:00.316167 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 9 at term 112627
raft2025/05/09 06:45:00.316173 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to a at term 112627
raft2025/05/09 06:45:00.316178 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 1b at term 112627
raft2025/05/09 06:45:00.316187 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 23 at term 112627
raft2025/05/09 06:45:00.316192 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 24 at term 112627
raft2025/05/09 06:45:00.316198 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to c at term 112627
raft2025/05/09 06:45:00.316207 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to d at term 112627
raft2025/05/09 06:45:00.316213 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 12 at term 112627
raft2025/05/09 06:45:00.316218 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 16 at term 112627
raft2025/05/09 06:45:00.316229 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 15 at term 112627
raft2025/05/09 06:45:00.316234 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 17 at term 112627
raft2025/05/09 06:45:00.316239 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 1c at term 112627
raft2025/05/09 06:45:00.316249 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 1e at term 112627
raft2025/05/09 06:45:00.316254 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 4 at term 112627
raft2025/05/09 06:45:00.316259 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 6 at term 112627
2025-05-09 06:45:00,317 DEBG 'geth' stdout output:
raft2025/05/09 06:45:00.316912 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to e at term 112627
raft2025/05/09 06:45:00.316924 INFO: 1d [logterm: 112626, index: 262094] sent MsgVote request to 1f at term 112627
raft2025/05/09 06:45:00.316933 INFO: raft.node: 1d lost leader 15 at term 112627
2025-05-09 06:45:00,599 DEBG 'geth' stdout output:
raft2025/05/09 06:45:00.599364 INFO: 1d received MsgVoteResp rejection from 1b at term 112627
raft2025/05/09 06:45:00.599409 INFO: 1d [quorum:19] has received 1 MsgVoteResp votes and 1 vote rejections
raft2025/05/09 06:45:00.599473 INFO: 1d received MsgVoteResp rejection from a at term 112627
raft2025/05/09 06:45:00.599490 INFO: 1d [quorum:19] has received 1 MsgVoteResp votes and 2 vote rejections
2025-05-09 06:45:00,600 DEBG 'geth' stdout output:
raft2025/05/09 06:45:00.599817 INFO: 1d received MsgVoteResp rejection from d at term 112627
raft2025/05/09 06:45:00.599878 INFO: 1d [quorum:19] has received 1 MsgVoteResp votes and 3 vote rejections
2025-05-09 06:45:00,611 DEBG 'geth' stdout output:
raft2025/05/09 06:45:00.611011 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611068 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611132 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611144 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
2025-05-09 06:45:00,611 DEBG 'geth' stdout output:
raft2025/05/09 06:45:00.611162 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611169 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611186 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611193 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611209 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611220 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611234 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611240 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611255 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611261 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611279 INFO: 1d [term: 112627] ignored a MsgHeartbeat message with lower term from 15 [term: 112626]
raft2025/05/09 06:45:00.611288 INFO: 1d received MsgVoteResp rejection from 15 at term 112627
raft2025/05/09 06:45:00.611302 INFO: 1d [quorum:19] has received 1 MsgVoteResp votes and 4 vote rejections
2025-05-09 06:45:00,650 DEBG 'geth' stdout output:
raft2025/05/09 06:45:00.650435 INFO: 1d received MsgVoteResp rejection from 14 at term 112627
raft2025/05/09 06:45:00.650493 INFO: 1d [quorum:19] has received 1 MsgVoteResp votes and 5 vote rejections
2025-05-09 06:45:00,695 DEBG 'geth' stdout output:
raft2025/05/09 06:45:00.695262 INFO: 1d became follower at term 112627
raft2025/05/09 06:45:00.695306 INFO: raft.node: 1d elected leader 1e at term 112627
2025-05-09 06:45:01,748 DEBG 'geth' stdout output:
2025-05-09 06:45:01.748048 W | rafthttp: the clock difference against peer 2 is too high [1.056380704s > 1s] (prober "ROUND_TRIPPER_SNAPSHOT")
2025-05-09 06:45:02,187 DEBG 'geth' stdout output:
raft2025/05/09 06:45:02.187105 INFO: 1d [term: 112627] received a MsgApp message with higher term from f [term: 112628]
raft2025/05/09 06:45:02.187152 INFO: 1d became follower at term 112628
raft2025/05/09 06:45:02.187164 INFO: raft.node: 1d changed leader from 1e to f at term 112628
raft2025/05/09 06:45:02.187253 INFO: 1d [term: 112628] ignored a MsgVoteResp message with lower term from f [term: 112627]
raft2025/05/09 06:45:02.187266 INFO: 1d [logterm: 112628, index: 262096, vote: 0] rejected MsgVote from f [logterm: 112627, index: 262095] at term 112628
2025-05-09 06:45:02,188 DEBG 'geth' stdout output:
raft2025/05/09 06:45:02.187348 INFO: 1d [term: 112628] ignored a MsgVoteResp message with lower term from 18 [term: 112627]
raft2025/05/09 06:45:02.187427 INFO: 1d [term: 112628] ignored a MsgVote message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187435 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187444 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187450 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187459 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187464 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187471 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187477 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187484 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187489 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187497 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187502 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187511 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187516 INFO: 1d [term: 112628] ignored a MsgHeartbeat message with lower term from 1e [term: 112627]
raft2025/05/09 06:45:02.187525 INFO: 1d [term: 112628] ignored a MsgVoteResp message with lower term from 1e [term: 112627]
2025-05-09 06:45:02,188 DEBG 'geth' stdout output:
raft2025/05/09 06:45:02.188855 INFO: 1d [term: 112628] ignored a MsgVoteResp message with lower term from 6 [term: 112627]
2025-05-09 06:45:02,189 DEBG 'geth' stdout output:
raft2025/05/09 06:45:02.189408 INFO: 1d [term: 112628] ignored a MsgVoteResp message with lower term from 7 [term: 112627]
2025-05-09 06:45:02,192 DEBG 'geth' stdout output:
raft2025/05/09 06:45:02.191311 INFO: 1d [term: 112628] ignored a MsgVoteResp message with lower term from 3 [term: 112627]
2025-05-09 06:45:02,194 DEBG 'geth' stdout output:
raft2025/05/09 06:45:02.194192 INFO: 1d [term: 112628] ignored a MsgVoteResp message with lower term from 1c [term: 112627]
2025-05-09 06:45:02,649 DEBG 'geth' stdout output:
2025-05-09 06:45:02.649554 W | rafthttp: the clock difference against peer 6 is too high [2.161859895s > 1s] (prober "ROUND_TRIPPER_SNAPSHOT")
2025-05-09 06:45:02,698 DEBG 'geth' stdout output:
2025-05-09 06:45:02.697926 W | rafthttp: the clock difference against peer 17 is too high [2.071030396s > 1s] (prober "ROUND_TRIPPER_SNAPSHOT")
2025-05-09 06:45:02,911 DEBG 'geth' stdout output:
2025-05-09 06:45:02.911003 W | rafthttp: the clock difference against peer 11 is too high [2.182313578s > 1s] (prober "ROUND_TRIPPER_SNAPSHOT")
2025-05-09 06:45:03,087 DEBG 'geth' stdout output:
2025-05-09 06:45:03.087214 W | rafthttp: the clock difference against peer 22 is too high [2.046944094s > 1s] (prober "ROUND_TRIPPER_SNAPSHOT")
2025-05-09 06:45:04,768 DEBG 'geth' stdout output:
2025-05-09 06:45:04.768138 W | rafthttp: the clock difference against peer 1e is too high [1.296003651s > 1s] (prober "ROUND_TRIPPER_SNAPSHOT")
2025-05-09 06:45:39,433 DEBG 'geth' stdout output:
2025-05-09 06:45:39.432932 W | rafthttp: the clock difference against peer 21 is too high [1.504098692s > 1s] (prober "ROUND_TRIPPER_SNAPSHOT")
Other evidence
