Cutting etcd/raft failover from 1.25 s to 343 ms, checked against 2,000 simulated leader crashes

When the leader of a three-node etcd/raft cluster dies, the other two servers wait between 1 and 1.9 seconds before one of them holds an election. That's with a tick every 100 ms and the settings from etcd/raft's README: ElectionTick 10 and HeartbeatTick 1. Until a new leader is in place, no write commits. I wanted that gap under a second.

Lowering ElectionTick is a one-line change. What I didn't know was what it does once servers crash and links drop. On a test cluster I could kill leaders and time the gap, but every attempt sees different timing. When one is slow, there's no way to run it again and see why.

So I tried it with faultline, the deterministic simulation testing tool for Go I've been building. Version 0.1.1 came out today. A faultline test runs a distributed system in virtual time on a simulated network and disk. Every random choice in the simulation comes from a seed, so a run replays exactly.

faultline includes a harness for etcd/raft v3.7.0. It runs a cluster of RawNodes with a write-ahead log on the simulated disk and clients that write and read keys, and checks raft's safety properties after every event. It tests the raft library with your settings. The key-value store, the log and the transport on top are the harness's own, not your service's.

Is a shorter timeout still safe?

I started with safety. The first test runs 500 seeds with elections after 3 ticks instead of 10. Each seed runs 60 seconds of virtual time under partitions, an isolated leader, cut and lossy links, crashes, pauses, failed disk syncs and clock drift. The last 10 seconds are quiet, and the cluster must make progress again.

func TestFastElectionsStaySafe(t *testing.T) {
    cfg := etcdraft.DefaultConfig()
    cfg.ElectionTick = 3 // elections after 3 to 5 ticks of 100 ms, instead of 10 to 19
    etcdraft.Test(t, cfg, faultline.Options{Seeds: 500})
}

$ go test -run '^TestFastElectionsStaySafe$' .
ok      example.com/failover    37.110s

No seed broke a safety check or left the cluster stuck. That makes the change safe in these runs. It says nothing yet about how fast failover got.

How long does failover take?

Then I timed it. The next test crashes whichever server leads at 5 seconds, with no other faults, and checks the time until another server becomes leader. etcdraft.Setup builds the cluster inside faultline.Run, and LeaderChanges lists every change of leadership in the run:

// failover crashes whichever server leads at 5s. check gets the time until the next leader and
// the number of elections it took.
func failover(t *testing.T, cfg etcdraft.Config, seeds int, check func(time.Duration, uint64) error) {
    cfg.Faults = etcdraft.FaultsNone // no faults except the crash below
    cfg.Duration = 20 * time.Second
    opts := faultline.Options{Seeds: seeds, Duration: cfg.Duration, Net: etcdraft.NetConfig()}
    faultline.Run(t, opts, func(w *faultline.World) {
        c := etcdraft.Setup(w, cfg)
        crash := kernel.Time(5 * time.Second)
        w.Plan(fault.Script(fault.Event{At: crash, Kind: fault.KindCrash, Role: "leader"}))
        w.Final("new leader after the crash", func() error {
            var oldTerm uint64
            for _, ch := range c.LeaderChanges() {
                if ch.State != raft.StateLeader {
                    continue
                }
                if ch.At <= crash {
                    oldTerm = ch.Term
                    continue
                }
                return check(time.Duration(ch.At-crash), ch.Term-oldTerm)
            }
            return errors.New("no new leader after the crash")
        })
    })
}

func TestFailoverUnderOneSecond(t *testing.T) {
    cfg := etcdraft.DefaultConfig()
    cfg.ElectionTick = 3
    failover(t, cfg, 200, func(d time.Duration, _ uint64) error {
        if d > time.Second {
            return fmt.Errorf("new leader %v after the crash", d)
        }
        return nil
    })
}

It failed on the 45th seed:

