Decrease rate of Raft heartbeat messages. #3708
Conversation
A new log "Called n.Raft().Tick()" appears whenever a Raft tick is called.
Running `dgraph increment --num=10000` shows that proposals are going through
just fine. The glog "Called n.Raft().Tick()" is called every 30 seconds.
This doesn't change anything in conn/draft.go, so HeartbeatTick is configured
for 30s and ElectionTick for 100*30s (50 minutes). When we stop an Alpha
Steps to reproduce:
shell 1:
cd ./compose
./run.sh -a 3 -z 3
shell 2:
dgraph increment --alpha localhost:9180 --num=100000
shell 3:
curl localhost:6180/state # check who the leader is
docker stop alpha1 # stop the leader (could be alpha1, alpha2, or alpha3)
See the cluster logs in shell 1 for how long leader election takes.
Ticks happen every 30s, as expected from this change:
I0720 00:21:21.698651 1 draft.go:760] Called n.Raft().Tick().
I0720 00:21:51.698690 1 draft.go:760] Called n.Raft().Tick().
Leadership change detection, according to my understanding, should happen every
50 minutes. But when I stop the leader in shell 3 the leadership election
happens immediately once I stop the leader process with SIGINT.
Setting Raft's HeartbeatTick to 100ms to reduce the number of heartbeats that need to be sent. This changes how often heartbeats are sent, but the election tick is still 2s.
|
Decreasing how the rate of calling tick should reduce the chance of the warning log showing up that says |
There was a problem hiding this comment.
Just make sure you include the reason in the commit message. Otherwise it
Reviewed 2 of 2 files at r1.
Reviewable status:complete! all files reviewed, all discussions resolved (waiting on @manishrjain)
There was a problem hiding this comment.
Reviewed 2 of 2 files at r1.
Reviewable status: all files reviewed, 1 unresolved discussion (waiting on @danielmai)
worker/draft.go, line 730 at r1 (raw file):
var leader bool // See also our configuration of HeartbeatTick and ElectionTick. ticker := time.NewTicker(100 * time.Millisecond)
Add a comment here:
Before we used to have 20ms ticks, but they would overload the Raft tick channel, causing "ticks missed to fire" logs. Etcd uses 100ms and they haven't seen those issues. Additionally, using 100ms for ticks does not cause proposals to slow down, because they get sent out asap and don't rely on ticks. So, setting this to 100ms instead of 20ms is a NOOP.
|
worker/draft.go, line 730 at r1 (raw file): Previously, manishrjain (Manish R Jain) wrote…
Done. |
Before we used to have 20ms ticks, but they would overload the Raft tick channel, causing "A tick missed to fire. Node blocks too long!" logs. Etcd uses 100ms and they haven't seen those issues. Additionally, using 100ms for ticks does not cause proposals to slow down, because they get sent out asap and don't rely on ticks. So, setting this to 100ms instead of 20ms is a NOOP. (cherry picked from commit 4b41d9c)
Before we used to have 20ms ticks, but they would overload the Raft tick channel, causing "A tick missed to fire. Node blocks too long!" logs. Etcd uses 100ms and they haven't seen those issues. Additionally, using 100ms for ticks does not cause proposals to slow down, because they get sent out asap and don't rely on ticks. So, setting this to 100ms instead of 20ms is a NOOP. (cherry picked from commit 4b41d9c)
Setting Raft's HeartbeatTick to 100ms to reduce the number of heartbeats that need to be sent. This changes how often heartbeats are sent but does not affect the time needed for a leader election to occur if the leader is in a network partition (= 100ms * 20 = 2 seconds).
Notes on when leader re-election happens:
These logs all happen within 1-2ms, but above we see that Node 0x2 starts an election at
I0723 01:03:15.444864even before the log message that acknowledges that it lost leader 0x1 atI0723 01:03:15.445199.This change is