Artifact [ff55c6148e]

Artifact ff55c6148e961c9374ad60a756d9d997fadbc854d2a79d625235b580aefb8656:

• File src/serve_benchmark.zig — part of check-in [e17845e40d] at 2026-07-25 13:37:43 on branch trunk — serve: read the served store through a log-offset index, not a resident copy

  Priming a serve snapshot copied every artifact's container out of the log into an in-memory store and held them there for the server's lifetime. The log had already been scanned and every frame CRC-checked to build the rid table, so the copy was a second full read whose only product was resident bytes: on a 254k-artifact repository it was two thirds of the prime time and a few hundred megabytes of RSS, all to re-hold what the log already holds.

  The snapshot is now a log-backed store: an index of hash -> log location, and container bytes read from the log on demand as a round emits them, memoised only for the round and released after it. Persisted order is preserved so the clone pager still cursors correctly, the binary-digest to hex-wire-name conversion stays at its one site, and a read fault after the scan surfaces as a server storage error so a clone is never silently truncated. The old whole-store copy is retained only where it is actually needed: the pull client's holdings and the equivalence test's oracle.

  Measured, 67499-artifact repository, ReleaseSafe: a clone off the indexed serve is byte-identical to a clone off the copy-based serve (both materialise all 983 files of trunk identically), while serve peak RSS falls from 157 MB to 32 MB. The one remaining O(store) cost, the startup scan itself, is a separate change. (user: dmestas, size: 21507) [annotate] [blame] [check-ins using]

//! Serve-readiness probe (`zig build bench -- serve [--artifacts N]`).
//!
//! A run-on-demand milestone probe that pins the load-bearing bring-up order of
//! `zit serve` fixed under ticket #13: the listener is opened BEFORE the
//! O(store) prime (`cmd_sync.runServe` — `serve_mod.listen` first, then the
//! config read, then `ctx.baseSnapshot` primes the whole log, then
//! `serve_mod.serve`). A client that connects during the prime queues in the
//! accept backlog rather than being refused, so serve readiness begins at the
//! bind, not after the scan.
//!
//! That ordering CANNOT be pinned by a unit test: reverting it (priming before
//! the bind) leaves the whole suite green — the regression only manifests when
//! prime latency exceeds a client's readiness window, a wall-clock property no
//! in-process assertion sees. So this lives in the compiled-but-manual bench
//! tier (like `zig build smoke`), and defends the reorder empirically:
//!
//!   1. Synthesize a deterministic on-disk `.zit` with `--artifacts` frames,
//!      sized so priming it is a real O(store) cost (>> the connect window).
//!   2. Measure a synthetic prime IN-PROCESS over the same store: `openReadOnly`
//!      + a full content read of every frame. After #14 the server's real
//!      `baseSnapshot` is lighter — scan + index build only, containers read on
//!      demand at serve, never at prime — so this pass is an UPPER bound on the
//!      server's own prime, kept deliberately heavy so the synthesized readiness
//!      window is unmistakably large. The property the ratio proves (the listener
//!      binds BEFORE any prime) does not depend on the prime's exact cost.
//!   3. Spawn the REAL `zit serve --port <ephemeral>` against that store and
//!      measure time-to-first-successful-TCP-connect from the spawn instant, by
//!      retry-connecting in a tight loop (the `waitForListen` shape, but timed).
//!   4. Assert BOTH `prime > prime_floor` (the window genuinely existed — a
//!      trivial prime would make the ratio prove nothing) AND `connect/prime <
//!      connect_fraction` (readiness is early RELATIVE to the prime). The ratio,
//!      not an absolute ms bound, is the discriminator: cold child-spawn latency
//!      (fork+exec+runtime init+discoverRoot) alone can exceed any small
//!      absolute threshold yet is still a tiny fraction of an O(store) prime, and
//!      has nothing to do with the ordering. Fail (exit non-zero) if either
//!      breaches; the reverted prime-before-listen order opens the listener only
//!      AFTER the whole prime, so connect ≈ spawn+prime and the ratio jumps to
//!      ≈1.0, breaching the fraction by a wide margin.
//!
//! Determinism: corpus bytes derive solely from a fixed seed and the frame
//! index (same generator as logstore_benchmark). The only ambient effects are
//! the monotonic clock (`Io.Clock.awake`) and the temp store/child process,
//! all reached through the injected `std.Io`. ReleaseFast (the bench module is
//! always optimized), matching the optimization the spawned server runs under.

