Artifact 1ce3cfb1eec19cdba9345ec432d01aa2e0f56dfb0ecae7c578638a3d60d9cfa8:
- File
src/logstore_benchmark.zig
— part of check-in
[de218fa6f6]
at
2026-07-25 00:21:57
on branch trunk
— serve: open the listener before priming; move the post-push rebuild off the request path
zit serve built its whole in-memory snapshot of the repository before it opened the listener socket. The build is O(store), so past a few thousand artifacts it outlasted the client's readiness probe and the client reported the server never came up — the store could be served, just never reached.
Bring-up now binds first: listen, announce, then prime, then accept. A client that connects during the prime queues in the kernel accept backlog instead of being refused, so the readiness window starts at the bind rather than after the scans. The listener open moves ahead of BOTH O(store) reads on the path — the config read and the prime. The connection deadline is armed only on accept, so priming never falls inside it. On a 254k-artifact store a connect now completes in ~2 ms against a ~5 s prime.
A push made the snapshot stale, and the old code rebuilt it inside the pushing round's own reply deadline — an O(store) rebuild charged to the request that caused it. The rebuild moves to a maintain hook the accept loop runs between connections, with no connection open to charge it to; the append-only stat gate makes the stale snapshot self-correcting until then.
The reorder is inherently a large-corpus latency property: reverting it leaves every unit test green, because the failure only shows when prime latency exceeds the readiness window. It is pinned in the milestone tier instead, where smoke already lives: zig build bench -- serve synthesizes a store, spawns the real server, and asserts time-to-first-connect is a small fraction of the prime (fixed order ~0.1; reverted order jumps past 1.0). The de-race and the accept-loop hook are pinned by ordinary unit tests. (user: dmestas, size: 23310) [annotate] [blame] [check-ins using]
//! LogStore benchmark harness (storage-track-plan.md §C / storage-slice.md). //! //! `zig build bench -- <put|read|open> [flags]`. Measures the LogStore's //! actual raw-frame paths — there is no RFC oracle behind a benchmark, so //! this file implements no normative clause and asserts no comparative //! claim: it prints measured MB/s, ops/s, and p50/p99 latencies and nothing //! else. The plan's targets (>=200 MB/s put, <=150us/<=10us content, >=1 //! GB/s scan) are goals to eyeball against, never encoded here. //! //! Scope: the store today writes/reads `raw` frames only (logstore.zig //! hardcodes FrameKind.raw on append and rejects any other kind on read), //! so this measures the raw path — `put` = encode + append; `commit` = one //! fsync; `content` = pread + two crc32 + hash memcmp + owned alloc; `open` //! = header validate + full frame scan + index rebuild. zlib/delta frames //! do not exist yet; benching a nonexistent inflate/apply path would be a //! fabricated number, so it is deliberately out of scope (a `--kind` axis //! joins when the delta slice lands). This scoping is printed in each header. //! //! Everything effectful goes through the injected `std.Io`: the monotonic //! clock is `Io.Clock.awake` (0.16 routes wall/monotonic time through the //! injected Io rather than a free-standing timer type), and the //! backing file is a real temp file reached only through `init.io`. The //! LogStore/StorageFile library code stays pure and injected; only this //! top-level harness reads the clock and touches the filesystem. Corpus //! bytes derive solely from a seeded PRNG — no ambient entropy anywhere. const std = @import("std"); const Io = std.Io; const storage = @import("zit").storage; const logstore = @import("zit").logstore; /// Closed harness error set: `Storage`/`Corrupt` propagate from LogStore, /// `ReadMismatch` is the in-bench correctness guard (a benchmark that /// silently measures a broken read is worse than none), `BadArgs` is a /// rejected/oversized flag, `Io` is a failed temp-file syscall. Printing /// adds the writer's own error set — both explicit, never `anyerror`. const BenchError = error{ OutOfMemory, Storage, Corrupt, BadArgs, ReadMismatch, Io }; /// The `sync` subcommand's harness has its own closed causes (control /// divergence, nondeterminism, the sync/logstore seam errors); fold them in so /// `run` stays a single named error set the top-level `main` prints by name. const RunError = BenchError || @import("sync_benchmark.zig").Error || @import("storage_benchmark.zig").Error || @import("warmread_benchmark.zig").Error || @import("serve_benchmark.zig").Error || Io.Writer.Error; /// Explicit fixed caps (TigerStyle bounds); each overflow -> `BadArgs`. const max_count: u64 = 10_000_000; /// <= LogStore.max_payload; 8-byte floor leaves room for the index prefix. const max_blob: u64 = 64 << 20; const min_blob: u64 = 8; const max_reps: u64 = 1000; /// Content address width the harness synthesizes for every blob. const hash_len: usize = 32; const Cmd = enum { put, read, open }; /// All inputs arrive here from argv only; defaults match the plan's /// measurement points (100k x 10 KiB, commit every 100). const Config = struct { seed: u64 = 42, count: u64 = 100_000, blob: u64 = 10_240, commit_every: u64 = 100, working_set: u64 = 1024, reps: u64 = 5, }; const Parsed = struct { cmd: Cmd, cfg: Config }; pub fn main(init: std.process.Init) !void { const gpa = init.gpa; const io = init.io; const args = try init.minimal.args.toSlice(init.arena.allocator()); var out_buf: [4096]u8 = undefined; var out_w: Io.File.Writer = .init(.stdout(), io, &out_buf); const out = &out_w.interface; var err_buf: [256]u8 = undefined; var err_w: Io.File.Writer = .init(.stderr(), io, &err_buf); const err = &err_w.interface; run(gpa, io, args, out) catch |e| { err.print("bench: {s}\n", .{@errorName(e)}) catch {}; err.flush() catch {}; std.process.exit(1); }; try out.flush(); } fn run(gpa: std.mem.Allocator, io: Io, args: []const []const u8, out: *Io.Writer) RunError!void { if (args.len < 2) return usage(out); // The `sync` clone benchmark carries its own string-valued flags // (`--size small`), so it is routed before `parseArgs` (which parses every // flag value as an integer). Its harness lives in `sync_benchmark.zig`. if (std.mem.eql(u8, args[1], "sync")) return @import("sync_benchmark.zig").run(gpa, io, args, out); // `storage` takes an optional `.zit` path positional and string-free // integer flags; it is routed before `parseArgs` (which rejects a // non-flag positional). Its harness lives in `storage_benchmark.zig`. if (std.mem.eql(u8, args[1], "storage")) return @import("storage_benchmark.zig").run(gpa, io, args, out); // `warm` takes a `.zit` path positional and instruments the warm read path // (cache-body I/O vs replay re-derivation vs formatting). Routed before // `parseArgs` (which rejects a non-flag positional). if (std.mem.eql(u8, args[1], "warm")) return @import("warmread_benchmark.zig").run(gpa, io, args, out); // `serve` synthesizes a `.zit`, spawns the real `zit serve` against it, and // asserts the #13 listen-before-prime order (a run-on-demand milestone // probe). Routed before `parseArgs` (its only flag, `--artifacts`, is an // integer, but the subcommand keyword is not a `put|read|open` verb). if (std.mem.eql(u8, args[1], "serve")) return @import("serve_benchmark.zig").run(gpa, io, args, out); const parsed = try parseArgs(args); switch (parsed.cmd) { .put => try benchPut(gpa, io, parsed.cfg, out), .read => try benchRead(gpa, io, parsed.cfg, out), .open => try benchOpen(gpa, io, parsed.cfg, out), } } fn usage(out: *Io.Writer) RunError!void { try out.writeAll( \\usage: zig build bench -- <put|read|open> [flags] \\ put [--seed N] [--count N] [--blob N] [--commit-every N] \\ read [--seed N] [--count N] [--blob N] [--working-set N] [--reps N] \\ open [--seed N] [--count N] [--blob N] [--reps N] \\ sync [--size small|medium|large|all] [--artifacts N] [--blob N] \\ [--delta-frac F] [--seed N] [--reps N] \\ storage [<.zit path>] [--seed N] [--count N] [--blob N] [--manifest-frac N] \\ warm <.zit path> [--reps N] [--warmup N] \\ serve [--artifacts N] \\measures the LogStore raw-frame path (put/read/open) in MB/s, ops/s, \\p50/p99; `sync` clones a seeded repo in-process and reports a per-phase \\time breakdown + protocol/byte counters (sync-performance-plan.md M1); \\`storage` reports bytes at rest by frame-kind + artifact-type and serve \\CPU over a real or synthetic `.zit` (read-only diagnostic). \\ ); } // --------------------------------------------------------------------------- // Argument parsing // --------------------------------------------------------------------------- fn parseArgs(args: []const []const u8) BenchError!Parsed { std.debug.assert(args.len >= 2); const cmd = parseCmd(args[1]) orelse return error.BadArgs; var cfg = Config{}; var i: usize = 2; while (i < args.len) : (i += 1) { const flag = args[i]; i += 1; if (i >= args.len) return error.BadArgs; // flag with no value const val = std.fmt.parseInt(u64, args[i], 0) catch return error.BadArgs; if (std.mem.eql(u8, flag, "--seed")) { cfg.seed = val; } else if (std.mem.eql(u8, flag, "--count")) { cfg.count = val; } else if (std.mem.eql(u8, flag, "--blob")) { cfg.blob = val; } else if (std.mem.eql(u8, flag, "--commit-every")) { cfg.commit_every = val; } else if (std.mem.eql(u8, flag, "--working-set")) { cfg.working_set = val; } else if (std.mem.eql(u8, flag, "--reps")) { cfg.reps = val; } else return error.BadArgs; } try validate(&cfg); return .{ .cmd = cmd, .cfg = cfg }; } fn parseCmd(s: []const u8) ?Cmd { if (std.mem.eql(u8, s, "put")) return .put; if (std.mem.eql(u8, s, "read")) return .read; if (std.mem.eql(u8, s, "open")) return .open; return null; } /// Enforce every fixed cap up front; `working_set` is clamped to `count` /// rather than rejected (a natural, non-surprising fit). fn validate(cfg: *Config) BenchError!void { if (cfg.count < 1 or cfg.count > max_count) return error.BadArgs; if (cfg.blob < min_blob or cfg.blob > max_blob) return error.BadArgs; if (cfg.commit_every < 1) return error.BadArgs; if (cfg.reps < 1 or cfg.reps > max_reps) return error.BadArgs; if (cfg.working_set < 1) return error.BadArgs; if (cfg.working_set > cfg.count) cfg.working_set = cfg.count; } // --------------------------------------------------------------------------- // Deterministic corpus (pure — no clock, no file, no ambient entropy) // --------------------------------------------------------------------------- /// Fills `buf` from `seed` and `index` alone, so a run replays exactly and /// any rid's expected bytes can be regenerated for read-back verification. /// The first 8 bytes carry `index` (little-endian), guaranteeing distinct /// blobs — hence distinct content hashes — across indices. fn fillBlob(seed: u64, index: u64, buf: []u8) void { std.debug.assert(buf.len >= 8); var mix = std.hash.Wyhash.init(seed); mix.update(std.mem.asBytes(&index)); var prng = std.Random.DefaultPrng.init(mix.final()); prng.random().bytes(buf); std.mem.writeInt(u64, buf[0..8], index, .little); } fn hashBlob(buf: []const u8) [hash_len]u8 { var h: [hash_len]u8 = undefined; std.crypto.hash.sha2.Sha256.hash(buf, &h, .{}); return h; } // --------------------------------------------------------------------------- // Temp backing file (real file, reached only through injected Io) // --------------------------------------------------------------------------- /// A throwaway `/tmp` file, named from the monotonic clock so concurrent /// runs never collide, unlinked on cleanup. const Temp = struct { file: Io.File, path_buf: [64]u8, path_len: usize, fn create(io: Io) BenchError!Temp { var t: Temp = undefined; const nonce = Io.Clock.Timestamp.now(io, .awake).raw.nanoseconds; const p = std.fmt.bufPrint(&t.path_buf, "/tmp/zit-bench-{d}.log", .{nonce}) catch return error.BadArgs; t.path_len = p.len; t.file = Io.Dir.createFileAbsolute(io, t.path_buf[0..t.path_len], .{ .read = true }) catch return error.Io; return t; } fn path(self: *const Temp) []const u8 { return self.path_buf[0..self.path_len]; } fn cleanup(self: *Temp, io: Io) void { self.file.close(io); Io.Dir.deleteFileAbsolute(io, self.path()) catch {}; } }; /// Writes `count` distinct blobs into a fresh store, committing on the /// configured cadence plus a final commit. Shared by every subcommand that /// needs a populated log. Asserts the dense-rid invariant (rid == i+1). fn buildLog(store: *logstore.LogStore, cfg: Config, blob: []u8) BenchError!void { std.debug.assert(blob.len == cfg.blob); const n: usize = @intCast(cfg.count); for (0..n) |i| { fillBlob(cfg.seed, @intCast(i), blob); const h = hashBlob(blob); const rid = store.put(&h, blob) catch |e| return mapPut(e); std.debug.assert(rid == @as(logstore.Rid, i) + 1); if ((i + 1) % cfg.commit_every == 0) store.commit() catch return error.Storage; } store.commit() catch return error.Storage; } // --------------------------------------------------------------------------- // put // --------------------------------------------------------------------------- /// Times each `put` call in isolation (samples exclude the fsync); wall time /// spans the whole loop, so the two reported lines separate the committed /// cadence (fsync included) from the raw append rate (fsync excluded). fn benchPut(gpa: std.mem.Allocator, io: Io, cfg: Config, out: *Io.Writer) RunError!void { var temp = try Temp.create(io); defer temp.cleanup(io); var fs = storage.FileStorage.init(io, temp.file, 0); var store = logstore.LogStore.open(gpa, fs.storageFile(), 0) catch |e| return mapOpen(e); defer store.deinit(gpa); const blob = try gpa.alloc(u8, @intCast(cfg.blob)); defer gpa.free(blob); const samples = try gpa.alloc(u64, @intCast(cfg.count)); defer gpa.free(samples); const n: usize = @intCast(cfg.count); var append_ns: u64 = 0; const wall0 = now(io); for (0..n) |i| { fillBlob(cfg.seed, @intCast(i), blob); const h = hashBlob(blob); const s0 = now(io); const rid = store.put(&h, blob) catch |e| return mapPut(e); const dt = elapsed(s0, now(io)); std.debug.assert(rid == @as(logstore.Rid, i) + 1); samples[i] = dt; append_ns += dt; if ((i + 1) % cfg.commit_every == 0) store.commit() catch return error.Storage; } store.commit() catch return error.Storage; const wall = elapsed(wall0, now(io)); const bytes = cfg.blob * cfg.count; std.sort.pdq(u64, samples, {}, std.sort.asc(u64)); try header(out, "put", cfg); try line(out, "put ", cfg, cfg.count, bytes, wall, samples); try appendLine(out, cfg, bytes, append_ns); } // --------------------------------------------------------------------------- // read // --------------------------------------------------------------------------- /// Builds and commits the log, reopens it (fresh index rebuild), then times /// content() twice: a cold first-touch pass over every rid in order, then a /// warm pass rereading the first `working_set` rids `reps` times. Every read /// is verified against the regenerated blob (error.ReadMismatch on drift). fn benchRead(gpa: std.mem.Allocator, io: Io, cfg: Config, out: *Io.Writer) RunError!void { var temp = try Temp.create(io); defer temp.cleanup(io); const blob = try gpa.alloc(u8, @intCast(cfg.blob)); defer gpa.free(blob); var fs0 = storage.FileStorage.init(io, temp.file, 0); var builder = logstore.LogStore.open(gpa, fs0.storageFile(), 0) catch |e| return mapOpen(e); try buildLog(&builder, cfg, blob); const total = builder.size(); builder.deinit(gpa); var fs = storage.FileStorage.init(io, temp.file, total); var store = logstore.LogStore.open(gpa, fs.storageFile(), 0) catch |e| return mapOpen(e); defer store.deinit(gpa); try header(out, "read", cfg); const cold = try gpa.alloc(u64, @intCast(cfg.count)); defer gpa.free(cold); const cold_bytes = try readPass(gpa, io, &store, cfg, blob, cold, 0, cfg.count); std.sort.pdq(u64, cold, {}, std.sort.asc(u64)); try line(out, "cold", cfg, cfg.count, cold_bytes, sum(cold), cold); try out.writeAll(" # cold = first touch after open; a lower bound on a true cold cache (page-cache eviction needs privileges, out of scope)\n"); const ws: u64 = cfg.working_set; const warm = try gpa.alloc(u64, @intCast(ws * cfg.reps)); defer gpa.free(warm); var wi: usize = 0; var warm_bytes: u64 = 0; for (0..@intCast(cfg.reps)) |_| { warm_bytes += try readPass(gpa, io, &store, cfg, blob, warm[wi..][0..@intCast(ws)], 0, ws); wi += @intCast(ws); } std.sort.pdq(u64, warm, {}, std.sort.asc(u64)); try line(out, "warm", cfg, ws * cfg.reps, warm_bytes, sum(warm), warm); } /// Reads rids `first+1 .. first+count`, timing content() alone; verifies and /// frees each payload immediately (bounded live set). Returns total bytes. fn readPass( gpa: std.mem.Allocator, io: Io, store: *logstore.LogStore, cfg: Config, expected: []u8, samples: []u64, first: u64, count: u64, ) BenchError!u64 { std.debug.assert(samples.len == count); var bytes: u64 = 0; for (0..@intCast(count)) |j| { const index = first + j; const rid: logstore.Rid = index + 1; const s0 = now(io); const got = (store.content(gpa, rid) catch |e| return mapContent(e)) orelse return error.Corrupt; samples[j] = elapsed(s0, now(io)); fillBlob(cfg.seed, index, expected); const ok = std.mem.eql(u8, got, expected); gpa.free(got); if (!ok) return error.ReadMismatch; bytes += cfg.blob; } return bytes; } // --------------------------------------------------------------------------- // open // --------------------------------------------------------------------------- /// Builds the log once, then times `reps` fresh `open`s (scan + index /// rebuild) over the same file. Reports p50/p99 open latency and scan MB/s /// (file bytes / p50 open). fn benchOpen(gpa: std.mem.Allocator, io: Io, cfg: Config, out: *Io.Writer) RunError!void { var temp = try Temp.create(io); defer temp.cleanup(io); const blob = try gpa.alloc(u8, @intCast(cfg.blob)); defer gpa.free(blob); var fs0 = storage.FileStorage.init(io, temp.file, 0); var builder = logstore.LogStore.open(gpa, fs0.storageFile(), 0) catch |e| return mapOpen(e); try buildLog(&builder, cfg, blob); const total = builder.size(); builder.deinit(gpa); const samples = try gpa.alloc(u64, @intCast(cfg.reps)); defer gpa.free(samples); for (0..@intCast(cfg.reps)) |r| { var fs = storage.FileStorage.init(io, temp.file, total); const s0 = now(io); var store = logstore.LogStore.open(gpa, fs.storageFile(), 0) catch |e| return mapOpen(e); samples[r] = elapsed(s0, now(io)); store.deinit(gpa); } std.sort.pdq(u64, samples, {}, std.sort.asc(u64)); try header(out, "open", cfg); const p50 = percentile(samples, 50); const p99 = percentile(samples, 99); try out.print("open n={d} blob={d} bytes={d} seed={d}: {d:.1} MB/s scan p50={d:.2}us p99={d:.2}us\n", .{ cfg.count, cfg.blob, total, cfg.seed, mbPerSec(total, p50), nsToUs(p50), nsToUs(p99), }); } // --------------------------------------------------------------------------- // Timing, statistics, reporting // --------------------------------------------------------------------------- fn now(io: Io) Io.Timestamp { return Io.Timestamp.now(io, .awake); } fn elapsed(t0: Io.Timestamp, t1: Io.Timestamp) u64 { const ns = t0.durationTo(t1).nanoseconds; // i96, monotonic so >= 0 return if (ns < 0) 0 else @intCast(ns); } fn sum(xs: []const u64) u64 { var total: u64 = 0; for (xs) |x| total += x; return total; } /// p-th percentile of an already-sorted slice; `len >= 1` designs the /// div-by-zero out of existence rather than asserting it away downstream. fn percentile(sorted: []const u64, p: u64) u64 { std.debug.assert(sorted.len >= 1); std.debug.assert(p <= 100); var idx: usize = @intCast(p * sorted.len / 100); if (idx >= sorted.len) idx = sorted.len - 1; return sorted[idx]; } fn mbPerSec(bytes: u64, ns: u64) f64 { if (ns == 0 or bytes == 0) return 0; const secs = @as(f64, @floatFromInt(ns)) / 1_000_000_000.0; const mib = @as(f64, @floatFromInt(bytes)) / (1024.0 * 1024.0); return mib / secs; } fn opsPerSec(ops: u64, ns: u64) f64 { if (ns == 0 or ops == 0) return 0; const secs = @as(f64, @floatFromInt(ns)) / 1_000_000_000.0; return @as(f64, @floatFromInt(ops)) / secs; } fn nsToUs(ns: u64) f64 { return @as(f64, @floatFromInt(ns)) / 1000.0; } fn header(out: *Io.Writer, cmd: []const u8, cfg: Config) RunError!void { try out.print("# {s} bench: raw frames only (zlib/delta not yet implemented) seed={d}\n", .{ cmd, cfg.seed }); } /// `ops` is the count of operations actually timed into `sorted` — the put /// count for put/cold, but working_set*reps for the warm pass — so ops/s /// stays consistent with the MB/s computed from the same `bytes`/`ns`. fn line(out: *Io.Writer, label: []const u8, cfg: Config, ops: u64, bytes: u64, ns: u64, sorted: []const u64) RunError!void { const p50 = percentile(sorted, 50); const p99 = percentile(sorted, 99); try out.print("{s} n={d} blob={d} commit_every={d} seed={d}: {d:.1} MB/s {d:.0} ops/s p50={d:.2}us p99={d:.2}us\n", .{ label, cfg.count, cfg.blob, cfg.commit_every, cfg.seed, mbPerSec(bytes, ns), opsPerSec(ops, ns), nsToUs(p50), nsToUs(p99), }); } fn appendLine(out: *Io.Writer, cfg: Config, bytes: u64, ns: u64) RunError!void { try out.print("append n={d} blob={d} seed={d}: {d:.1} MB/s {d:.0} ops/s # fsync excluded\n", .{ cfg.count, cfg.blob, cfg.seed, mbPerSec(bytes, ns), opsPerSec(cfg.count, ns), }); } /// LogStore's `OpenError`/`ContentError` fold into the closed harness set; /// `OutOfMemory` stays itself so the OOM path is never masked as `Storage`. fn mapOpen(e: logstore.OpenError) BenchError { return switch (e) { error.OutOfMemory => error.OutOfMemory, error.Storage => error.Storage, error.Corrupt => error.Corrupt, }; } fn mapContent(e: logstore.ContentError) BenchError { return switch (e) { error.OutOfMemory => error.OutOfMemory, error.Storage => error.Storage, error.Corrupt => error.Corrupt, }; } fn mapPut(e: logstore.PutError) BenchError { return switch (e) { error.OutOfMemory => error.OutOfMemory, error.Storage => error.Storage, }; } // --------------------------------------------------------------------------- // Test (Debug, wired into `zig build test`): the corpus generator is pure // and deterministic — the only genuinely testable property of a benchmark // (no RFC oracle behind measurement code). No timing loop runs under `test`. // --------------------------------------------------------------------------- test "bench corpus: one seed reproduces identical blobs; indices give distinct content hashes" { const blob_len = 128; var a: [blob_len]u8 = undefined; var b: [blob_len]u8 = undefined; // Same (seed, index) is byte-identical across calls. fillBlob(0xB0BA, 7, &a); fillBlob(0xB0BA, 7, &b); try std.testing.expectEqualSlices(u8, &a, &b); // A different seed changes the bytes (the index prefix stays, the tail // moves), so the corpus carries no hidden ambient entropy. fillBlob(0xB0BB, 7, &b); try std.testing.expect(!std.mem.eql(u8, &a, &b)); // Distinct indices yield distinct blobs, hence distinct hashes. const n = 64; var hashes: [n][hash_len]u8 = undefined; for (0..n) |i| { fillBlob(0xB0BA, @intCast(i), &a); hashes[i] = hashBlob(&a); } for (0..n) |i| { for (i + 1..n) |j| { try std.testing.expect(!std.mem.eql(u8, &hashes[i], &hashes[j])); } } } test { // The sync clone + storage diagnostic benchmarks' correctness/determinism // tests ride the same bench test binary into `zig build test` (Debug); no // timing loop runs here. _ = @import("sync_benchmark.zig"); _ = @import("storage_benchmark.zig"); _ = @import("warmread_benchmark.zig"); _ = @import("serve_benchmark.zig"); }