perf(wal): checkpoint measured — 2.16x space, 1.78x boot, 2.7ms pause — T5

databasev2 3, task 5.

Full campaign, same workload twice, differing only in whether
checkpointing may fire:

- WAL used 1962358 -> 907094 bytes (2.16x reclaimed)
- boot 114 -> 64 ms (1.78x), median of 3
- stop-the-world pause max 2651us against a STATED 50ms budget

The budget is asserted, not assumed: 50ms is a stall a serving process
can absorb without a client seeing a timeout, and the leg fails if it is
exceeded. The pause is O(live rows) — at ~181 MB/s a 1GB live set implies
~5.5s, which is the number an incremental design must be bought against.
The spec deliberately did not buy it in advance.

FOUND BY MEASURING: the dump was 8x slower than it needed to be. It
flushed through wo_wal_commit, which fdatasyncs, so it paid one barrier
per 256 records. Intermediate durability there is worthless — the temp is
not authoritative until the rename and is fsynced once immediately before
it. With a single final barrier:

- ~107KB live: 23948us -> 2903us
- ~500KB live: 36361us -> 7526us
- ~1.98MB live: 107649us -> 13212us
- marginal ~22 MB/s -> ~181 MB/s, sync-bound to bandwidth-bound

Correctness re-proven after that change: wovm-test 36 suites 0 fail,
test_wal 760 pass including the 40-round kill-during-compaction battery.

Two measurement defects of my own, fixed rather than reported:

- boot measured through the driver's run() helper reported 251ms both
  with and without checkpointing — run() samples RSS on a 250ms poll, so
  every timing floors at the quantum. Measured directly instead, median
  of 3
- ckpt.reclaim_x was recorded as lower-is-better by the default detector,
  which would have PASSED "reclaimed nothing" and FAILED an improvement:
  the feature's central claim, gated backwards. Now higher-is-better,
  gated at 15% while the wall-clock metrics stay wide — waiving them all
  would have left the leg ungated, part A's task 4 mistake

- sample gains a `boot` mode that does nothing, so boot time is boot time
- walstats now reports compactions, pause max/total and compacted bytes
- baseline refreshed from the FULL campaign (N=20000, crash_reps=3), and
  a fresh full run passes 116 checks 0 failures
- gate bites: reclaim_x doctored to 1.0 -> FAIL on exactly that metric

One flake seen and checked, not papered over: durable.sN.query.ops_sec
failed once at 53% below baseline. It is a read-only metric that touches
no WAL code, and a re-run passed 116/0 with the box at load 1.85.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
shoney.arickathil 2026-08-29 06:20:13 +02:00
parent d432bc5301
commit 40d56c4664
7 changed files with 396 additions and 117 deletions

View file