$ go test -run '^TestFailoverUnderOneSecond$' .
--- FAIL: TestFailoverUnderOneSecond (1.14s)
    failover_test.go:30: faultline: running 200 seeds from base 0xf41bc040834225b9 (test name)
    --- FAIL: TestFailoverUnderOneSecond/seed=0xe05bdf977f330e42 (0.19s)
        faultline: final check "new leader after the crash" failed after the run at t=20.000000000s
          new leader 1.783042452s after the crash
        replay:    FAULTLINE_SEED=0xe05bdf977f330e42 go test -v -run '^TestFailoverUnderOneSecond$' example.com/failover
        artifacts: /tmp/faultline-501/example.com_failover/TestFailoverUnderOneSecond/e05bdf977f330e42/
    failover_test.go:30: faultline: stopping after failing seed 0xe05bdf977f330e42; 155 of 200 seeds not run (set Options.KeepGoing to run all)
FAIL
FAIL    example.com/failover    1.678s
FAIL

Reading the slow seed

This time I could run the slow one again as often as I liked. The replay command runs the identical run, with the same events at the same virtual times. The failing seed also left an artifact directory, and its text timeline shows what happened after the crash:

grep -E "fault.crash|became (candidate|leader)" timeline.txt

    254  0.220702122s n3#1    etcdraft.raft_log    3 became candidate at term 2 level=info <-253
    300  0.225595569s n3#1    etcdraft.raft_log    3 became leader at term 2 level=info <-299
  18833  5.000000000s n3#1    fault.crash          crash n3 id=1 source=script node=n3 effect=applied <-18832
  18905  5.473915956s n2#1    etcdraft.raft_log    2 became candidate at term 3 level=info <-18904
  18916  5.474188777s n1#1    etcdraft.raft_log    1 became candidate at term 3 level=info <-18915
  19083  5.873566634s n1#1    etcdraft.raft_log    1 became candidate at term 4 level=info <-19082
  19094  5.874618666s n2#1    etcdraft.raft_log    2 became candidate at term 4 level=info <-19093
  19271  6.374222166s n1#1    etcdraft.raft_log    1 became candidate at term 5 level=info <-19270
  19290  6.375359195s n2#1    etcdraft.raft_log    2 became candidate at term 5 level=info <-19289
  19457  6.774700502s n1#1    etcdraft.raft_log    1 became candidate at term 6 level=info <-19456
  19505  6.783042452s n1#1    etcdraft.raft_log    1 became leader at term 6 level=info <-19504

n1 and n2 became candidates within about a millisecond of each other, three rounds in a row. Each voted for itself, so neither got the second vote it needed, and both waited out another timeout. In the fourth round only n1 ran, and it won.

etcd/raft picks each server's timeout in whole ticks: electionTimeout + rand.Intn(electionTimeout), drawn from crypto/rand, which faultline seeds for every run. With ElectionTick 3, a server waits 3, 4 or 5 ticks. The harness starts each server's ticks at a random point within the first interval, as real servers that started at different times would. In this seed, n1's and n2's ticks landed less than half a millisecond apart, and they kept drawing the same number of ticks.

How often does it happen?

One slow seed doesn't give a rate. The next test runs 2,000 crashes per setting and records the time to the next leader and the number of election rounds it took. More than one round means at least one round elected nobody, as in the seed above:

func TestFailoverDistribution(t *testing.T) {
    for _, c := range []struct {
        name  string
        tick  time.Duration
        ticks int
    }{
        {"10 ticks of 100ms", 100 * time.Millisecond, 10},
        {"3 ticks of 100ms", 100 * time.Millisecond, 3},
        {"10 ticks of 30ms", 30 * time.Millisecond, 10},
    } {
        var took []time.Duration
        var repeated, slow int
        t.Run(c.name, func(t *testing.T) {
            cfg := etcdraft.DefaultConfig()
            cfg.TickInterval, cfg.ElectionTick = c.tick, c.ticks
            failover(t, cfg, 2000, func(d time.Duration, elections uint64) error {
                took = append(took, d)
                if elections > 1 {
                    repeated++ // at least one election round elected nobody
                }
                if d > time.Second {
                    slow++
                }
                return nil
            })
        })
        slices.Sort(took)
        n := len(took)
        ms := func(d time.Duration) time.Duration { return d.Round(time.Millisecond) }
        t.Logf("%-17s median %v, p99 %v, max %v; repeated elections in %d, over 1s in %d of %d",
            c.name, ms(took[n/2]), ms(took[n*99/100]), ms(took[n-1]), repeated, slow, n)
    }
}

