From 40d56c4664c8f5d5b9a527e0910aa8d1723f3e6f Mon Sep 17 00:00:00 2001 From: "shoney.arickathil" Date: Sat, 29 Aug 2026 06:20:13 +0200 Subject: [PATCH] =?UTF-8?q?perf(wal):=20checkpoint=20measured=20=E2=80=94?= =?UTF-8?q?=202.16x=20space,=201.78x=20boot,=202.7ms=20pause=20=E2=80=94?= =?UTF-8?q?=20T5?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- bench/baseline.json | 262 +++++++++++++++++++-------------- database/src/wal.c | 45 +++++- database/src/wal.h | 6 + docs/examples/db-bench/main.wo | 8 +- docs/plan/perf-targets.md | 66 +++++++++ runtime/src/main.c | 10 +- scripts/db-bench.py | 116 ++++++++++++++- 7 files changed, 396 insertions(+), 117 deletions(-) diff --git a/bench/baseline.json b/bench/baseline.json index 0d748fe..218e002 100644 --- a/bench/baseline.json +++ b/bench/baseline.json @@ -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 } } \ No newline at end of file diff --git a/database/src/wal.c b/database/src/wal.c index 5fb28b5..02ff2f4 100644 --- a/database/src/wal.c +++ b/database/src/wal.c @@ -4,6 +4,7 @@ #include "wal.h" #include +#include #include #include #include @@ -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: diff --git a/database/src/wal.h b/database/src/wal.h index 442e81c..2e484c3 100644 --- a/database/src/wal.h +++ b/database/src/wal.h @@ -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; diff --git a/docs/examples/db-bench/main.wo b/docs/examples/db-bench/main.wo index 87467b4..0925196 100644 --- a/docs/examples/db-bench/main.wo +++ b/docs/examples/db-bench/main.wo @@ -550,7 +550,7 @@ fn all_mode(n: Int) -> Int { fn usage() -> Int { print_err("usage: db-bench "); 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(); } diff --git a/docs/plan/perf-targets.md b/docs/plan/perf-targets.md index 4461beb..29dcd5f 100644 --- a/docs/plan/perf-targets.md +++ b/docs/plan/perf-targets.md @@ -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. diff --git a/runtime/src/main.c b/runtime/src/main.c index 3cb0f1c..3bacaef 100644 --- a/runtime/src/main.c +++ b/runtime/src/main.c @@ -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) { diff --git a/scripts/db-bench.py b/scripts/db-bench.py index 32a1237..696a53a 100755 --- a/scripts/db-bench.py +++ b/scripts/db-bench.py @@ -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 : 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")