const std = @import("std");
const Io = std.Io;
const net = std.Io.net;
const build_options = @import("build_options");
const storage = @import("zit").storage;
const logstore = @import("zit").logstore;

/// Closed harness error set (never `anyerror`). Store faults fold in from the
/// LogStore; `BadArgs` is a rejected flag; `Spawn`/`ServerNeverBound` are the
/// child-process seam; `ProbeTooSlow`/`PrimeTooFast` are the two probe verdicts
/// (connect over threshold, prime under floor). `RunError` adds the writer's
/// own error set for reporting.
pub const Error = error{
    OutOfMemory,
    Storage,
    Corrupt,
    BadArgs,
    Spawn,
    ServerNeverBound,
    ProbeTooSlow,
    PrimeTooFast,
};
pub const RunError = Error || Io.Writer.Error;

const ns_per_ms: u64 = 1_000_000;

/// Default frame count: chosen so the prime is comfortably a few hundred ms —
/// well above `prime_floor` — on a modern machine, giving the reorder a real
/// window to defend. Overridable with `--artifacts`.
const default_artifacts: u64 = 60_000;
const min_artifacts: u64 = 1;
/// TigerStyle upper bound (matches sync_benchmark's cap); an overflow is BadArgs.
const max_artifacts: u64 = 1_000_000;

/// Per-frame blob width. Fixed (not a flag — the probe measures readiness, not
/// throughput): 4 KiB × 60k ≈ 240 MB of frames, enough scan + content work to
/// keep the prime firmly above the floor. The 8-byte index prefix in `fillBlob`
/// guarantees distinct content, hence distinct hashes.
const blob_len: usize = 4096;
const hash_len: usize = 32;
const seed: u64 = 42;
/// fsync cadence while building — bounds the number of syncs (60 for the
/// default) without leaving the durable tail torn for the read-back.
const commit_every: u64 = 1000;

/// The reorder guard, RELATIVE to prime: a ready server's connect time must be
/// a small FRACTION of its prime. Under the fixed bind-before-prime order the
/// listener is up before any O(store) work, so connect is only child-spawn
/// latency — a few percent of the prime. Under the reverted prime-before-bind
/// order the listener opens only AFTER the whole prime, so connect ≈ spawn+prime
/// and the ratio is ≈1.0. 0.5 passes the fixed order with an order of magnitude
/// of margin (observed ratios ~0.01–0.1) and fails the revert decisively. An
/// absolute ms bound is NOT usable here: cold fork+exec+runtime-init alone can
/// exceed a few hundred ms while remaining a tiny fraction of the prime.
const connect_fraction: f64 = 0.5;
/// The floor the measured prime must clear for the probe to be non-vacuous: it
/// proves the accept-backlog window the ratio relies on was real and large. A
/// trivial prime would make the ratio meaningless (any spawn latency would
/// dominate a near-zero denominator), so a prime under this floor is reported as
/// an inconclusive run, not a pass.
const prime_floor_ns: u64 = 250 * ns_per_ms;

