From 781fac25e05c9dbfe1f7a78b3215e330e04d8fc6 Mon Sep 17 00:00:00 2001 From: Sung-Kyu Yoo Date: Sun, 9 Aug 2026 21:13:56 +0900 Subject: [PATCH 1/5] Add a soak test and record what four hours of it found `make soak` puts load on a three-node cluster with one node stopped and restarted every thirty seconds, and on a single node writing to its append log. Both skip unless -soak names a duration, so `make test` and CI cost what they did before. Four hours of it: 350,260 acknowledged writes across 457 node restarts, every one present on every node at the end holding the value it was acknowledged with, and no crashes. The single-node log grew 50 bytes per write to 76MB for a keyspace that never exceeded a thousand entries, and its memory settled. Two things did not come out clean, and the clustering page now says so. Raft discards log entries only once a snapshot covers them and takes one every two to four minutes, so a node going down every ninety seconds never takes one: each held 133MB of undiscardable log after four hours. And the heap went from 10MB to 139MB, more than half of it Raft's own per-connection transport buffers, the only kvs frame holding the thousand keys themselves. The cluster soak reports the heap rather than asserting on it. Convergence is what was measured not to happen under that churn, so a threshold would either be picked to pass or fail without telling anyone something they can act on. What it does assert is the one that matters: nothing acknowledged went missing. --- CONTRIBUTING.md | 7 + Makefile | 13 +- .../Documentation-20260809-210000.yaml | 5 + content/docs/clustering.md | 29 +++ content/docs/contributing.md | 8 + internal/cluster/soak_test.go | 214 ++++++++++++++++++ soak_test.go | 119 ++++++++++ 7 files changed, 394 insertions(+), 1 deletion(-) create mode 100644 changes/unreleased/Documentation-20260809-210000.yaml create mode 100644 internal/cluster/soak_test.go create mode 100644 soak_test.go diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index e153378..b28bc88 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -44,6 +44,13 @@ make build # build binary to dist/ make clean # remove dist/ ``` +`make all` is what CI runs. The long one is separate and opt-in: + +```sh +make soak # 5 minutes of load with a node restarted every 30 seconds +make soak SOAK=4h # the full run the numbers in the docs come from +``` + ### Pre-commit Hooks (optional) ```sh diff --git a/Makefile b/Makefile index 43c7621..0ee48de 100644 --- a/Makefile +++ b/Makefile @@ -1,4 +1,7 @@ -.PHONY: all setup clean build test lint lint-fix vet coverage race +.PHONY: all setup clean build test lint lint-fix vet coverage race soak + +# How long `make soak` runs for. The full run behind the numbers in the docs is SOAK=4h. +SOAK ?= 5m all: vet lint test build @@ -30,3 +33,11 @@ coverage: race: @go test -race ./... + +# Load and fault injection over hours. Only the two packages naming -soak are listed, because +# passing an unknown flag to the others fails them before they start, and they have to come +# before -soak: go test treats everything after a flag it does not know as arguments for the +# test binary and falls back to the current directory. -timeout 0 leaves the deadline to the +# test, so raising SOAK never means recalculating a second number. +soak: + @go test . ./internal/cluster -run TestSoak -soak $(SOAK) -timeout 0 -v diff --git a/changes/unreleased/Documentation-20260809-210000.yaml b/changes/unreleased/Documentation-20260809-210000.yaml new file mode 100644 index 0000000..f1b6f7b --- /dev/null +++ b/changes/unreleased/Documentation-20260809-210000.yaml @@ -0,0 +1,5 @@ +kind: Documentation +body: The durability and clustering page now carries measured numbers from a four hour run under load with a node restarted every thirty seconds - 350,260 acknowledged writes and none of them lost across 457 restarts, 50 bytes of append log per write, and the two things that do grow under that churn - along with a make soak target that reproduces it +time: 2026-08-09T21:00:00.000000+09:00 +custom: + Issue: "246" diff --git a/content/docs/clustering.md b/content/docs/clustering.md index 1f9f439..72ca39e 100644 --- a/content/docs/clustering.md +++ b/content/docs/clustering.md @@ -35,6 +35,14 @@ the file without them. keyspace in memory, so rewriting the log costs nothing extra at that moment and needs no background worker. A long-running process grows its log without bound in the meantime. +How fast is worth knowing before you size a disk. Four hours of continuous writes over a +thousand keys — 1,527,358 of them, so every key was overwritten some fifteen hundred times — +left a **76MB log for a keyspace that never exceeded a thousand entries**, at **50 bytes per +write**. Multiply by your own write rate rather than by that one: the log grows with writes, +not with time and not with how much data you are keeping. Memory settled over the same four +hours, 1.06MB to 1.11MB, so it is the disk that needs watching, and a restart is what +reclaims it. + **One node means one disk.** Durability is not availability: a lost disk is lost data, and a stopped process is a stopped service. That is what clustering is for. @@ -69,6 +77,13 @@ eventual: the price is that every write pays one consensus round. **Failover needs no person.** Stop the leader and the survivors elect a replacement on their own. +**Nothing acknowledged was lost over four hours of being knocked down.** A three-node cluster +took 350,260 writes while one node was stopped and restarted every thirty seconds — 457 +restarts — and at the end every acknowledged write was on every node, holding the value it was +acknowledged with. No crashes. Writes were refused nearly as often as they were taken, which is +a client retrying through an election rather than anything being lost: only a write that +returns is a write kvs claims to have. `make soak SOAK=4h` is that run. + ### What it does not **Three nodes, not two.** A majority of two is two, so a two-node cluster stops accepting @@ -115,6 +130,20 @@ liveness checks; treat them as "this process is up", not "this node is useful". hold. Writes are serialized through the leader, one consensus round each: this is built for staying up, not for throughput. +**A node that restarts faster than it can snapshot never truncates its log.** Raft discards log +entries only once a snapshot covers them, and it takes one every two to four minutes. In the run +above each node was going down every ninety seconds and so never lived long enough to take one: +after four hours every node held **133MB of Raft log for a thousand keys**, none of it +discardable. A node in a crash loop fills its disk while looking like it is merely restarting. +A node that stays up snapshots normally and none of this arises. + +**Memory grows under that same churn.** Across those four hours the heap went from 10MB to +139MB. A heap profile puts more than half of what is still reachable in Raft's own network +transport, which holds a 256KB read buffer and a 256KB write buffer per connection; the only +frame belonging to kvs held 544KB, which is the thousand keys themselves. Whether it levels off +beyond that has not been established. A cluster whose nodes reconnect constantly wants a memory +limit and something to restart it; a settled one showed no such growth. + ## Configuration notes **`--data-dir` is required in a cluster.** The Raft log has to live somewhere. It replaces the diff --git a/content/docs/contributing.md b/content/docs/contributing.md index 301b7c5..e508e11 100644 --- a/content/docs/contributing.md +++ b/content/docs/contributing.md @@ -21,6 +21,14 @@ make lint # run golangci-lint make build # build binary ``` +`make all` is what CI runs. The soak test is separate and opt-in, because it is measured in +hours rather than seconds: + +```sh +make soak # 5 minutes of load with a node restarted every 30 seconds +make soak SOAK=4h # the full run the numbers on the clustering page come from +``` + ## PR Guidelines - Keep PRs small and focused on a single concern diff --git a/internal/cluster/soak_test.go b/internal/cluster/soak_test.go new file mode 100644 index 0000000..3a47219 --- /dev/null +++ b/internal/cluster/soak_test.go @@ -0,0 +1,214 @@ +package cluster + +import ( + "flag" + "io/fs" + "path/filepath" + "runtime" + "strconv" + "testing" + "time" + + "github.com/skyoo2003/kvs/internal/datadir" +) + +// soakFor turns the long run on and says how long it lasts. Zero, the default, skips it, so +// `go test ./...` costs what it costs today and only `make soak` pays for this. +var soakFor = flag.Duration("soak", 0, "run the soak test for this long") + +// soakKeys is a fixed set that gets overwritten rather than one that grows. A keyspace that +// grows makes the heap grow for honest reasons, and then the heap says nothing about leaks. +const soakKeys = 1000 + +// killEvery is how often a node is taken away. One at a time: three nodes still hold a +// majority with one gone, and taking two would measure a design decision, not a fault. +const killEvery = 30 * time.Second + +// The milestone in one test: hours of writes with a node dying every half minute, and at the +// end every write kvs acknowledged is on every node. What it reports - writes, restarts, heap, +// bytes on disk - is the record that says the thing survived, so those numbers go in the docs. +func TestSoakSurvivesLoadAndFailover(t *testing.T) { + if *soakFor == 0 { + t.Skip("soak run is off; pass -soak , or run make soak") + } + + nodes := startCluster(t, 3) + waitForLeader(t, nodes) + + run := &soakRun{nodes: nodes, acked: make(map[string]string, soakKeys)} + run.load(t, *soakFor) + run.verify(t) + run.report(t) +} + +type soakRun struct { + nodes []*testNode + // acked holds the last value each key was acknowledged with. A write that came back with + // an error is a retry, not a loss, so only what returned nil is in here. + acked map[string]string + // last is the key of the most recent acknowledged write, used as the barrier to wait on. + last string + writes int + refused int + failovers int + // warmup and final are the heap once the run has settled and at the end of it. + warmup heapSample + final heapSample +} + +// heapSample is what the run records at its endpoints. alloc is what is still reachable, which +// is the question a leak asks. inUse is what the spans hold, which is closer to what an +// operator sees and which a non-moving collector does not hand back just because objects died. +type heapSample struct { + alloc uint64 + inUse uint64 +} + +func (r *soakRun) load(t *testing.T, over time.Duration) { + t.Helper() + + start := time.Now() + deadline := start.Add(over) + // The heap is first read once the run has settled, so the baseline is a steady state + // rather than a process still filling its caches. + warmupAt := start.Add(over / 10) + nextKill := start.Add(killEvery) + + for round := 0; time.Now().Before(deadline); round++ { + r.put(t, "soak-"+strconv.Itoa(round%soakKeys), strconv.Itoa(round)) + + now := time.Now() + // A live process never has a zero heap, so zero is still "not read yet". + if r.warmup.alloc == 0 && now.After(warmupAt) { + r.warmup = heapAfterGC() + } + + if now.After(nextKill) { + r.cycle(t, r.failovers%len(r.nodes)) + r.failovers++ + nextKill = time.Now().Add(killEvery) + } + } + + r.final = heapAfterGC() +} + +// put offers the write to every node until one takes it, which is what a client following a +// MOVED does. Only a write that returned nil is recorded, because that is the only one kvs +// claimed to have. +func (r *soakRun) put(t *testing.T, key, value string) { + t.Helper() + + eventually(t, "a node to take "+key, func() bool { + for _, node := range r.nodes { + if err := node.store.Put(key, value); err != nil { + r.refused++ + + continue + } + + r.acked[key] = value + r.last = key + r.writes++ + + return true + } + + return false + }) +} + +// cycle takes one node away and brings it back, waiting for it to catch up before returning. +// The next kill therefore never lands while the cluster is still a node short. +func (r *soakRun) cycle(t *testing.T, i int) { + t.Helper() + + node := r.nodes[i] + node.stop(t) + node.restart(t) + node.mustEventuallyHold(t, r.last, r.acked[r.last]) + + // Sampled every restart rather than only at the ends, because two readings cannot tell a + // leak from a step change. No forced collection here: this is a trend, and stopping the + // world hundreds of times would change what it is measuring. + var stats runtime.MemStats + runtime.ReadMemStats(&stats) + t.Logf("restart %d of %s: heap alloc %d bytes, heap in use %d bytes, %d goroutines", + r.failovers, node.id, stats.HeapAlloc, stats.HeapInuse, runtime.NumGoroutine()) +} + +// verify is what the run exists for: every write kvs acknowledged has to be on every node with +// the value it acknowledged. Waiting on one key rather than all of them is enough because Raft +// applies its log in order - a node holding the last write has applied everything before it. +func (r *soakRun) verify(t *testing.T) { + t.Helper() + + for _, node := range r.nodes { + node.mustEventuallyHold(t, r.last, r.acked[r.last]) + + for key, want := range r.acked { + got, err := node.store.Get(key) + if err != nil || got != want { + t.Errorf("%s Get(%q) = %v, %v, want %v, nil", node.id, key, got, err, want) + } + } + } +} + +func (r *soakRun) report(t *testing.T) { + t.Helper() + + t.Logf("ran %s: %d writes acknowledged over %d keys, %d refused, %d node restarts", + *soakFor, r.writes, len(r.acked), r.refused, r.failovers) + t.Logf("heap alloc: %d bytes once settled, %d bytes at the end", r.warmup.alloc, r.final.alloc) + t.Logf("heap in use: %d bytes once settled, %d bytes at the end, %d goroutines left", + r.warmup.inUse, r.final.inUse, runtime.NumGoroutine()) + + for _, node := range r.nodes { + dir := filepath.Join(node.dir, datadir.RaftName) + t.Logf("%s raft store: %d bytes", node.id, dirBytes(t, dir)) + } +} + +// The heap is reported and not asserted on, which is a decision rather than an omission. Over +// four hours it went from 10MB to 139MB, and a heap profile put more than half of what was +// still reachable in Raft's own NetworkTransport - a 256KB read buffer and a 256KB write +// buffer per connection, and this test opens connections faster than a real cluster ever +// would. The only frame belonging to kvs held 544KB, which is the thousand keys themselves. +// A threshold here would either be a number picked to pass or a failure nobody can act on, so +// what stays is the measurement, and clustering.md carries what it means. The assertion that +// matters is verify: no acknowledged write went missing across 457 restarts. + +func heapAfterGC() heapSample { + // Collect first: the question is what is retained, not what has yet to be swept. + runtime.GC() + + var stats runtime.MemStats + runtime.ReadMemStats(&stats) + + return heapSample{alloc: stats.HeapAlloc, inUse: stats.HeapInuse} +} + +func dirBytes(t *testing.T, dir string) int64 { + t.Helper() + + var total int64 + err := filepath.WalkDir(dir, func(_ string, entry fs.DirEntry, err error) error { + if err != nil || entry.IsDir() { + return err + } + + info, err := entry.Info() + if err != nil { + return err + } + total += info.Size() + + return nil + }) + if err != nil { + t.Fatalf("walk %s: %v", dir, err) + } + + return total +} diff --git a/soak_test.go b/soak_test.go new file mode 100644 index 0000000..7bf02c0 --- /dev/null +++ b/soak_test.go @@ -0,0 +1,119 @@ +package kvs + +import ( + "flag" + "os" + "path/filepath" + "runtime" + "strconv" + "testing" + "time" +) + +// soakFor turns the long run on and says how long it lasts. Zero, the default, skips it. +var soakFor = flag.Duration("soak", 0, "run the soak test for this long") + +// soakKeys is a fixed set that gets overwritten, so the keyspace stays the same size while the +// log does not. That difference is the measurement. +const soakKeys = 1000 + +// soakSizeCap stops the run before it can fill the disk it is measuring. Reaching it is a +// result rather than a failure: it says how long a process writing this fast has before the +// log is that large. +const soakSizeCap = 2 << 30 + +// soakSizeEvery is how many writes pass between size checks. Statting the log on every write +// would measure the stat. +const soakSizeEvery = 10000 + +// The append log is compacted when Open replays it and nowhere else, so a process that stays +// up keeps appending - clustering.md says so, and this puts a number on it. A rate is more use +// to whoever has to size a disk than the sentence alone. Changing that behavior is not v1 +// work; measuring it is. +func TestSoakMeasuresLogGrowth(t *testing.T) { + if *soakFor == 0 { + t.Skip("soak run is off; pass -soak , or run make soak") + } + + dir := t.TempDir() + store := openTestStore(t, dir) + + start := time.Now() + deadline := start.Add(*soakFor) + // The heap is first read once the run has settled, so the baseline is a steady state + // rather than a process still filling its caches. + warmupAt := start.Add(*soakFor / 10) + + var writes int + var warmup uint64 + var capped bool + + for ; time.Now().Before(deadline); writes++ { + key := "soak-" + strconv.Itoa(writes%soakKeys) + if err := store.Put(key, strconv.Itoa(writes)); err != nil { + t.Fatalf("Put(%q) error = %v", key, err) + } + + now := time.Now() + // A live process never has a zero heap, so zero is still "not read yet". + if warmup == 0 && now.After(warmupAt) { + warmup = heapInUse() + } + + if writes%soakSizeEvery == 0 && logBytes(t, dir) > soakSizeCap { + capped = true + + break + } + } + + reportGrowth(t, dir, writes, time.Since(start), capped) + assertHeapSettled(t, warmup, heapInUse()) +} + +func reportGrowth(t *testing.T, dir string, writes int, elapsed time.Duration, capped bool) { + t.Helper() + + size := logBytes(t, dir) + if capped { + t.Logf("stopped early at the %d byte cap, %s into a %s run", soakSizeCap, elapsed, *soakFor) + } + + t.Logf("ran %s: %d writes over %d keys, log is %d bytes (%.1f bytes per write)", + elapsed.Round(time.Second), writes, soakKeys, size, float64(size)/float64(writes)) + t.Logf("log growth: %.1f MiB/hour at this write rate", float64(size)/(1<<20)/elapsed.Hours()) +} + +// assertHeapSettled is the only assertion here. The log is expected to grow; the keyspace is +// not, so what holds it has to settle. Half again is the loosest reading that still catches +// something holding on to every write. +func assertHeapSettled(t *testing.T, warmup, final uint64) { + t.Helper() + + t.Logf("heap in use: %d bytes once settled, %d bytes at the end", warmup, final) + + if limit := warmup + warmup/2; final > limit { + t.Errorf("heap in use went from %d to %d bytes, want at most %d", warmup, final, limit) + } +} + +func heapInUse() uint64 { + // Collect first: the question is what is retained, not what has yet to be swept. + runtime.GC() + + var stats runtime.MemStats + runtime.ReadMemStats(&stats) + + return stats.HeapInuse +} + +func logBytes(t *testing.T, dir string) int64 { + t.Helper() + + info, err := os.Stat(filepath.Join(dir, logName)) + if err != nil { + t.Fatalf("stat log: %v", err) + } + + return info.Size() +} From db7b86f769dd5fff22e6e554f2ed4bcbbdae1a94 Mon Sep 17 00:00:00 2001 From: Sung-Kyu Yoo Date: Sun, 9 Aug 2026 21:51:01 +0900 Subject: [PATCH 2/5] Keep writing while the node is away The load and the fault injection shared one goroutine, so the node was stopped and restarted between two writes and never missed any. That measures a process being started twice, not a cluster taking writes a node short and handing them over when it comes back, which is what the run is for. The node now stays down for ten seconds while the writes carry on, and how many were taken in that state is counted rather than inferred. Every acknowledged value is also checked on the returning node before the run writes again. Checking only at the end let a later round overwrite a value that had gone missing, which took the loss out of the evidence along with the data. --- internal/cluster/soak_test.go | 102 ++++++++++++++++++++++++++-------- 1 file changed, 78 insertions(+), 24 deletions(-) diff --git a/internal/cluster/soak_test.go b/internal/cluster/soak_test.go index 3a47219..3cb74c4 100644 --- a/internal/cluster/soak_test.go +++ b/internal/cluster/soak_test.go @@ -24,9 +24,15 @@ const soakKeys = 1000 // majority with one gone, and taking two would measure a design decision, not a fault. const killEvery = 30 * time.Second -// The milestone in one test: hours of writes with a node dying every half minute, and at the -// end every write kvs acknowledged is on every node. What it reports - writes, restarts, heap, -// bytes on disk - is the record that says the thing survived, so those numbers go in the docs. +// downFor is how long it stays away, and writes carry on the whole time. Restarting it straight +// away would leave it nothing to catch up on, and catching up is the part a restart has to +// survive; a run that never writes into the gap proves only that a process can be started twice. +const downFor = 10 * time.Second + +// Hours of writes with a node taken away every half minute and kept away while the writes keep +// coming, held after every restart and again at the end to every value kvs acknowledged. What +// it reports - writes, restarts, heap, bytes on disk - is the record that says the thing +// survived, so those numbers go in the docs. func TestSoakSurvivesLoadAndFailover(t *testing.T) { if *soakFor == 0 { t.Skip("soak run is off; pass -soak , or run make soak") @@ -47,10 +53,16 @@ type soakRun struct { // an error is a retry, not a loss, so only what returned nil is in here. acked map[string]string // last is the key of the most recent acknowledged write, used as the barrier to wait on. - last string - writes int - refused int - failovers int + last string + // down is the node currently stopped, if any, and backAt when it is due to come back. + down *testNode + backAt time.Time + writes int + // shorthanded counts the acknowledged writes taken while a node was stopped. It is the + // claim the docs make, so it is counted rather than inferred from the timings. + shorthanded int + refused int + failovers int // warmup and final are the heap once the run has settled and at the end of it. warmup heapSample final heapSample @@ -83,13 +95,20 @@ func (r *soakRun) load(t *testing.T, over time.Duration) { r.warmup = heapAfterGC() } - if now.After(nextKill) { - r.cycle(t, r.failovers%len(r.nodes)) - r.failovers++ - nextKill = time.Now().Add(killEvery) + switch { + case r.down != nil && now.After(r.backAt): + r.bringBack(t) + + case r.down == nil && now.After(nextKill): + r.takeDown(t, r.failovers%len(r.nodes)) + nextKill = now.Add(killEvery) } } + if r.down != nil { + r.bringBack(t) + } + r.final = heapAfterGC() } @@ -101,6 +120,12 @@ func (r *soakRun) put(t *testing.T, key, value string) { eventually(t, "a node to take "+key, func() bool { for _, node := range r.nodes { + // A node known to be stopped is skipped rather than asked, so that a refusal means + // what it says: the leader was somewhere else. + if node == r.down { + continue + } + if err := node.store.Put(key, value); err != nil { r.refused++ @@ -111,6 +136,10 @@ func (r *soakRun) put(t *testing.T, key, value string) { r.last = key r.writes++ + if r.down != nil { + r.shorthanded++ + } + return true } @@ -118,15 +147,33 @@ func (r *soakRun) put(t *testing.T, key, value string) { }) } -// cycle takes one node away and brings it back, waiting for it to catch up before returning. -// The next kill therefore never lands while the cluster is still a node short. -func (r *soakRun) cycle(t *testing.T, i int) { +// takeDown stops a node and leaves it stopped. The caller keeps writing, so what the cluster is +// asked to do is take writes a node short and hand them over when it comes back. +func (r *soakRun) takeDown(t *testing.T, i int) { + t.Helper() + + r.down = r.nodes[i] + r.down.stop(t) + r.backAt = time.Now().Add(downFor) +} + +// bringBack restarts the stopped node and checks it against every acknowledged value before the +// run is allowed to write again. Checking here rather than only at the end is what makes the +// check mean something: a value lost while the node was away would otherwise be overwritten by +// a later round, and the missing write would be gone from the evidence as well as from disk. +func (r *soakRun) bringBack(t *testing.T) { t.Helper() - node := r.nodes[i] - node.stop(t) + node := r.down node.restart(t) + r.down = nil + r.failovers++ + + // A restart starts the node on an empty store, so this waits out a replay of everything, + // not a top-up. Raft applies its log in order, so holding the last write means holding the + // rest, and the comparison that follows is a comparison rather than a race. node.mustEventuallyHold(t, r.last, r.acked[r.last]) + r.mustHoldEverything(t, node) // Sampled every restart rather than only at the ends, because two readings cannot tell a // leak from a step change. No forced collection here: this is a trend, and stopping the @@ -137,20 +184,25 @@ func (r *soakRun) cycle(t *testing.T, i int) { r.failovers, node.id, stats.HeapAlloc, stats.HeapInuse, runtime.NumGoroutine()) } -// verify is what the run exists for: every write kvs acknowledged has to be on every node with -// the value it acknowledged. Waiting on one key rather than all of them is enough because Raft -// applies its log in order - a node holding the last write has applied everything before it. +// verify is what the run exists for: every value kvs acknowledged has to be on every node when +// the load stops. It is the last of the checks rather than the only one - each restart has +// already been held to the same standard against the state at that moment. func (r *soakRun) verify(t *testing.T) { t.Helper() for _, node := range r.nodes { node.mustEventuallyHold(t, r.last, r.acked[r.last]) + r.mustHoldEverything(t, node) + } +} - for key, want := range r.acked { - got, err := node.store.Get(key) - if err != nil || got != want { - t.Errorf("%s Get(%q) = %v, %v, want %v, nil", node.id, key, got, err, want) - } +func (r *soakRun) mustHoldEverything(t *testing.T, node *testNode) { + t.Helper() + + for key, want := range r.acked { + got, err := node.store.Get(key) + if err != nil || got != want { + t.Errorf("%s Get(%q) = %v, %v, want %v, nil", node.id, key, got, err, want) } } } @@ -160,6 +212,8 @@ func (r *soakRun) report(t *testing.T) { t.Logf("ran %s: %d writes acknowledged over %d keys, %d refused, %d node restarts", *soakFor, r.writes, len(r.acked), r.refused, r.failovers) + t.Logf("%d of those writes were taken while a node was stopped, each stopped for %s", + r.shorthanded, downFor) t.Logf("heap alloc: %d bytes once settled, %d bytes at the end", r.warmup.alloc, r.final.alloc) t.Logf("heap in use: %d bytes once settled, %d bytes at the end, %d goroutines left", r.warmup.inUse, r.final.inUse, runtime.NumGoroutine()) From 6189ed12beeb5ec5658804b868b5bae68d9864f8 Mon Sep 17 00:00:00 2001 From: Sung-Kyu Yoo Date: Mon, 10 Aug 2026 01:54:13 +0900 Subject: [PATCH 3/5] Replace the measurements with the ones the fixed harness took The numbers on the page came from a run where the node never missed a write, so they described a weaker thing than they claimed. Four hours with the node kept down for ten seconds at a time: 329,631 acknowledged writes, 111,516 of them taken while a node was gone, none of them missing across 479 restarts. The heap is the part that changed its mind. It ended where it started, 4.3MB to 4.0MB, where the run that restarted a node the instant it stopped went from 10MB to 139MB. So the growth belongs to the process that comes back with no pause, and the page now says that rather than saying memory grows under churn. The Raft log a restarting node never truncates is unchanged in kind, 126MB a node. Bytes per write is qualified as this workload's, since a record carries the key and the encoded value and someone sizing a disk needs their own record, not this one's. --- .../Documentation-20260809-210000.yaml | 2 +- content/docs/clustering.md | 43 +++++++++++-------- internal/cluster/soak_test.go | 17 ++++---- 3 files changed, 35 insertions(+), 27 deletions(-) diff --git a/changes/unreleased/Documentation-20260809-210000.yaml b/changes/unreleased/Documentation-20260809-210000.yaml index f1b6f7b..c615385 100644 --- a/changes/unreleased/Documentation-20260809-210000.yaml +++ b/changes/unreleased/Documentation-20260809-210000.yaml @@ -1,5 +1,5 @@ kind: Documentation -body: The durability and clustering page now carries measured numbers from a four hour run under load with a node restarted every thirty seconds - 350,260 acknowledged writes and none of them lost across 457 restarts, 50 bytes of append log per write, and the two things that do grow under that churn - along with a make soak target that reproduces it +body: The durability and clustering page now carries measured numbers from a four hour run under load with a node stopped every thirty seconds and kept down for ten - 329,631 acknowledged writes, 111,516 of them taken while a node was gone, and none of them lost across 479 restarts - along with 51 bytes of append log per write, the Raft log a node too busy restarting never truncates, and a make soak target that reproduces all of it time: 2026-08-09T21:00:00.000000+09:00 custom: Issue: "246" diff --git a/content/docs/clustering.md b/content/docs/clustering.md index 72ca39e..8d1d715 100644 --- a/content/docs/clustering.md +++ b/content/docs/clustering.md @@ -36,12 +36,13 @@ keyspace in memory, so rewriting the log costs nothing extra at that moment and background worker. A long-running process grows its log without bound in the meantime. How fast is worth knowing before you size a disk. Four hours of continuous writes over a -thousand keys — 1,527,358 of them, so every key was overwritten some fifteen hundred times — -left a **76MB log for a keyspace that never exceeded a thousand entries**, at **50 bytes per -write**. Multiply by your own write rate rather than by that one: the log grows with writes, -not with time and not with how much data you are keeping. Memory settled over the same four -hours, 1.06MB to 1.11MB, so it is the disk that needs watching, and a restart is what -reclaims it. +thousand keys — 1,726,455 of them, so every key was overwritten some seventeen hundred times — +left an **87MB log for a keyspace that never exceeded a thousand entries**, at **51 bytes per +write**. That last figure is this workload's, not yours: a record carries the key and the +encoded value, so your own average record is what scales it. The shape is what carries over — +the log grows with writes, not with time and not with how much data you are keeping. Memory +settled over the same four hours, 1.11MB to 1.22MB, so it is the disk that needs watching, and +a restart is what reclaims it. **One node means one disk.** Durability is not availability: a lost disk is lost data, and a stopped process is a stopped service. That is what clustering is for. @@ -78,11 +79,14 @@ eventual: the price is that every write pays one consensus round. own. **Nothing acknowledged was lost over four hours of being knocked down.** A three-node cluster -took 350,260 writes while one node was stopped and restarted every thirty seconds — 457 -restarts — and at the end every acknowledged write was on every node, holding the value it was -acknowledged with. No crashes. Writes were refused nearly as often as they were taken, which is -a client retrying through an election rather than anything being lost: only a write that -returns is a write kvs claims to have. `make soak SOAK=4h` is that run. +took 329,631 writes with one node stopped every thirty seconds and left down for ten — 479 +restarts — and **111,516 of those writes were taken while a node was gone**. Each node that +came back was held against every acknowledged value before the load was allowed to write again, +so a write that went missing could not be covered up by the next round overwriting its key; all +three were checked once more at the end. Nothing was missing and nothing crashed. Writes were +refused slightly more often than they were taken, which is what asking a follower looks like — +the refusal names the leader — rather than anything being lost: only a write that returns is a +write kvs claims to have. `make soak SOAK=4h` is that run. ### What it does not @@ -133,16 +137,19 @@ staying up, not for throughput. **A node that restarts faster than it can snapshot never truncates its log.** Raft discards log entries only once a snapshot covers them, and it takes one every two to four minutes. In the run above each node was going down every ninety seconds and so never lived long enough to take one: -after four hours every node held **133MB of Raft log for a thousand keys**, none of it +after four hours every node held **126MB of Raft log for a thousand keys**, none of it discardable. A node in a crash loop fills its disk while looking like it is merely restarting. A node that stays up snapshots normally and none of this arises. -**Memory grows under that same churn.** Across those four hours the heap went from 10MB to -139MB. A heap profile puts more than half of what is still reachable in Raft's own network -transport, which holds a 256KB read buffer and a 256KB write buffer per connection; the only -frame belonging to kvs held 544KB, which is the thousand keys themselves. Whether it levels off -beyond that has not been established. A cluster whose nodes reconnect constantly wants a memory -limit and something to restart it; a settled one showed no such growth. +**Memory holds under that churn, unless the node comes back instantly.** Across those four +hours the heap of the one process holding all three nodes ended where it began, 4.3MB once +settled and 4.0MB after 479 restarts. An earlier version of the same run restarted each node +the moment it stopped rather than leaving it down, and that one climbed from 10MB to 139MB over +four hours; a heap profile put more than half of what was still reachable in Raft's own network +transport, which holds a 256KB read buffer and a 256KB write buffer per connection, while the +only frame belonging to kvs held 544KB — the thousand keys themselves. Ten seconds down was +enough for none of that to accumulate. It is the process that crash-loops without pause that +grows, and it wants a memory limit as much as it wants the disk headroom above. ## Configuration notes diff --git a/internal/cluster/soak_test.go b/internal/cluster/soak_test.go index 3cb74c4..8215e3b 100644 --- a/internal/cluster/soak_test.go +++ b/internal/cluster/soak_test.go @@ -224,14 +224,15 @@ func (r *soakRun) report(t *testing.T) { } } -// The heap is reported and not asserted on, which is a decision rather than an omission. Over -// four hours it went from 10MB to 139MB, and a heap profile put more than half of what was -// still reachable in Raft's own NetworkTransport - a 256KB read buffer and a 256KB write -// buffer per connection, and this test opens connections faster than a real cluster ever -// would. The only frame belonging to kvs held 544KB, which is the thousand keys themselves. -// A threshold here would either be a number picked to pass or a failure nobody can act on, so -// what stays is the measurement, and clustering.md carries what it means. The assertion that -// matters is verify: no acknowledged write went missing across 457 restarts. +// The heap is reported and not asserted on, which is a decision rather than an omission. It +// held over four hours and 479 restarts, 4.3MB settled to 4.0MB at the end. An earlier version +// of this test brought each node back the instant it stopped, and that one went from 10MB to +// 139MB over the same four hours, with more than half of what was still reachable sitting in +// Raft's own NetworkTransport - a 256KB read buffer and a 256KB write buffer per connection. +// The only frame belonging to kvs held 544KB, which is the thousand keys themselves. A +// threshold tuned to pass one of those runs says nothing about the other, so what stays is the +// measurement, and clustering.md carries what it means. The assertion that matters is the +// comparison at every restart: no acknowledged value went missing across 479 of them. func heapAfterGC() heapSample { // Collect first: the question is what is retained, not what has yet to be swept. From fe2a7af4d2e353a1e4839d359ae3853d31f27734 Mon Sep 17 00:00:00 2001 From: Sung-Kyu Yoo Date: Mon, 10 Aug 2026 23:19:17 +0900 Subject: [PATCH 4/5] Hold the soak to what it can actually show Three ways the long run reported better than it knew. Any error from a write counted as a refusal and sent the load to the next node. A follower refusing a write is the ordinary case and names the leader, but an apply that timed out, a store that failed, or an FSM that would not take a frame is not that, and retrying until some node says yes let a broken run finish looking clean while inflating the refusal count the docs quote. Only kvs.ErrNotLeader is retried now; anything else ends the run where it happened. The check at every restart compares the last acknowledged value of each key, and the load walks a thousand keys in order, so an interval that got through more than a thousand writes overwrote values nothing had compared yet. That is not a loss, but it is not evidence either, and the run said nothing about how much of it there was. It counts them now: a ninety-five second run on this machine put 1,383 of 4,383 acknowledged writes past a check, which is the number the claim has to be qualified by rather than a number to hide. And the single-node half asserted the heap against a baseline it might never have taken. Reaching the size cap before the tenth of the run when the baseline is due left it at zero, and a limit of zero fails, so the one outcome that cap exists to produce was a guaranteed failure. It says there is nothing to compare instead. --- internal/cluster/soak_test.go | 44 +++++++++++++++++++++++++++++++---- soak_test.go | 11 ++++++++- 2 files changed, 50 insertions(+), 5 deletions(-) diff --git a/internal/cluster/soak_test.go b/internal/cluster/soak_test.go index 8215e3b..f409a2b 100644 --- a/internal/cluster/soak_test.go +++ b/internal/cluster/soak_test.go @@ -1,6 +1,7 @@ package cluster import ( + "errors" "flag" "io/fs" "path/filepath" @@ -9,6 +10,7 @@ import ( "testing" "time" + "github.com/skyoo2003/kvs" "github.com/skyoo2003/kvs/internal/datadir" ) @@ -63,6 +65,13 @@ type soakRun struct { shorthanded int refused int failovers int + // window counts the writes acknowledged since the last check, and unverified the ones a check + // could not vouch for on its own. The load walks the keys in order, so a window longer than + // the keyspace overwrites values it already acknowledged and only the newer one is left to + // compare. Zero unverified means every acknowledged write was held against a returning node + // as itself, rather than as whatever replaced it. + window int + unverified int // warmup and final are the heap once the run has settled and at the end of it. warmup heapSample final heapSample @@ -126,15 +135,26 @@ func (r *soakRun) put(t *testing.T, key, value string) { continue } - if err := node.store.Put(key, value); err != nil { + err := node.store.Put(key, value) + + // A refusal names the leader and is the ordinary answer from a follower, so the next + // node gets asked. Anything else - an apply that timed out, a store that failed, an + // FSM that would not take the frame - is not a redirect, and retrying until some node + // says yes would let a run that is quietly broken finish looking clean. + if errors.Is(err, kvs.ErrNotLeader) { r.refused++ continue } + if err != nil { + t.Fatalf("%s Put(%q) = %v, want nil or %v", node.id, key, err, kvs.ErrNotLeader) + } + r.acked[key] = value r.last = key r.writes++ + r.window++ if r.down != nil { r.shorthanded++ @@ -158,9 +178,10 @@ func (r *soakRun) takeDown(t *testing.T, i int) { } // bringBack restarts the stopped node and checks it against every acknowledged value before the -// run is allowed to write again. Checking here rather than only at the end is what makes the -// check mean something: a value lost while the node was away would otherwise be overwritten by -// a later round, and the missing write would be gone from the evidence as well as from disk. +// run is allowed to write again. Checking here rather than only at the end is what keeps the +// evidence: a value lost while the node was away would otherwise be overwritten by a later +// round, and the missing write would be gone from the record as well as from disk. It narrows +// that window to one interval rather than closing it, which is what unverified counts. func (r *soakRun) bringBack(t *testing.T) { t.Helper() @@ -174,6 +195,7 @@ func (r *soakRun) bringBack(t *testing.T) { // rest, and the comparison that follows is a comparison rather than a race. node.mustEventuallyHold(t, r.last, r.acked[r.last]) r.mustHoldEverything(t, node) + r.closeWindow() // Sampled every restart rather than only at the ends, because two readings cannot tell a // leak from a step change. No forced collection here: this is a trend, and stopping the @@ -194,6 +216,19 @@ func (r *soakRun) verify(t *testing.T) { node.mustEventuallyHold(t, r.last, r.acked[r.last]) r.mustHoldEverything(t, node) } + + r.closeWindow() +} + +// closeWindow settles what the check just made could account for. The load writes the keys in +// order, so a window that ran past the keyspace acknowledged some keys twice, and the earlier +// value of each is no longer anywhere to compare - not a loss, but not evidence either. +func (r *soakRun) closeWindow() { + if r.window > soakKeys { + r.unverified += r.window - soakKeys + } + + r.window = 0 } func (r *soakRun) mustHoldEverything(t *testing.T, node *testNode) { @@ -214,6 +249,7 @@ func (r *soakRun) report(t *testing.T) { *soakFor, r.writes, len(r.acked), r.refused, r.failovers) t.Logf("%d of those writes were taken while a node was stopped, each stopped for %s", r.shorthanded, downFor) + t.Logf("%d acknowledged writes were superseded before a check could compare them", r.unverified) t.Logf("heap alloc: %d bytes once settled, %d bytes at the end", r.warmup.alloc, r.final.alloc) t.Logf("heap in use: %d bytes once settled, %d bytes at the end, %d goroutines left", r.warmup.inUse, r.final.inUse, runtime.NumGoroutine()) diff --git a/soak_test.go b/soak_test.go index 7bf02c0..b710537 100644 --- a/soak_test.go +++ b/soak_test.go @@ -19,7 +19,8 @@ const soakKeys = 1000 // soakSizeCap stops the run before it can fill the disk it is measuring. Reaching it is a // result rather than a failure: it says how long a process writing this fast has before the -// log is that large. +// log is that large. It assumes the temporary directory has that much to spare - a smaller +// filesystem fails the write instead, which says so plainly enough. const soakSizeCap = 2 << 30 // soakSizeEvery is how many writes pass between size checks. Statting the log on every write @@ -90,6 +91,14 @@ func reportGrowth(t *testing.T, dir string, writes int, elapsed time.Duration, c func assertHeapSettled(t *testing.T, warmup, final uint64) { t.Helper() + // A run that hit the size cap before the baseline was due has nothing to compare, and a + // baseline of zero would turn the result the cap exists to produce into a failure. + if warmup == 0 { + t.Logf("heap in use: %d bytes at the end, with no settled reading to compare it to", final) + + return + } + t.Logf("heap in use: %d bytes once settled, %d bytes at the end", warmup, final) if limit := warmup + warmup/2; final > limit { From ef874496e32f93b2afb1ae3d571e901c51d1880a Mon Sep 17 00:00:00 2001 From: Sung-Kyu Yoo Date: Mon, 10 Aug 2026 23:19:41 +0900 Subject: [PATCH 5/5] Say what the soak checked, and when Raft snapshots Two claims on the clustering page that went further than the run behind them. The restart check was described as making a lost write impossible to cover up. It compares the latest acknowledged value of every key, so an interval that gets through more writes than there are keys leaves only the later value to compare - per key, not per write. The page says which it is, and the run reports how many writes went past a check. And a healthy node was said to snapshot every two to four minutes. That is how often hashicorp/raft asks the question; it takes one only once 8,192 entries have arrived since the last, which at the rate measured here is another five or six minutes, and it keeps the most recent 10,240 entries even then. An operator waiting for the log to shrink was given the wrong minute. --- content/docs/clustering.md | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/content/docs/clustering.md b/content/docs/clustering.md index 8d1d715..d7442ce 100644 --- a/content/docs/clustering.md +++ b/content/docs/clustering.md @@ -80,10 +80,13 @@ own. **Nothing acknowledged was lost over four hours of being knocked down.** A three-node cluster took 329,631 writes with one node stopped every thirty seconds and left down for ten — 479 -restarts — and **111,516 of those writes were taken while a node was gone**. Each node that -came back was held against every acknowledged value before the load was allowed to write again, -so a write that went missing could not be covered up by the next round overwriting its key; all -three were checked once more at the end. Nothing was missing and nothing crashed. Writes were +restarts — and **111,516 of those writes were taken while a node was gone**. Each node that came +back was held against the latest acknowledged value of every key before the load was allowed to +write again, and all three were checked once more at the end. Nothing was missing and nothing +crashed. The check is per key rather than per write: an interval that gets through more writes +than there are keys overwrites some of its own, and only the later value is left to compare, so +the run reports how many acknowledged writes were superseded before a check could see them. +Writes were refused slightly more often than they were taken, which is what asking a follower looks like — the refusal names the leader — rather than anything being lost: only a write that returns is a write kvs claims to have. `make soak SOAK=4h` is that run. @@ -135,8 +138,10 @@ hold. Writes are serialized through the leader, one consensus round each: this i staying up, not for throughput. **A node that restarts faster than it can snapshot never truncates its log.** Raft discards log -entries only once a snapshot covers them, and it takes one every two to four minutes. In the run -above each node was going down every ninety seconds and so never lived long enough to take one: +entries only once a snapshot covers them. It considers taking one every two to four minutes, and +takes it only if 8,192 entries have arrived since the last — at the write rate above that is +another five or six minutes — then keeps the most recent 10,240 entries anyway. In the run above +each node was going down every ninety seconds and so never lived long enough to take one: after four hours every node held **126MB of Raft log for a thousand keys**, none of it discardable. A node in a crash loop fills its disk while looking like it is merely restarting. A node that stays up snapshots normally and none of this arises.