@ -6,29 +6,71 @@
"note": "refresh only with a commit that says why; tolerances come from tolerance_for() in the driver",
"wal_n": 4000
},
"ckpt.boot_off_ms": {
"dir": "lower",
"floor": 456,
"tolerance_pct": 100,
"value": 114
},
"ckpt.boot_on_ms": {
"dir": "lower",
"floor": 260,
"tolerance_pct": 100,
"value": 65
},
"ckpt.bytes_off": {
"dir": "lower",
"floor": 7843356,
"tolerance_pct": 100,
"value": 1960839
},
"ckpt.bytes_on": {
"dir": "lower",
"floor": 3770868,
"tolerance_pct": 100,
"value": 942717
},
"ckpt.compactions": {
"dir": "lower",
"floor": 100,
"tolerance_pct": 100,
"value": 6
},
"ckpt.pause_us_max": {
"dir": "lower",
"floor": 10368,
"tolerance_pct": 100,
"value": 2592
},
"ckpt.reclaim_x": {
"dir": "higher",
"floor": 0.0,
"tolerance_pct": 15,
"value": 2.08
},
"durable.s1.mixread.ops_sec": {
"dir": "higher",
"floor": 2173,
"floor": 2185,
"tolerance_pct": 50,
"value": 8695
"value": 8740
},
"durable.s1.mixread.p50us": {
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 1
"value": 2
},
"durable.s1.mixread.p99us": {
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 14
"value": 13
},
"durable.s1.mixwrite.ops_sec": {
"dir": "higher",
"floor": 241,
"floor": 242,
"tolerance_pct": 50,
"value": 966
"value": 971
},
"durable.s1.mixwrite.p50us": {
"dir": "lower",
@ -38,15 +80,15 @@
},
"durable.s1.mixwrite.p99us": {
"dir": "lower",
"floor": 2832,
"floor": 2768,
"tolerance_pct": 50,
"value": 708
"value": 692
},
"durable.s1.query.ops_sec": {
"dir": "higher",
"floor": 314465,
"floor": 236183,
"tolerance_pct": 50,
"value": 1257861
"value": 944733
},
"durable.s1.query.p50us": {
"dir": "lower",
@ -58,13 +100,13 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 1
"value": 2
},
"durable.s1.read.ops_sec": {
"dir": "higher",
"floor": 318714,
"floor": 221317,
"tolerance_pct": 50,
"value": 1274859
"value": 885269
},
"durable.s1.read.p50us": {
"dir": "lower",
@ -76,25 +118,25 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 1
"value": 2
},
"durable.s1.seed.ops_sec": {
"dir": "higher",
"floor": 1102,
"floor": 1091,
"tolerance_pct": 15,
"value": 4409
"value": 4366
},
"durable.s1.seed.p50us": {
"dir": "lower",
"floor": 844,
"floor": 856,
"tolerance_pct": 15,
"value": 211
"value": 214
},
"durable.s1.seed.p99us": {
"dir": "lower",
"floor": 2280,
"floor": 2108,
"tolerance_pct": 15,
"value": 570
"value": 527
},
"durable.s1.wmix.mean_batch": {
"dir": "higher",
@ -104,21 +146,21 @@
},
"durable.s1.wmix.ops_sec": {
"dir": "higher",
"floor": 396,
"floor": 386,
"tolerance_pct": 15,
"value": 1586
"value": 1545
},
"durable.s1.wmix.p50us": {
"dir": "lower",
"floor": 1780,
"floor": 1784,
"tolerance_pct": 15,
"value": 445
"value": 446
},
"durable.s1.wmix.p99us": {
"dir": "lower",
"floor": 2728,
"floor": 2844,
"tolerance_pct": 15,
"value": 682
"value": 711
},
"durable.s1.wmix.peak_batch": {
"dir": "higher",
@ -134,45 +176,45 @@
},
"durable.s1.write.ops_sec": {
"dir": "higher",
"floor": 584,
"floor": 565,
"tolerance_pct": 15,
"value": 2338
"value": 2261
},
"durable.s1.write.p50us": {
"dir": "lower",
"floor": 1744,
"floor": 1776,
"tolerance_pct": 15,
"value": 436
"value": 444
},
"durable.s1.write.p99us": {
"dir": "lower",
"floor": 2588,
"floor": 2852,
"tolerance_pct": 15,
"value": 647
"value": 713
},
"durable.sN.mixread.ops_sec": {
"dir": "higher",
"floor": 1251,
"floor": 1124,
"tolerance_pct": 50,
"value": 5007
"value": 4496
},
"durable.sN.mixread.p50us": {
"dir": "lower",
"floor": 240,
"floor": 268,
"tolerance_pct": 50,
"value": 60
"value": 67
},
"durable.sN.mixread.p99us": {
"dir": "lower",
"floor": 14156,
"floor": 14280,
"tolerance_pct": 100,
"value": 3539
"value": 3570
},
"durable.sN.mixwrite.ops_sec": {
"dir": "higher",
"floor": 139,
"floor": 124,
"tolerance_pct": 50,
"value": 556
"value": 499
},
"durable.sN.mixwrite.p50us": {
"dir": "lower",
@ -182,15 +224,15 @@
},
"durable.sN.mixwrite.p99us": {
"dir": "lower",
"floor": 21280,
"floor": 15744,
"tolerance_pct": 100,
"value": 5320
"value": 3936
},
"durable.sN.query.ops_sec": {
"dir": "higher",
"floor": 309981,
"floor": 316055,
"tolerance_pct": 50,
"value": 1239925
"value": 1264222
},
"durable.sN.query.p50us": {
"dir": "lower",
@ -206,9 +248,9 @@
},
"durable.sN.read.ops_sec": {
"dir": "higher",
"floor": 291987,
"floor": 271385,
"tolerance_pct": 50,
"value": 1167951
"value": 1085540
},
"durable.sN.read.p50us": {
"dir": "lower",
@ -220,49 +262,49 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 100,
"value": 1
"value": 2
},
"durable.sN.seed.ops_sec": {
"dir": "higher",
"floor": 1121,
"floor": 1100,
"tolerance_pct": 50,
"value": 4484
"value": 4403
},
"durable.sN.seed.p50us": {
"dir": "lower",
"floor": 844,
"floor": 852,
"tolerance_pct": 50,
"value": 211
"value": 213
},
"durable.sN.seed.p99us": {
"dir": "lower",
"floor": 2248,
"floor": 2076,
"tolerance_pct": 100,
"value": 562
"value": 519
},
"durable.sN.wmix.mean_batch": {
"dir": "higher",
"floor": 1.0,
"tolerance_pct": 100,
"value": 6.35
"value": 6.5
},
"durable.sN.wmix.ops_sec": {
"dir": "higher",
"floor": 1535,
"floor": 1587,
"tolerance_pct": 50,
"value": 6140
"value": 6351
},
"durable.sN.wmix.p50us": {
"dir": "lower",
"floor": 26480,
"floor": 25584,
"tolerance_pct": 50,
"value": 6620
"value": 6396
},
"durable.sN.wmix.p99us": {
"dir": "lower",
"floor": 48548,
"floor": 36608,
"tolerance_pct": 100,
"value": 12137
"value": 9152
},
"durable.sN.wmix.peak_batch": {
"dir": "higher",
@ -278,27 +320,27 @@
},
"durable.sN.write.ops_sec": {
"dir": "higher",
"floor": 579,
"floor": 559,
"tolerance_pct": 50,
"value": 2317
"value": 2239
},
"durable.sN.write.p50us": {
"dir": "lower",
"floor": 1752,
"floor": 1792,
"tolerance_pct": 50,
"value": 438
"value": 448
},
"durable.sN.write.p99us": {
"dir": "lower",
"floor": 2628,
"floor": 3128,
"tolerance_pct": 100,
"value": 657
"value": 782
},
"ram.s1.mixread.ops_sec": {
"dir": "higher",
"floor": 22428,
"floor": 22256,
"tolerance_pct": 50,
"value": 89712
"value": 89025
},
"ram.s1.mixread.p50us": {
"dir": "lower",
@ -314,9 +356,9 @@
},
"ram.s1.mixwrite.ops_sec": {
"dir": "higher",
"floor": 2492,
"floor": 2472,
"tolerance_pct": 50,
"value": 9968
"value": 9891
},
"ram.s1.mixwrite.p50us": {
"dir": "lower",
@ -328,19 +370,19 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 1
"value": 2
},
"ram.s1.msgrate.msgs_sec": {
"dir": "higher",
"floor": 1756111,
"floor": 1737438,
"tolerance_pct": 15,
"value": 14048890
"value": 13899506
},
"ram.s1.query.ops_sec": {
"dir": "higher",
"floor": 208073,
"floor": 238891,
"tolerance_pct": 50,
"value": 832292
"value": 955566
},
"ram.s1.query.p50us": {
"dir": "lower",
@ -352,13 +394,13 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 2
"value": 1
},
"ram.s1.read.ops_sec": {
"dir": "higher",
"floor": 254556,
"floor": 257042,
"tolerance_pct": 50,
"value": 1018226
"value": 1028171
},
"ram.s1.read.p50us": {
"dir": "lower",
@ -374,9 +416,9 @@
},
"ram.s1.seed.ops_sec": {
"dir": "higher",
"floor": 56107,
"floor": 58306,
"tolerance_pct": 15,
"value": 224429
"value": 233225
},
"ram.s1.seed.p50us": {
"dir": "lower",
@ -388,13 +430,13 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 15,
"value": 13
"value": 10
},
"ram.s1.write.ops_sec": {
"dir": "higher",
"floor": 45587,
"floor": 44816,
"tolerance_pct": 15,
"value": 182351
"value": 179266
},
"ram.s1.write.p50us": {
"dir": "lower",
@ -406,55 +448,55 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 15,
"value": 12
"value": 16
},
"ram.sN.mixread.ops_sec": {
"dir": "higher",
"floor": 7482,
"floor": 11233,
"tolerance_pct": 50,
"value": 29930
"value": 44933
},
"ram.sN.mixread.p50us": {
"dir": "lower",
"floor": 272,
"floor": 248,
"tolerance_pct": 50,
"value": 68
"value": 62
},
"ram.sN.mixread.p99us": {
"dir": "lower",
"floor": 372,
"floor": 376,
"tolerance_pct": 50,
"value": 93
"value": 94
},
"ram.sN.mixwrite.ops_sec": {
"dir": "higher",
"floor": 831,
"floor": 1248,
"tolerance_pct": 50,
"value": 3325
"value": 4992
},
"ram.sN.mixwrite.p50us": {
"dir": "lower",
"floor": 296,
"floor": 268,
"tolerance_pct": 50,
"value": 74
"value": 67
},
"ram.sN.mixwrite.p99us": {
"dir": "lower",
"floor": 420,
"floor": 388,
"tolerance_pct": 50,
"value": 105
"value": 97
},
"ram.sN.msgrate.msgs_sec": {
"dir": "higher",
"floor": 307283,
"floor": 309065,
"tolerance_pct": 50,
"value": 2458270
"value": 2472524
},
"ram.sN.query.ops_sec": {
"dir": "higher",
"floor": 246669,
"floor": 257201,
"tolerance_pct": 50,
"value": 986679
"value": 1028806
},
"ram.sN.query.p50us": {
"dir": "lower",
@ -466,13 +508,13 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 1
"value": 3
},
"ram.sN.read.ops_sec": {
"dir": "higher",
"floor": 262357,
"floor": 293565,
"tolerance_pct": 50,
"value": 1049428
"value": 1174260
},
"ram.sN.read.p50us": {
"dir": "lower",
@ -488,9 +530,9 @@
},
"ram.sN.seed.ops_sec": {
"dir": "higher",
"floor": 63510,
"floor": 65093,
"tolerance_pct": 50,
"value": 254042
"value": 260375
},
"ram.sN.seed.p50us": {
"dir": "lower",
@ -502,24 +544,24 @@
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 8
"value": 10
},
"ram.sN.write.ops_sec": {
"dir": "higher",
"floor": 47959,
"floor": 53619,
"tolerance_pct": 50,
"value": 191839
"value": 214477
},
"ram.sN.write.p50us": {
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 8
"value": 7
},
"ram.sN.write.p99us": {
"dir": "lower",
"floor": 100,
"tolerance_pct": 50,
"value": 12
"value": 11
}
}