/// Dispatched from logstore_benchmark's `run` when argv[1] == "serve". `args`
/// is the whole process argv; serve's flags begin at index 2.
pub fn run(gpa: std.mem.Allocator, io: Io, args: []const []const u8, out: *Io.Writer) RunError!void {
    const artifacts = try parseArgs(args);

    var repo = try TempRepo.create(io);
    defer repo.cleanup(io);
    try buildStore(gpa, io, repo.zitPath(), artifacts);

    // Prime first (child not yet spawned): under the FIXED order the child's own
    // prime happens after it accepts connections, so this in-process pre-read
    // never affects the measured connect time. It captures the O(store) window.
    const prime_ns = try measurePrime(gpa, io, repo.zitPath());
    // Then the real server: time-to-first-connect from the spawn instant.
    const connect_ns = try measureConnect(gpa, io, repo.dirPath());

    // Emit and flush BEFORE the verdict returns: `main` exits without flushing
    // `out` on an error, so the three numbers (and the ratio) must already be on
    // the wire.
    const ratio = ratioOf(connect_ns, prime_ns);
    try out.print(
        "# serve readiness probe (#13): listener opens BEFORE the O(store) prime\n" ++
            "serve artifacts={d} blob={d}: connect={d:.2}ms prime={d:.1}ms ratio={d:.3}" ++
            " (non-vacuity: prime>{d}ms, reorder guard: connect/prime<{d:.2})\n",
        .{
            artifacts,          blob_len,
            nsToMs(connect_ns), nsToMs(prime_ns),
            ratio,              prime_floor_ns / ns_per_ms,
            connect_fraction,
        },
    );
    try out.flush();

    // Non-vacuity first: a prime under the floor means the store was too small to
    // prove anything, so the ratio carries no signal — report that.
    if (prime_ns <= prime_floor_ns) return error.PrimeTooFast;
    // The reorder guard, RELATIVE to prime: under the fixed order connect is a
    // small fraction of prime (listener up early, clients queue in the backlog);
    // under the reverted order the listener opens only after the whole prime, so
    // connect ≈ spawn+prime and the ratio reaches ≈1.0. The fraction — not an
    // absolute ms bound — is the true discriminator (cold child-spawn latency
    // alone would false-positive an absolute threshold).
    if (ratio >= connect_fraction) return error.ProbeTooSlow;

    try out.writeAll("serve: PASS (listener ready well within the prime window)\n");
    try out.flush();
}

fn parseArgs(args: []const []const u8) Error!u64 {
    std.debug.assert(args.len >= 2);
    var artifacts: u64 = default_artifacts;
    var i: usize = 2;
    while (i < args.len) : (i += 1) {
        if (std.mem.eql(u8, args[i], "--artifacts")) {
            i += 1;
            if (i >= args.len) return error.BadArgs; // flag with no value
            artifacts = std.fmt.parseInt(u64, args[i], 0) catch return error.BadArgs;
        } else return error.BadArgs;
    }
    if (artifacts < min_artifacts or artifacts > max_artifacts) return error.BadArgs;
    return artifacts;
}

// ---------------------------------------------------------------------------
// Deterministic corpus (pure — no clock, no ambient entropy). Same generator
// as logstore_benchmark: bytes derive from (seed, index) alone.
// ---------------------------------------------------------------------------