$ go test -v -run '^TestFailoverDistribution$' . | grep repeated
    failover_test.go:91: 10 ticks of 100ms median 1.249s, p99 1.893s, max 3.155s; repeated elections in 16, over 1s in 1797 of 2000
    failover_test.go:91: 3 ticks of 100ms  median 343ms, p99 622ms, max 1.177s; repeated elections in 27, over 1s in 1 of 2000
    failover_test.go:91: 10 ticks of 30ms  median 381ms, p99 814ms, max 1.418s; repeated elections in 32, over 1s in 7 of 2000

With 3 ticks, half the failovers finished within 343 ms and 99% within 622 ms, against 1.249 s and 1.893 s with the default. One failover in 2,000 took more than a second. About 1.4% needed more than one round.

Fewer ticks or shorter ticks?

The third line is the other way to reach a 300 ms timeout: keep 10 ticks and make each one 30 ms. I expected it to repeat elections less often, because a server then picks from 10 timeouts instead of 3. It didn't. Its median was close, and its tail was worse: 7 failovers over a second, and a p99 of 814 ms.

Three more settings, 2,000 crashes each, point at the reason. Settings whose shortest timeout is 300 ms repeated an election in 24 to 32 of 2,000 failovers, whether they used 3, 10 or 20 ticks. Settings that start at 600 ms or later repeated one in 14 to 20. So the timeout in milliseconds, not the number of ticks, seems to set how often two servers start an election together.

30 ms ticks also cost something that 3 ticks don't. With HeartbeatTick 1, the leader sends a heartbeat every tick, so 30 ms ticks send heartbeats more than three times as often. The same settings passed 500 seeds of the full fault mix, like the 3-tick version:

func TestShortTicksStaySafe(t *testing.T) {
    cfg := etcdraft.DefaultConfig()
    cfg.TickInterval = 30 * time.Millisecond
    etcdraft.Test(t, cfg, faultline.Options{Seeds: 500})
}

$ go test -run '^TestShortTicksStaySafe$' .
ok      example.com/failover    43.569s

What a shorter timeout costs

A shorter timeout reacts faster to every missed heartbeat, not only to a dead leader. I counted the elections in 200 runs of 60 seconds for each setting. With no faults, all three settings held exactly one election per run, the first. Under the default faults, the default setting held 8.95 per run, and the two 300 ms settings 12.7 and 12.4. Each election is a short window with no leader. Some of the extra ones are faster reactions to real failures; others are elections a longer timeout would have ridden out, and these runs don't separate the two.

etcd/raft's documentation suggests ElectionTick = 10 * HeartbeatTick "to avoid unnecessary leader switching". In these runs, the 3:1 setting and the 10:1 setting held the same number of extra elections, so the timeout in milliseconds mattered and the ratio didn't. On a network that loses messages in bursts, the ratio may still matter. The harness doesn't model that kind of loss.

What this doesn't tell you

The harness runs etcd/raft with its own state machine, log and transport. Your service's code is not in the run. To test it, you port it to faultline's node API, and the harness is one worked example of such a port.

The network is a model with 1 ms of latency and up to 2 ms of jitter. One message in 100 is delayed by up to 50 ms more, one in 1,000 is lost, and one in 1,000 is duplicated. A real network with longer stalls, or a process with long garbage collection pauses, needs more headroom than these runs show. Inside the simulation a callback takes no time, so CPU load doesn't slow the cluster down.

Try it

Every test above runs with go test, against the released modules. All four took under four minutes on my laptop, an Apple M4 Max with Go 1.27.1:

go get github.com/hmdsefi/faultline/harness/etcdraft@v0.1.1

I first ran these tests on v0.1.0, and v0.1.1 gives the same numbers. v0.1.1 also adds faultline.RunSeeds, which keeps a failing seed like the slow one above as a regression test.

Test etcd/raft with the harness covers the rest of the harness: cluster sizes, fault presets, snapshots and membership changes. The documentation starts with how an AI coding agent runs the same loop, from a failing seed to a pinned regression test, and the repository is on GitHub.