Seeing increase in "Installing snapshot at index ***" messages after upgrade #232

LarsWithCA · 2024-04-16T15:39:01Z

LarsWithCA
Apr 16, 2024

After upgrading to DotNext.Net.Cluster 5.3.0 (+.NET8) I see the message Installing snapshot at index *** in the leader log every 5-10 minutes.
Before this upgrade (DotNext.Net.Cluster 4.14.1 + .NET8/.NET6) I would almost never see this message.

My setup:

Linux ARM
Cluster with 6 nodes
10Hz communication frequency

Here's an excerpt of the log of one of the nodes in the cluster that receives a snapshot:

...
2024-04-16 09:36:35.9391|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:35.9391|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:35.9391|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:35.9391|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Incoming configuration with 5857771273067105839 fingerprint from leader. Local fingerprint is 5857771273067105839, apply True
2024-04-16 09:36:36.0417|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.0417|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.0417|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:36.0417|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Incoming configuration with 5857771273067105839 fingerprint from leader. Local fingerprint is 5857771273067105839, apply True
2024-04-16 09:36:36.1629|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.1629|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.1629|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:36.2381|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.2381|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.2381|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:36.2470|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Incoming configuration with 5857771273067105839 fingerprint from leader. Local fingerprint is 5857771273067105839, apply True
2024-04-16 09:36:36.3462|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.3462|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.3462|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
2024-04-16 09:36:36.3462|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Incoming configuration with 5857771273067105839 fingerprint from leader. Local fingerprint is 5857771273067105839, apply True
2024-04-16 09:36:36.4395|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgrading to follower state with term 1
2024-04-16 09:36:36.4395|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Election timeout is refreshed
2024-04-16 09:36:36.4395|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member is downgraded to follower state with term 1
...

What I notice here is there is no Incoming configuration with ... around 09:36:36.1629

Here's an excerpt of the log of the leader during the same time (grouped into three "rounds"):

...
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.1:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.202:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.1:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.202:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.31:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.232:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.31:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.232:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.149:4250 started at log index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.31:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.1:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.232:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.149:4250 contains 1 entries. Preceding entry has index 15148 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.0405|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.202:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0475|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.149:4250 is replicated successfully starting from index 15149
2024-04-16 09:36:36.0475|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|All changes up to 15149 index are committed. The number of committed entries is 1

2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.1:4250 started at log index 15150
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.31:4250 started at log index 15150
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.1:4250 contains 1 entries. Preceding entry has index 15149 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.31:4250 contains 1 entries. Preceding entry has index 15149 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.202:4250 started at log index 15150
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.202:4250 contains 1 entries. Preceding entry has index 15149 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.149:4250 started at log index 15150
2024-04-16 09:36:36.1481|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.149:4250 contains 1 entries. Preceding entry has index 15149 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.1:4250 is replicated successfully starting from index 15150
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.31:4250 is replicated successfully starting from index 15150
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.149:4250 is replicated successfully starting from index 15150
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.232:4250 started at log index 15150
2024-04-16 09:36:36.1595|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.202:4250 is replicated successfully starting from index 15150
2024-04-16 09:36:36.1595|INFO|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Installing snapshot at index 15150
2024-04-16 09:36:36.1660|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|All changes up to 15150 index are committed. The number of committed entries is 1
2024-04-16 09:36:36.1660|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.232:4250 is replicated successfully starting from index 15150

2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.202:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.149:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.202:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.149:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.1:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.232:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of member 192.168.100.31:4250 started at log index 15151
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.232:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2370|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.1:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.1:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.202:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Replication of 192.168.100.31:4250 contains 1 entries. Preceding entry has index 15150 and term 1. Local fingerprint is 5857771273067105839, remote is 5857771273067105839, apply True
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.149:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2440|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.232:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2565|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|Member 192.168.100.31:4250 is replicated successfully starting from index 15151
2024-04-16 09:36:36.2565|DEBUG|DotNext.Net.Cluster.Consensus.Raft.RaftCluster|All changes up to 15151 index are committed. The number of committed entries is 1
...

What I noticed here is Installing snapshot at index 15150 at 09:36:36.1595 + no message saying Replication of 192.168.100.232:4250 contains 1 entries in that "round".

Is this something I should be worried about?
What could be the cause of this particular node receiving a snapshot once in a while - as the (almost) only one?
Please let me know if there is something I can do to investigate further.

Cheers,
Lars

LarsWithCA · 2024-04-17T14:17:30Z

LarsWithCA
Apr 17, 2024
Author

I just tried DotNext.Net.Cluster 4.14.1 + .NET8 and I almost never see this message.

0 replies

sakno · 2024-04-18T17:38:35Z

sakno
Apr 18, 2024
Maintainer

What the IP address of the node which receives the snapshot? What kind of log compaction are you using?

7 replies

LarsWithCA Apr 24, 2024
Author

Wouldn't WAL look like 'S' only when a compaction has just happened - which only happens when you exceed 'recordsPerPartition'?
Do all of the compaction modes have a time window where the WAL contains only a snapshot forcing some followers to install the snapshot (instead of getting the log entries they're missing)?

sakno May 2, 2024
Maintainer

happens when you exceed recordsPerPartition

This is correct. I was wrong. However, I still think that the behavior is observable because of aggressive compaction. What's the value of recordsPerPartition? And how frequently you perform writes (and subsequent calls of ForceReplicationAsync)?

LarsWithCA May 2, 2024
Author

recordsPerPartition=50. We write 10 times per second.

sakno May 2, 2024
Maintainer

Installing snapshot at index 15150

This line is taken from the log above. 15150 mod 50 = 0, so the replication of log entry 15150 can be snapshot installation or regular log entry depending on the nature of the last changes.

sakno May 2, 2024
Maintainer

However, I think that the change needs to be reverted. The transfer of snapshot must be avoided if cluster operates normally because the size of snapshot can be large enough to introduce unnecessary latency.

LarsWithCA · 2024-05-03T07:28:36Z

LarsWithCA
May 3, 2024
Author

Messages gone in dev build. Closing.

0 replies

LarsWithCA · 2024-05-08T10:03:02Z

LarsWithCA
May 8, 2024
Author

Fixed in 5.5.0

0 replies

Navigation Menu

Uh oh!

Seeing increase in "Installing snapshot at index ***" messages after upgrade #232

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 4 comments 7 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Uh oh!

Seeing increase in "Installing snapshot at index ***" messages after upgrade #232

Uh oh!

Uh oh!

LarsWithCA Apr 16, 2024

Replies: 4 comments · 7 replies

Uh oh!

LarsWithCA Apr 17, 2024 Author

Uh oh!

sakno Apr 18, 2024 Maintainer

Uh oh!

LarsWithCA Apr 24, 2024 Author

Uh oh!

sakno May 2, 2024 Maintainer

Uh oh!

LarsWithCA May 2, 2024 Author

Uh oh!

sakno May 2, 2024 Maintainer

Uh oh!

sakno May 2, 2024 Maintainer

Uh oh!

LarsWithCA May 3, 2024 Author

Uh oh!

LarsWithCA May 8, 2024 Author

LarsWithCA
Apr 16, 2024

Replies: 4 comments 7 replies

LarsWithCA
Apr 17, 2024
Author

sakno
Apr 18, 2024
Maintainer

LarsWithCA Apr 24, 2024
Author

sakno May 2, 2024
Maintainer

LarsWithCA May 2, 2024
Author

sakno May 2, 2024
Maintainer

sakno May 2, 2024
Maintainer

LarsWithCA
May 3, 2024
Author

LarsWithCA
May 8, 2024
Author