fn fillBlob(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 repository: a throwaway `/tmp/zit-serve-bench-<nonce>/` directory holding
// one `.zit`, so a spawned `zit serve` with that cwd discovers it. Named from
// the monotonic clock so concurrent runs never collide; removed on cleanup.
// ---------------------------------------------------------------------------

const TempRepo = struct {
    dir_buf: [64]u8,
    dir_len: usize,
    zit_buf: [72]u8,
    zit_len: usize,
    chk_buf: [80]u8,
    chk_len: usize,

    fn create(io: Io) Error!TempRepo {
        var self: TempRepo = undefined;
        const nonce = std.Io.Clock.now(.awake, io).nanoseconds;
        const d = std.fmt.bufPrint(&self.dir_buf, "/tmp/zit-serve-bench-{d}", .{nonce}) catch return error.BadArgs;
        self.dir_len = d.len;
        std.Io.Dir.createDirAbsolute(io, self.dirPath(), .default_dir) catch return error.Storage;
        const z = std.fmt.bufPrint(&self.zit_buf, "{s}/.zit", .{self.dirPath()}) catch return error.BadArgs;
        self.zit_len = z.len;
        // The checkout marker `.zit-checkout` — `cli.discoverRoot` requires BOTH
        // it and `.zit` present before it will call a directory a repository
        // root. `serve` never READS it (it opens only `.zit`), so an empty marker
        // is enough to make the served store discoverable.
        const c = std.fmt.bufPrint(&self.chk_buf, "{s}/.zit-checkout", .{self.dirPath()}) catch return error.BadArgs;
        self.chk_len = c.len;
        var chk = std.Io.Dir.createFileAbsolute(io, self.checkoutPath(), .{}) catch return error.Storage;
        chk.close(io);
        return self;
    }

    fn dirPath(self: *const TempRepo) []const u8 {
        return self.dir_buf[0..self.dir_len];
    }

    fn zitPath(self: *const TempRepo) []const u8 {
        return self.zit_buf[0..self.zit_len];
    }

    fn checkoutPath(self: *const TempRepo) []const u8 {
        return self.chk_buf[0..self.chk_len];
    }

    fn cleanup(self: *TempRepo, io: Io) void {
        std.Io.Dir.deleteFileAbsolute(io, self.zitPath()) catch {};
        std.Io.Dir.deleteFileAbsolute(io, self.checkoutPath()) catch {};
        std.Io.Dir.deleteDirAbsolute(io, self.dirPath()) catch {};
    }
};

/// Write `artifacts` distinct raw frames into a fresh `.zit` and fsync. Reuses
/// the production LogStore append path (`put` hardcodes `.raw`), so the store is
/// byte-for-byte what `zit serve`'s read-only scanner opens. `hash_kind` 0 on a
/// fresh file is a don't-care (no config frame is written; `serve` falls back to
/// its placeholder project code — see `runServe`).
fn buildStore(gpa: std.mem.Allocator, io: Io, zit_path: []const u8, artifacts: u64) Error!void {
    var file = std.Io.Dir.createFileAbsolute(io, zit_path, .{ .read = true }) catch return error.Storage;
    defer file.close(io);
    var fs = storage.FileStorage.init(io, file, 0);
    var log = logstore.LogStore.open(gpa, fs.storageFile(), 0) catch |e| return mapOpen(e);
    defer log.deinit(gpa);

    var blob: [blob_len]u8 = undefined;
    const n: usize = @intCast(artifacts);
    for (0..n) |i| {
        fillBlob(@intCast(i), &blob);
        const h = hashBlob(&blob);
        _ = log.put(&h, &blob) catch |e| return mapPut(e);
        if ((i + 1) % commit_every == 0) log.commit() catch return error.Storage;
    }
    log.commit() catch return error.Storage;
}

/// A synthetic in-process O(store) prime over the same store: `openReadOnly`
/// (header validate + full-frame scan + index rebuild) then a `content()` read
/// of every frame. After #14 the server's real `ctx.baseSnapshot` is lighter —
/// scan + index build only, with container bytes read on demand at serve rather
/// than copied at prime — so this pass is an UPPER bound on the server's real
/// prime, kept deliberately heavy so the synthesized readiness window is
/// unmistakably large. What the bench proves (readiness begins at the bind, not
/// after the prime) does not depend on this number matching the real prime.
fn measurePrime(gpa: std.mem.Allocator, io: Io, zit_path: []const u8) Error!u64 {
    var file = std.Io.Dir.openFileAbsolute(io, zit_path, .{ .mode = .read_only }) catch return error.Storage;
    defer file.close(io);
    const st = file.stat(io) catch return error.Storage;

    const t0 = std.Io.Clock.now(.awake, io).nanoseconds;
    var fs = storage.FileStorage.init(io, file, st.size);
    var log = logstore.LogStore.openReadOnly(gpa, fs.storageFile()) catch |e| return mapOpen(e);
    defer log.deinit(gpa);
    const rids = log.ridsInPersistedOrder(gpa) catch return error.OutOfMemory;
    defer gpa.free(rids);
    for (rids) |rid| {
        const maybe = log.content(gpa, rid) catch |e| return mapContent(e);
        if (maybe) |bytes| gpa.free(bytes);
    }
    const t1 = std.Io.Clock.now(.awake, io).nanoseconds;
    return diffNs(t0, t1);
}

/// Spawn the real `zit serve --port <ephemeral>` against the store at `dir_path`
/// and return the elapsed nanoseconds from the spawn instant to the first
/// successful loopback TCP connect. A successful connect completes on the listen
/// backlog — before `accept`, and (with the fixed order) before the prime — so
/// this is exactly the serve-readiness latency #13 pins.
fn measureConnect(gpa: std.mem.Allocator, io: Io, dir_path: []const u8) Error!u64 {
    const port = freshLoopbackPort(io) catch return error.ServerNeverBound;
    const addr = net.IpAddress.parseIp4("127.0.0.1", port) catch return error.ServerNeverBound;

    // Parent-side prep is NOT part of serve readiness — build argv/env, then
    // start the clock immediately before the OS spawn.
    var env = std.process.Environ.Map.init(gpa);
    defer env.deinit();
    env.put("TZ", "UTC") catch return error.Spawn;
    env.put("HOME", "/zit-serve-bench-isolated-home-does-not-exist") catch return error.Spawn;
    env.put("PATH", "/usr/bin:/bin") catch return error.Spawn;

    const cwd_abs = std.process.currentPathAlloc(io, gpa) catch return error.Spawn;
    defer gpa.free(cwd_abs);
    const abs_exe = std.fs.path.resolve(gpa, &.{ cwd_abs, build_options.zit_exe }) catch return error.OutOfMemory;
    defer gpa.free(abs_exe);
    const port_str = std.fmt.allocPrint(gpa, "{d}", .{port}) catch return error.OutOfMemory;
    defer gpa.free(port_str);

    const t0 = std.Io.Clock.now(.awake, io).nanoseconds;
    var child = std.process.spawn(io, .{
        .argv = &.{ abs_exe, "serve", "--port", port_str },
        .cwd = .{ .path = dir_path },
        .environ_map = &env,
        .stdout = .ignore,
        .stderr = .ignore,
    }) catch return error.Spawn;
    defer child.kill(io);

    // Retry-connect until the child binds. A short sleep between attempts YIELDS
    // the core: a tight busy-loop pins one CPU at 100% and starves the very child
    // we are timing, inflating the measured connect time by seconds under load.
    // The 0.5 ms poll keeps resolution two orders of magnitude finer than the
    // 150 ms threshold while letting the child make progress. The deadline is the
    // runaway backstop if the server never binds (never hit by a live serve).
    const poll_ns: u64 = 500_000; // 0.5 ms
    const deadline_ns: i96 = 30_000_000_000; // 30 s
    while (true) {
        if (addr.connect(io, .{ .mode = .stream })) |stream| {
            const t1 = std.Io.Clock.now(.awake, io).nanoseconds;
            stream.close(io);
            return diffNs(t0, t1);
        } else |_| {}
        if (std.Io.Clock.now(.awake, io).nanoseconds - t0 > deadline_ns) return error.ServerNeverBound;
        io.sleep(.{ .nanoseconds = poll_ns }, .awake) catch {};
    }
}

/// Reserve a kernel-assigned ephemeral loopback port, then release it for the
/// child to bind. The close→child-bind race is unavoidable (a child server
/// cannot inherit the listener) and harmless: the retry-connect loop tolerates
/// the brief pre-bind window. Same pattern as smoke/e2e's `freshLoopbackPort`.
fn freshLoopbackPort(io: Io) !u16 {
    const addr = try net.IpAddress.parseIp4("127.0.0.1", 0);
    var server = try addr.listen(io, .{});
    const port = server.socket.address.getPort();
    server.deinit(io);
    if (port == 0) return error.NoLoopbackPort;
    return port;
}

// ---------------------------------------------------------------------------
// Timing + error mapping
// ---------------------------------------------------------------------------

/// Monotonic (`.awake`) so a negative delta is impossible; clamp to 0 anyway
/// rather than assert, so a clock quirk degrades a number, never crashes a probe.
fn diffNs(t0: i96, t1: i96) u64 {
    const d = t1 - t0;
    return if (d < 0) 0 else @intCast(d);
}

fn nsToMs(ns: u64) f64 {
    return @as(f64, @floatFromInt(ns)) / 1_000_000.0;
}

/// connect/prime as a fraction. A zero prime (guarded separately by the floor)
/// yields +inf rather than a NaN/crash, so the ratio still prints and the floor
/// check fires the inconclusive verdict.
fn ratioOf(connect_ns: u64, prime_ns: u64) f64 {
    if (prime_ns == 0) return std.math.inf(f64);
    return @as(f64, @floatFromInt(connect_ns)) / @as(f64, @floatFromInt(prime_ns));
}

fn mapOpen(e: logstore.OpenError) Error {
    return switch (e) {
        error.OutOfMemory => error.OutOfMemory,
        error.Storage => error.Storage,
        error.Corrupt => error.Corrupt,
    };
}

fn mapContent(e: logstore.ContentError) Error {
    return switch (e) {
        error.OutOfMemory => error.OutOfMemory,
        error.Storage => error.Storage,
        error.Corrupt => error.Corrupt,
    };
}

fn mapPut(e: logstore.PutError) Error {
    return switch (e) {
        error.OutOfMemory => error.OutOfMemory,
        error.Storage => error.Storage,
    };
}

// ---------------------------------------------------------------------------
// Tests (Debug, wired into `zig build test` via logstore_benchmark's test
// block): the corpus generator is pure and deterministic, and the two verdict
// thresholds must stay ordered so the probe's PASS window is real. No timing
// loop, no child process, and no filesystem touch run under `test`.
// ---------------------------------------------------------------------------

test "serve bench corpus: one index reproduces identical blobs; distinct indices give distinct hashes" {
    var a: [blob_len]u8 = undefined;
    var b: [blob_len]u8 = undefined;

    fillBlob(7, &a);
    fillBlob(7, &b);
    try std.testing.expectEqualSlices(u8, &a, &b);

    fillBlob(8, &b);
    try std.testing.expect(!std.mem.eql(u8, &a, &b));
    try std.testing.expect(!std.mem.eql(u8, &hashBlob(&a), &hashBlob(&b)));
}

test "serve bench guard: the connect/prime ratio passes the fixed order and fails the revert" {
    // The fraction must leave real room on both sides — not a coincidental bound.
    try std.testing.expect(connect_fraction > 0.0 and connect_fraction < 1.0);

    // Fixed bind-before-prime order: connect is only child-spawn latency, a small
    // fraction of an O(store) prime — comfortably under the fraction even when the
    // spawn is unusually slow (576 ms spawn against a 6.2 s prime -> ~0.093).
    const fixed_ratio = ratioOf(576 * ns_per_ms, 6225 * ns_per_ms);
    try std.testing.expect(fixed_ratio < connect_fraction);

    // Reverted prime-before-bind order: the listener opens only AFTER the whole
    // prime, so connect ≈ spawn + prime and the ratio exceeds 1.0 — well past the
    // fraction, so the guard fires.
    const reverted_ratio = ratioOf((6225 + 60) * ns_per_ms, 6225 * ns_per_ms);
    try std.testing.expect(reverted_ratio >= connect_fraction);
    try std.testing.expect(reverted_ratio > 1.0);
}