View file

@ -4,6 +4,7 @@
#include "wal.h"
#include <errno.h>
#include <time.h>
#include <fcntl.h>
#include <stdio.h>
#include <stdlib.h>
@ -493,9 +494,39 @@ static void sync_parent_dir(const char *path) {
close(fd);
}
/* databasev2 3: write the staged bytes WITHOUT a durability barrier.
*
* Only compaction's dump uses this. Intermediate durability there is worthless:
* the temp file is not authoritative until the rename, and it is fsynced once
* immediately before that. Using wo_wal_commit for the dump instead cost one
* fdatasync per 256 records — measured, that was most of the stop-the-world
* pause (~22 MB/s, where the fixed cost plus ~150 redundant syncs dominated a
* 2 MB dump). */
static int wal_write_nosync(wo_wal *w) {
size_t at = 0;
while (at < w->len) {
ssize_t n = pwrite(w->fd, w->buf + at, w->len - at, (off_t)(w->off + at));
if (n < 0) {
if (errno == EINTR) continue;
return -1;
}
at += (size_t)n;
}
w->off += w->len;
w->len = 0;
return 0;
}
static uint64_t mono_us(void) {
struct timespec ts;
if (clock_gettime(CLOCK_MONOTONIC, &ts) != 0) return 0;
return (uint64_t)ts.tv_sec * 1000000ull + (uint64_t)ts.tv_nsec / 1000ull;
}
int wo_wal_compact(wo_wal *w, wo_db *db) {
/* staged records would be written into a file about to be replaced */
if (!w->path || w->len != 0) return -1;
uint64_t t0 = mono_us();
char tmp[4096];
if ((size_t)snprintf(tmp, sizeof tmp, "%s%s", w->path, WO_WAL_TMP_SUFFIX) >= sizeof tmp)
@ -526,13 +557,15 @@ int wo_wal_compact(wo_wal *w, wo_db *db) {
(size_t)(g % DB_SLAB_ROWS) * t->row_size);
if (wo_wal_append_insert(&nw, db, cid, r->id) != 0) goto fail;
if (++pending >= WO_WAL_COMPACT_FLUSH) {
if (wo_wal_commit(&nw) != 0) goto fail;
if (wal_write_nosync(&nw) != 0) goto fail;
pending = 0;
}
}
}
if (wo_wal_commit(&nw) != 0) goto fail; /* the tail batch */
if (fsync(nw.fd) != 0) goto fail; /* commit fdatasyncs; this is for the size */
if (wal_write_nosync(&nw) != 0) goto fail; /* the tail batch */
/* THE dump's one and only barrier: everything above is just bytes in the
* page cache until this, and nothing reads the temp before the rename. */
if (fsync(nw.fd) != 0) goto fail;
uint64_t new_bytes = nw.off;
wo_wal_close(&nw);
@ -551,6 +584,12 @@ int wo_wal_compact(wo_wal *w, wo_db *db) {
w->off = new_bytes;
w->len = 0;
w->compacted_bytes = new_bytes;
{ /* the stop-the-world pause: nothing was served while this ran */
uint64_t el = mono_us() - t0;
w->stat_compactions++;
w->stat_compact_us_total += el;
if (el > w->stat_compact_us_max) w->stat_compact_us_max = el;
}
return 0;
fail:

View file

@ -73,6 +73,12 @@ typedef struct wo_wal {
* appends never extend the file, which is what lets fdatasync alone be the
* ack barrier. A replacement without it silently weakens durability. */
uint64_t prealloc;
/* databasev2 3: what compaction actually did, reported under WO_WAL_STATS.
* The PAUSE is the number the spec refused to assume — compaction is
* stop-the-world, so its duration is the cost being weighed. */
uint64_t stat_compactions;
uint64_t stat_compact_us_max;
uint64_t stat_compact_us_total;
} wo_wal;
/* Open (create if missing) and preallocate [prealloc] bytes (best-effort;

View file

@ -550,7 +550,7 @@ fn all_mode(n: Int) -> Int {
fn usage() -> Int {
print_err("usage: db-bench <mode>");
print_err(" all N | seed N | read N | query N | write N | wal N");
print_err(" mix N C | wmix N C | msgrate N | verify | verify-acked M");
print_err(" mix N C | wmix N C | msgrate N | verify | verify-acked M | boot");
return 2;
}
@ -561,6 +561,12 @@ fn main(args: multi Text) -> Int {
if args[0] == "verify" {
return verify();
}
-- databasev2 3: does NOTHING. With WO_DATA set the runtime replays the whole
-- log before main runs, so a mode with no work of its own measures replay
-- plus a fixed process start — which is what "boot time" has to mean.
if args[0] == "boot" {
return 0;
}
if len(args) < 2 {
return usage();
}

View file

@ -166,3 +166,69 @@ the "close the 66× gap" framing part B was originally given.
because a 2–4×-variable tail gated at 50% gates the disk rather than the engine.
The **floor** is the real guard there, and it is not slack: `mixread`'s floor
(4172 µs) came within 25 µs of tripping on the worst observed run.
## 7. WAL checkpoint: compaction (databasev2 3)
**Measured 2026-08-29.** Before this the log grew forever: nothing ever removed
superseded records, so boot replayed all history and the file only ever got
bigger. Compaction rewrites it as one record per live row and swaps it in with
`rename`.
### Space and boot — the same workload, twice
Identical work, differing only in whether checkpointing may fire (an enormous
floor disables it). Full campaign:
| | checkpointing off | checkpointing on |
| --- | --- | --- |
| WAL used | 1 962 358 B | **907 094 B** |
| boot (median of 3, `boot` mode) | 114 ms | **64 ms** |
| compactions | 0 | 6 |
**2.16× space reclaimed, 1.78× faster boot.** Boot is measured with a mode that
does nothing at all: with `WO_DATA` set the runtime replays the whole log before
`main` runs, so a mode with no work of its own is the only honest way to price
replay. It is *not* measured through the driver's `run()` helper, which samples
RSS on a 250 ms poll — timings taken that way reported "251 ms" both with and
without checkpointing, which is the harness's clock rather than the engine's.
### The stop-the-world pause, and why it stopped being 8× worse
Compaction blocks the owner shard for its duration. The spec refused to assume
that was acceptable, so it is measured and gated against a stated **50 ms**
budget: a stall a serving process can absorb without a client seeing a timeout.
Measured **2 651 µs** on the full campaign — comfortably inside it.
It was not always. The first implementation flushed the dump through
`wo_wal_commit`, which `fdatasync`s, so a dump paid one barrier per 256 records:
| live set | pause, per-flush fsync | pause, one final fsync |
| --- | --- | --- |
| ~107 KB | 23 948 µs | **2 903 µs** |
| ~500 KB | 36 361 µs | **7 526 µs** |
| ~1.98 MB | 107 649 µs | **13 212 µs** |
Marginal rate went from **~22 MB/s to ~181 MB/s** — from sync-bound to
bandwidth-bound. Intermediate durability during a dump is worthless: the temp
file is not authoritative until the rename and is fsynced once immediately
before it, so those barriers bought nothing and cost 8×.
**The pause is O(live rows), and that is the number that eventually forces an
incremental design.** At ~181 MB/s a 1 GB live set implies roughly 5.5 s — well
past any interactive budget. The spec deliberately did not buy incremental
copying in advance; this is the measurement it is to be bought against.
### Gating
`ckpt.reclaim_x` is the feature's central claim and is gated tightly (15%).
Everything else in the leg — boot times, the pause, the byte counts — is
wall-clock or workload-shaped on a shared box and carries a wide tolerance,
because waiving them *all* would have left the leg ungated. The leg also
asserts two things directly rather than trusting a metric: that some compaction
actually ran (otherwise it proves nothing), and that the log really is smaller
with checkpointing on.
One direction bug worth recording: `reclaim_x` was first recorded as
lower-is-better by the default detector, which would have **passed "reclaimed
nothing" and failed an improvement** — the central claim gated backwards.

View file

@ -130,9 +130,15 @@ static void gc_pump(wo_vm *vm) {
* of every durable program; a gate that wants the numbers asks for them. */
static void wal_stats_report(const wo_wal *w) {
if (!w || !getenv("WO_WAL_STATS")) return;
fprintf(stderr, "walstats batches=%llu records=%llu peak_batch=%llu peak_staged=%llu\n",
fprintf(stderr,
"walstats batches=%llu records=%llu peak_batch=%llu peak_staged=%llu "
"compactions=%llu compact_us_max=%llu compact_us_total=%llu compacted_bytes=%llu\n",
(unsigned long long)w->stat_batches, (unsigned long long)w->stat_records,
(unsigned long long)w->stat_peak_batch, (unsigned long long)w->stat_peak_staged);
(unsigned long long)w->stat_peak_batch, (unsigned long long)w->stat_peak_staged,
(unsigned long long)w->stat_compactions,
(unsigned long long)w->stat_compact_us_max,
(unsigned long long)w->stat_compact_us_total,
(unsigned long long)w->compacted_bytes);
}
int main(int argc, char **argv) {

View file

@ -33,6 +33,17 @@ N = 2000 if QUICK else 20000
# measured mean batch rose 1.13 -> 1.76 -> 5.35 at C = 4 -> 16 -> 64.
WMIX_N = 4000 if QUICK else 20000
WMIX_C = 32 if QUICK else 64
# databasev2 3: the checkpoint leg. Ages a store by UPDATING the same rows, so
# history grows while the live set does not — otherwise the leg measures insert
# throughput instead of compaction.
CKPT_SEED = 2000 if QUICK else 5000
CKPT_OPS = 8000 if QUICK else 20000
# The stop-the-world budget. 50ms is a stall a serving process can absorb
# without a client noticing a timeout; measured at ~13ms for a 2MB live set,
# so this leaves real headroom while still failing before a stall becomes
# user-visible. Compaction is O(live rows), so this budget is what eventually
# forces the incremental design the spec deliberately did not buy in advance.
CKPT_PAUSE_BUDGET_US = 50000
MSG_N = 20000 if QUICK else 200000
WAL_N = 800 if QUICK else 4000
CRASH_REPS = 1 if QUICK else 3
@ -302,6 +313,13 @@ def tolerance_for(key):
# (4172us) came within 25us of tripping on the worst run.
if key.startswith("durable.sN.") and key.endswith(".p99us"):
return 100
# databasev2 3: the RECLAIM ratio is structural and gated tightly — it is
# the feature's whole claim. Boot time and the pause are wall-clock on a
# shared box and are not: waiving them all would have left the leg ungated,
# which is the mistake part A's task 4 made and had to undo.
if key in ("ckpt.boot_off_ms", "ckpt.boot_on_ms", "ckpt.pause_us_max",
"ckpt.compactions", "ckpt.bytes_off", "ckpt.bytes_on"):
return 100
if ".mixread." in key or ".mixwrite." in key: return 50
if ".sN." in key: return 50
if ".read." in key or ".query." in key: return 50
@ -313,7 +331,11 @@ def write_baseline(metrics):
"tolerances come from tolerance_for() in the driver"}}
for k, v in sorted(metrics.items()):
if k.endswith(("rss_growth_kb", "fd_growth")): continue
higher = k.endswith(("ops_sec", "msgs_sec", "mean_batch", "peak_batch"))
# reclaim_x: MORE reclaimed is better. Recorded as lower-is-better by
# the default detector, which would have passed "no reclaim at all" and
# failed an improvement — the feature's central claim, gated backwards.
higher = k.endswith(("ops_sec", "msgs_sec", "mean_batch", "peak_batch",
"reclaim_x"))
floor_div = 8 if k.endswith("msgs_sec") else 4
# latency floors never sit below 100µs: at post-index µs scale a
# 4×1µs "catastrophe line" is noise; the tripwire means "µs became
@ -325,6 +347,97 @@ def write_baseline(metrics):
json.dump(base, open(BASELINE, "w"), indent=1, sort_keys=True)
ok(f"baseline written ({len(base) - 1} metrics)")
def wal_used_bytes(data):
"""Bytes actually written, as the non-zero prefix — never the file size:
shard WALs are preallocated, so getsize reports the preallocation."""
total = 0
for name in sorted(os.listdir(data)):
with open(os.path.join(data, name), "rb") as f:
total += len(f.read().rstrip(b"\x00"))
return total
def checkpoint_leg(metrics):
"""Space reclaimed, boot time, and the stop-the-world PAUSE.
The same workload runs twice, differing only in whether checkpointing can
fire: an enormous floor disables it, a small one lets it. Comparing two runs
of one build is what isolates compaction from everything else the workload
does.
Boot is measured with the sample's `boot` mode, which does nothing at all —
with WO_DATA set the runtime replays the whole log before main runs, so a
mode with no work of its own is the only honest way to price replay."""
ncores = os.cpu_count() or 1
out = {}
for name, knobs in (("off", {"WO_CHECKPOINT_BYTES": "1000000000"}),
("on", {"WO_CHECKPOINT_BYTES": "65536", "WO_CHECKPOINT_RATIO": "2"})):
data = os.path.join(ROOT, "bench", f"tmp.{os.getpid()}.ckpt.{name}")
shutil.rmtree(data, ignore_errors=True); os.makedirs(data, exist_ok=True)
env = {"WO_DATA": data, "WO_SHARDS": str(ncores), "WO_WAL_STATS": "1"}
env.update(knobs)
rc, _, _, _ = run(["seed", str(CKPT_SEED)], env, 1800)
if rc != 0:
bad(f"ckpt.{name}.seed", f"rc={rc}"); shutil.rmtree(data, ignore_errors=True); return
rc, lines, _, _ = run(["wmix", str(CKPT_OPS), "16"], env, 1800)
if rc != 0:
bad(f"ckpt.{name}.age", f"rc={rc}"); shutil.rmtree(data, ignore_errors=True); return
stats = {}
for l in lines:
f = l.split()
if f and f[0] == "walstats":
stats = dict(x.split("=", 1) for x in f[1:] if "=" in x)
used = wal_used_bytes(data)
# NOT through run(): it samples RSS on a 250ms poll, so every timing it
# produces floors at the poll quantum — boot measured that way reported
# 251ms both with and without checkpointing, which is the harness's
# clock, not the engine's. Median of 3 because this is wall-clock.
benv = dict(os.environ)
benv.update({"WO_DATA": data, "WO_SHARDS": str(ncores)})
samples = []
brc = 0
for _ in range(3):
t0 = time.monotonic()
pr = subprocess.run([BIN, "boot"], stdout=subprocess.DEVNULL,
stderr=subprocess.DEVNULL, env=benv, timeout=900)
samples.append((time.monotonic() - t0) * 1000.0)
brc = pr.returncode or brc
boot_ms = sorted(samples)[1]
if brc != 0:
bad(f"ckpt.{name}.boot", f"rc={brc}"); shutil.rmtree(data, ignore_errors=True); return
out[name] = (used, boot_ms, stats)
shutil.rmtree(data, ignore_errors=True)
(off_b, off_boot, _), (on_b, on_boot, st) = out["off"], out["on"]
comps = int(st.get("compactions", 0))
if comps == 0:
bad("ckpt.inert", "no compaction ran — the leg proves nothing about checkpointing")
return
metrics["ckpt.compactions"] = comps
metrics["ckpt.bytes_off"] = off_b
metrics["ckpt.bytes_on"] = on_b
metrics["ckpt.reclaim_x"] = round(off_b / max(on_b, 1), 2)
metrics["ckpt.boot_off_ms"] = int(round(off_boot))
metrics["ckpt.boot_on_ms"] = int(round(on_boot))
metrics["ckpt.pause_us_max"] = int(st.get("compact_us_max", 0))
ok(f"ckpt: {off_b} -> {on_b} bytes ({metrics['ckpt.reclaim_x']}x reclaimed) over "
f"{comps} compactions; boot {off_boot:.0f} -> {on_boot:.0f} ms; "
f"stop-the-world pause max {metrics['ckpt.pause_us_max']}us")
# the space claim is the point of the feature, so it is asserted, not just recorded
if off_b <= on_b:
bad("ckpt.no-reclaim", f"checkpointing did not shrink the log ({off_b} -> {on_b})")
else:
ok(f"ckpt: the log is smaller with checkpointing on")
# THE BUDGET. Stated, not assumed — the spec refused to assume it.
if metrics["ckpt.pause_us_max"] > CKPT_PAUSE_BUDGET_US:
bad("ckpt.pause-budget",
f"stop-the-world pause {metrics['ckpt.pause_us_max']}us exceeds the stated "
f"{CKPT_PAUSE_BUDGET_US}us budget — alternatives (incremental copy, "
f"fork-and-dump) are bought against THIS number")
else:
ok(f"ckpt: pause within budget ({metrics['ckpt.pause_us_max']} <= {CKPT_PAUSE_BUDGET_US}us)")
def main():
# --check <results.json>: gate-only evaluation of a recorded run — the
# gate-bites smoke doctors a copy and this mode must FAIL on it
@ -337,6 +450,7 @@ def main():
build()
metrics = campaign()
durability(metrics)
checkpoint_leg(metrics)
os.makedirs(RESULTS_DIR, exist_ok=True)
stamp = time.strftime("%Y%m%d-%H%M%S")
out = os.path.join(RESULTS_DIR, f"run-{stamp}{'-quick' if QUICK else ''}.json")