Artifact [6c3e0ba2cb]

Artifact 6c3e0ba2cb9538f7cdc9ccf69796179ec5ef9cc61fba4aa4555c834ba955e1b4:

• File src/serve_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: 21159) [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 the prime IN-PROCESS over the same store — exactly what the
//!      server pays at `baseSnapshot`: `openReadOnly` + a full content read of
//!      every frame (the `readServedStore`/`loadContentStore` path). This is a
//!      lower bound on the server's own prime (it omits the MemStore inserts),
//!      which is the safe direction for proving the window is real.
//!   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;
}

/// The server's startup prime, measured in-process over the same store: the
/// exact O(store) work `runServe` does at `ctx.baseSnapshot` — `openReadOnly`
/// (header validate + full-frame scan + index rebuild) then a `content()` read
/// of every frame (`readServedStore`/`loadContentStore`). It omits the MemStore
/// inserts, so it is a LOWER bound on the server's real prime — the safe
/// direction for proving the readiness window is genuinely large.
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);
}