Tick missed to fire if Ready() is taking a long time

[manishrjain]

In Dgraph, when we sometimes have to retrieve a snapshot, or if a server gets killed and rejoins the cluster, it takes a while to retrieve the snapshot, or replay the raft logs -- during this time, we get these warnings:

2018/07/19 20:57:18 node.go:400: WARN: A tick missed to fire. Node blocks too long!
2018/07/19 20:57:18 node.go:400: WARN: A tick missed to fire. Node blocks too long!
2018/07/19 20:57:18 node.go:400: WARN: A tick missed to fire. Node blocks too long!

Can we do something about them, and if so what can we do? Should we run ticks in a separate goroutine than Ready? Currently, we have them all in one select loop.

		case <-ticker.C:
			n.Raft().Tick()

		case rd := <-n.Raft().Ready():

[gyuho]

What’s the problem?

Raft.Node.Tick in package raft call itself is not blocking. If previous ticks were queued up, following ticks will be ignored:

// make tickc a buffered chan, so raft node can buffer some ticks when the node
// is busy processing raft messages. Raft node will resume process buffered
// ticks when it becomes idle.
tickc:  make(chan struct{}, 128),

// Tick increments the internal logical clock for this Node. Election timeouts
// and heartbeat timeouts are in units of ticks.
func (n *node) Tick() {
    select {
    case n.tickc <- struct{}{}:
    case <-n.done:
    default:
        n.logger.Warningf("A tick missed to fire. Node blocks too long!")
    }
}

An application calls this Raft.Node.Tick method to increment either election (if follower) or heartbeat (if leader) timeout. Currently, this is how etcd calls Tick:

for {
    select {
    case <-r.ticker.C:
            r.Tick()
    case rd := <-r.Ready():
            ...
            r.Advance()

If <-r.Ready() takes too long to receive or never receives, *time.Ticker.C continues to trigger and queue up all tick channel buffer in package raft.

Real world use cases are:

• Tick missed to fire if Ready() is taking a long time (etcd#9939)
• "Tick missed to fire" issues in dgraph github
• Related user issues in dgraph

What can happen to end-users, and why?

When tick channel buffer is full, a tick call would be ignored (e.g. "A tick missed to fire. Node blocks too long!"). A sequence of tick calls being ignored means that raft loop is not incrementing any timeouts.

Then, what can happen when election or heartbeat timeouts are not progressing at all? In other words, what can happen when the tick channel is full discarding all following tick method calls?

The Raft.Node.Tick method call triggers tickElection (if follower) or tickHeartbeat (if leader) in package raft. Without tickElection calls, a follower can never start a new election and a leader can never run peer health checks. Which means even when a follower is disconnected or a leader is down, the follower would not be able to elect a new leader. Also, it means that the leader will never step down, even if all followers are disconnected (lost quorum). As a result, end-user would experience cluster availabilities.

Then, what would be the reason why election or heartbeat timeouts are not progressing at all? In other words, how can package raft fill up all tick channel buffer, thus dropping all following tick method calls?

As described in etcd#9939, this happens when package raft takes too long time to receive from ready channel, thus for-loop keeps calling r.Tick() method, using up all tick channel buffer.

for {
    select {
    case <-r.ticker.C:
            r.Tick()
    case rd := <-r.Ready():
            ...
            r.Advance()

In etcd, ready channel is used to bundle all ready to commit entries and snapshot:

func newReady(r *raft, prevSoftSt *SoftState, prevHardSt pb.HardState) Ready {
	rd := Ready{
		Entries:          r.raftLog.unstableEntries(),
		CommittedEntries: r.raftLog.nextEnts(),
		Messages:         r.msgs,
	}
	if softSt := r.softState(); !softSt.equal(prevSoftSt) {
		rd.SoftState = softSt
	}
	if hardSt := r.hardState(); !isHardStateEqual(hardSt, prevHardSt) {
		rd.HardState = hardSt
	}
	if r.raftLog.unstable.snapshot != nil {
		rd.Snapshot = *r.raftLog.unstable.snapshot
	}
	if len(r.readStates) != 0 {
		rd.ReadStates = r.readStates
	}
	rd.MustSync = MustSync(r.hardState(), prevHardSt, len(rd.Entries))
	return rd
}

To summarize, this Ready can take long time, that raft loop instead keeps firing node ticks while the Ready is in progress:

In Dgraph, when we sometimes have to retrieve a snapshot, or if a server gets killed and rejoins the cluster, it takes a while to retrieve the snapshot, or replay the raft logs -- during this time, we get these warnings

And I assume it takes long time to fetch Ready.CommittedEntries from disk in dgraph.

What can we do better?

Dgraph uses 20ms for heartbeat https://github.com/dgraph-io/dgraph/blob/0605360b1c7e3dcd565055f809b4dfa768a77eb6/worker/draft.go#L729-L730

func (n *node) Run() {
	defer n.closer.Done() // CLOSER:1

	firstRun := true
	var leader bool
	// See also our configuration of HeartbeatTick and ElectionTick.
	ticker := time.NewTicker(20 * time.Millisecond)
	...

We can try increasing the heartbeat intervals; etcd uses 100ms.

Would increasing heartbeat affect performance? Not really. MsgHeartbeat and MsgHeartbeatResp are mainly used for checking the availability, propagating read index, and follower's progress. MsgSnap or MsgApp may group together in Raft message mailbox, but it doesn't affect the message transport. It may affect the availability, since greater heartbeat means leader check quorum happens less frequent. I suggest making it configurable (e.g. cross region should run with greater heartbeat and election timeouts).

Ideally, receiving Ready does not take too much time, so that node ticks are called in time.

If the Ready has to take longer, what is the expected behavior in application layer?

etcd currently just blocks. Canceling ready call can be problematic. Let's say follower requests leader snapshot, but fetching snapshot in leader takes too long time. Canceling this does not make anything better, because the follower still needs snapshot. It would keep requesting snapshot.

Does etcd Raft package provide useful debugging information? We can improve logging via indicating whether the node is the leader or not. If the tick misses to fire in follower, then the follower may not trigger leadership election. If the tick misses to fire in leader, then the leader may not trigger quorum checks.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 21 days if no further activity occurs. Thank you for your contributions.