[Japabu]

Built on #1228, which has landed; the diff against main is this branch's own. Status: round 3 (9356faa) answers B1′ on round 2 (9108a46), which answered B1–B3; the head 79b15d3 adds only the owed-on-metal record. Host checks done; guest rows green at 9108a46 and queued at the head; metal is no landing condition while the benches are down, and what is owed on metal is listed below. The speed-up is not yet measured on the T14, and on the AMD bench by one boot per arm.

Problem

• Cost. The spawn-performance work measured, on both benches, that each spawn's two log lines (~157 bytes each) cost 370–475 µs of CPU across /log's file server, nvme and logkeeper on the T14, and 1.14–1.23 ms on the AMD bench, one spawn at a time (about 40% of the child's own CPU there). The cause: logkeeper wrote and synced every round. That the cost is fixed per write is an inference: it falls per line as concurrency rises.
• Waits (issues/the-console-waits-on-logkeepers-file-writes.md). The loop made every /log call itself. A /log server that took a call and never answered left every console channel and reader silent, with no bound.
• Readers (issues/logkeeper-hears-a-reader-leave-only-at-its-next-write.md). A caught-up reader learned that its reader had gone only at the next write.

Resulting behaviour

• The file is a consumer of the replay on its own thread (system/logkeeper/src/file.rs), as the readers and carriers already were.

  • The thread opens the volume (the separate opener thread goes), writes, syncs, rotates and asks a refusing volume again.
  • The loop appends each round to the replay and tells the thread. It makes no call on /log: its Log holds no Volume, and its only calls into the file are a send on an unbounded channel and the stop's two waits, each bounded.
  • Rounds the thread has not taken are one message: growth is an atomic beside the channel, and a Grew is sent only when none is unread. A thread held in a /log call has at most that one queued, rather than one a round for as long as the call lasts.

• Batches. A batch is written and synced when one of these holds:

  • 64 KiB of text is owed (BATCH_BYTES);
  • the oldest owed line has waited 1 s (BATCH_AGE);
  • a round holds a line at Error or above: a program's panic report is its stderr, and a kernel fault is an Alert;
  • the stop's flush asks for it, and a refused stop's held lines are written at once.

  A batch's age starts only for bytes the file is owed: a round a write has already taken, with the round before it, starts no wait. A catch-up that spends its 1 MiB budget on the replay's last line is caught up and synced, so that end leaves no age behind either.

  Both bounds are justified at their site.

• Stop. The flush and the stop mark are requests the loop waits on for at most STOP_FILE, three quarters of the supervisor's FLUSH_MS. If the file does not answer, the loop gives up, says so and goes on.

  • From the flush until a refused stop, the file thread makes no call except the mark.
  • It writes the mark only over a file the flush reached, and begins it only before the mark's deadline; a mark begun in time can land after it, which the next point covers.
  • The file thread keeps the record of the mark: any mark it asked the volume for, whatever the volume answered and whether or not the loop still waited, is taken back at a refused stop. The loop keeps no copy. The mark goes in the directory of the file it vouches for.

• Readers. A caught-up reader waits on two events: a bell the replay's growth rings, and its pipe's other end going. A reader that leaves while the log is quiet gives back its thread and its MAX_READERS slot at once.

• spawn_cost prints the machine's busy CPU a spawn, from the sysinfo header every process may read, beside its latency. The log's cost runs on other CPUs, off the spawn's path, so latency cannot show it; this figure is what the A/B below reads. It is the stack's first commit, so the A image carries it too.

What a crash can cost, against #1196 and the manual

• A machine that dies without a stop (kernel panic, deadline reset, power loss) loses from /log at most the unwritten batch.
  • On a volume that answers, that is at most 1 s of lines below Error. Lines at Error or above are written at once.
  • The console is not batched: it was handed every lost line as it was read. The kernel's own panic report goes to the console and panel, as before.
  • Before this change the loss was at most one round (10–250 ms).
• A stop. The flush writes the whole replay before FLUSHED, as before.
  • The stop mark is still the last write before the drivers stop, which is Memory overwrite on every boot; the black box goes, and a clean stop proves an image #1196's claim. The file thread is serial, so the mark follows the flush's writes. While the stop stands, the replay does not grow (later lines are held back as before) and the thread makes no other call.
  • A flush that begins after its deadline leaves finished false, so the mark is withheld, as it was before for a volume that was not open. A flush that begins in time and is cut short by the deadline says the shortfall in the file and syncs it, and the mark goes over that file, as on main.
  • A mark that lands after the loop stopped waiting is still the file thread's record, so a refused stop takes it back and a later death of the boot is not read as clean.
• The manual. docs/src/architecture/diagnostics.md now says the file is written in batches and what a crash costs it while the volume keeps pace; the boot page's account of the mark is unchanged and still true. The ABI's severity note no longer restates logkeeper's write policy, which is file::urgent's.

Decisions

• The issue's own exit shape. The file became a replay consumer rather than gaining a timeout around each call: a wedged /log holds only its own thread.
• Error, not only Alert, writes at once. A Rust program's panic message is stderr, which is Error. A program that writes heavily to stderr is therefore synced every round, as before this change. Spawn lines are Info.
• No separate "explicit sync" request. The brief named one. No program asks for one: the supervisor's FLUSH is the explicit sync and writes at once, as do Error/Alert lines and a refused stop's held lines. A protocol message can be added when a caller needs one.
• policy::Step is deleted with the per-round write it named.
• degraded is timed over a whole write (review S4, declined): that includes a catch-up of up to 1 MiB and a rotation, and LOG_WRITE_BUDGET is 5 s, many times what a stick takes for a mebibyte (an estimate, not measured here).
• Durability. Readers are now served a round as it is read, before the file has it. Nothing relied on the earlier "served only once on the stick" ordering; the guest helper's header that claimed it is corrected.

Checks

All on a macOS arm64 host unless named. Under the owner's testing policy the host checks are logkeeper's own; the merge queue runs the full host check.

• cargo test --manifest-path system/logkeeper/Cargo.toml at 9108a46: exit 0, 33 passed (b-test.log). New: a_batch_falls_due_at_its_size_its_age_or_an_urgent_line, the_file_takes_the_replay_a_batch_at_a_time, nothing_reaches_the_file_between_the_stops_flush_and_its_refusal, rounds_the_file_has_not_taken_are_one_ask, a_growth_already_written_starts_no_wait (B1), a_refused_stop_takes_back_the_mark_it_asked_for (B2).
• cargo test --manifest-path system/logkeeper/Cargo.toml at 9356faa: exit 0, 34 passed (r3-test.log). New: store::tests::a_budget_spent_on_the_replays_last_line_is_caught_up_and_synced (B1′): four lines in the replay, a budget of exactly their bytes; the catch-up answers caught up and the file is synced. Its control, the budget's return put back before the replay is asked, fails it at "the file has every byte" (exit 101; r3-b1p-control.log, patch). Clippy at 9356faa: the same four findings on main, none in the change (r3-clippy.log).
• Negative controls, each failing as intended (exit 101): at 9108a46, owe without its early return, which is the old took_growth and resume (fails a_growth_already_written_starts_no_wait: b1-control.log, patch), and resume that does not take the mark back (fails a_refused_stop_takes_back_the_mark_it_asked_for: b2-control.log, patch); File::grew asking at every round, 100 asks where 1 is owed, at ab336eb (coalesce-control.log, patch); at a7ed602, the batch policy without its bounds (batch-control-1.log) and due() without the stop guard (batch-control-2.log). The code those two controls cut is unchanged since a7ed602.
• cargo clippy --manifest-path system/logkeeper/Cargo.toml --all-targets with the workspace's adopted lints at 9108a46: no finding in this change (b-clippy.log). The four left are in code this branch does not touch and are on main as they are here. No gate lints a guest program (issues/userland-programs-are-never-linted.md).
• Not run separately: lib/logstream and sdk/abi, whose edits are doc comments with no code block.
• The checks ran on the working tree whose diff was then committed whole: 9108a46 (git diff hash a7f24befabea in each round-2 log's header and of the commit) and 9356faa (a915dacfe05b; first pushed as 03ce0c8, whose message was then reworded with the tree unchanged).
• Guest, x86-64 QEMU (the rows' declared target), a_clean_stop_proves_its_image the_log_lands_on_the_boot_stick: the stop mark through the file thread, and the file under a load through the stop's flush on usbd's disk.
  • at a7ed602 (batching before the coalescing): green, run 43041114433 (guest-43041114433.log).
  • at ab336eb: green, run 43051944401 (guest-43051944401.log). The mark proved the image on the next loader pass; the stick held 2,462,470 bytes of the boot's log in 6 files.
  • at 9108a46: green, run 43067018392 (guest-43067018392.log).
  • at 79b15d3, the head: run 43092231506, queued. Its code is 9356faa's, whose B1′ commit changes Volume::catch_up's end at its budget, so 43067018392 is not at a code-identical head; added here when it ends.
• No aarch64 row: the change touches no AArch64 code and no shared code beneath it.
• Metal, run before the benches went down. A = fd5d262 (logkeeper: the UART's carrier starts within a bound, whatever the rounds have read #1228 and the spawn_cost figure, no batching), B = ab336eb. Every one of these boots ends with a stop, and its verdict refuses a boot with no stop mark or whose log lacks the supervisor's stop line.
  • AMD bench, run 16:53–16:59Z, one boot per arm: A, B and metalcase B passed, and spawn_cost (A, B) and machine_reboot (B) pass the harness's judge (judge-a-amd.log, judge-b-amd.log, lines in amd-ab-extract.txt).
    • spawn_cost: A min 224 µs, median 288 µs, the machine busy 430 µs a spawn; B min 228 µs, median 276 µs, busy 360 µs a spawn. Latency did not move beyond the two runs' spread.
    • The busy CPU fell 70 µs a spawn, 3.5 ms over the loop, not the 1.1–1.2 ms a spawn the spawn-performance figures led us to expect. The loop's 51 spawns ran in 16 ms, inside one or two of logkeeper's 10 ms rounds, and before batching the cost is one write and sync per round with lines in it, not per spawn. Whether the 3.5 ms is one write and sync or two of half that, one or two rounds cannot tell; the spawn-performance table gives about 3.5 ms a write and sync on this bench (inference: about 290 ms of /log server, nvme and logkeeper CPU over the roughly 83 rounds of an 830 ms build at j1). On that figure the saving is about 3.5 ms of CPU per busy 10 ms round, down to a write a second or a 64 KiB batch; while the log is busy every round, that projects to about a third of one CPU (a projection, not measured). spawn_cost, which packs its spawns into a round or two, shows it once.
    • B's logs hold no "had not answered the stop's flush", no "stop mark was asked … after its time", no "answers but slowly". metalcase B: test_rs_ps2server_hold exited 0, so the served-log reader got its line through the new wait; no reader was refused.
  • AMD bench, machine_reboot at 9108a46: passed, with test_rs_ps2server_hold exit 0, the reset-register line, and none of the stop or slowness lines (amd-machine-reboot-9108a464a.txt).
• Owed on metal (recorded in issues/redesign-the-log-subsystem.md, to be run against main once a bench returns):
  • machine_reboot on the T14: main passes the boot verdict with the stop mark and the supervisor's stop line in the file, machine_reboot's reset-register line, and test_rs_ps2server_hold exit 0, with no "had not answered the stop's flush", "stop mark was asked … after its time", "answers but slowly" or "refusing reader" line.
  • spawn_cost's A/B on the T14, main before this PR against main after it, back to back: "the machine busy … a spawn" lower after, by about one write and sync per logkeeper round the loop spans; min and median no worse than the two runs' spread; both boots passing with the stop mark.

Evidence: ToyOSOrg/evidence pr-1232: the guest run at 9108a46 and the AMD machine_reboot at 36ba2576; round 3 at 8886efce (its message names a wrong ToyOS hash; 5f48598d corrects it to 03ce0c8, and 247ce08f records that 03ce0c8 is now 9356faa, the same tree), round 2 at f2b0acee, each linked above per check; earlier rounds' files are on the same branch.

Risks

• Deadline-ended boots. A boot its own deadline ends (no stop) can miss up to 1 s of its last lines below Error from the file. The one metal row of that kind (the_disk_survives_a_reset_under_load) needs a mebibyte of its load's lines on the disk, which batches of 64 KiB reach; not run here.
• Reader leave. The leave wake uses the kernel's pipe OTHER_END_GONE and the event bell. Host tests cannot reach either; the metal machine_reboot boot runs a reader, and no row asserts a slot coming back.
• The A/B's measure. spawn_cost's figure counts the machine's busy CPU over its 50 repetitions, which span a round or two of logkeeper's, so it shows the per-round write once rather than per spawn. A paced variant, a spawn a round, would show the per-round cost directly; not built here.
• Rebuilds. The sdk/abi comment edit rebuilds the sysroot and republishes toyos-abi.

🤖 Generated with Claude Code

[Japabu]

Review of #1232 at ab336eb (stacked on #1228)

Architecture

The file becomes the replay's third consumer, on its own thread. That is the exit the issue record itself proposed, and the ownership is right:

• The volume, its retry and its degraded state now live with the only code that calls /log.
• The loop keeps the rings, the replay and the stop protocol.
• The opener thread, policy::Step and the loop's write path go away.

The reader wake replaces the condvar with one bell per reader, because a reader must also wait on its pipe's other end leaving, and a condvar cannot. The kernel already provides that primitive for pipe ends, and test_rs_pipe_other_end_gone covers it.

Size: logkeeper production grows by about 190 lines (file.rs about +378, main.rs −240, serve.rs +70, policy.rs −19). Tests grow by about 100 lines. Two records close.

Durability under crash

Acceptable. On main, the manual's logging page already said the keeper "syncs on an alert or an interval". So losing lines up to an interval on a death without a stop was already within the requirement.

• This PR makes Error as well as Alert durable at once, and sets the interval to 1 s. That meets the page.
• The kernel's own panic report still goes to the console and panel.
• The one metal row that reads a deadline-ended boot's file (the_disk_survives_a_reset_under_load) needs 1 MiB of load lines. 64 KiB batches reach that.
• The new manual sentence states the bound without its condition; see S1.

The stop mark under batching

The design holds:

• The file thread is serial.
• stopped makes due and next_due refuse every batch from Finish until Resume.
• The replay does not grow during a stop.
• A Finish that begins after its by leaves finished false.
• A Mark that arrives after its by refuses.

So the mark follows the flush's sync and is the last write, except for B2 below.

PR description (for the orchestrator to correct): "A flush the file did not finish in time leaves finished false" is true only for a flush that began after its deadline. A flush that started in time but was cut short by the deadline leaves finished = v.is_open(), which is true. The mark then goes over the file and its shortfall line, as it did on main.

Findings

BLOCKER B1 — system/logkeeper/src/file.rs:220-223, 236-250: the file thread busy-spins on a quiet log.

• took_growth sets owed_since whether or not anything is still owed.
• A round appended while write() is in its catch-up gets written by that catch-up, because catch_up keeps reading owed() until Nothing. But that round's Grew stays queued: it was sent because the previous take had cleared TOLD.
• After the write resets owed_since (line 275), the thread takes the stale Grew and sets owed_since = now while hub.end() == through.
• due() is then false, because batch_due needs owed > 0. But next_due() returns since + BATCH_AGE. Once that instant passes, recv_timeout(0) returns at once, due stays false, and the loop spins until the next line arrives.
• This is the ordinary end of a busy period, when the log goes quiet right after a burst. The thread then holds a CPU at 100% for the whole quiet stretch.
• resume() (line 373) can create the same state when nothing is owed.
• Fix: do not keep owed_since (or urgent) while nothing is owed. Clear both when hub.end() == v.through(), or set them in took_growth only when something is owed.
• Test: write everything, call took_growth(), and assert next_due() is None. The current code is the negative control.

BLOCKER B2 — system/logkeeper/src/main.rs:257-261, 646, 673; file.rs:79, 146, 368-370: the record of whether the mark was written lives in two places, and they can disagree.

• The loop records marked from File::mark, which becomes None, and so false, when its recv_timeout expires.
• The file thread checks by only before calling store::mark_stopped(). That call (a create and a sync on /log) can finish after the loop has given up.
• A refused stop then sends Resume { marked: false }. The mark stays on the volume while the machine runs on.
• If this boot later dies uncleanly, the next loader pass finds the mark, counts the boot as clean and raises the anti-rollback floor.
• On main the loop wrote the mark itself, so RESUME always acted on the truth. The loop's line "the next boot will not count this one as clean" can also be false now.
• Fix, which also simplifies: the Writer records the mark it wrote and, on Resume, unmarks from that record. Delete Stopping::marked and Ask::Resume's field.

BLOCKER B3 — system/logkeeper/src/serve.rs:115-116: Hub::append's doc says "The lines the file has just taken, for every reader". That is now false: the file takes them from the replay after the append. The PR itself says readers are served a round before the file has it. Rewrite the doc to match.

SUGGESTION (optional):

• S1 docs/src/architecture/diagnostics.md:26-27: "loses at most that second of its file" holds only for a volume that keeps pace. A volume that is slow (up to LOG_WRITE_BUDGET, 5 s a batch, before it counts as degraded), refusing or wedged loses more. file.rs's header already adds "on a volume that answers"; add the same condition to the manual.
• S2 main.rs:543: the local file: String sits beside the module path file::urgent (lines 552, 560) and the field self.file (line 594). Rename the local, for example to text.
• S3 main.rs:132-135: the doc says POLL_QUICK/POLL_SLOW set "the latency of a program's line to the file and the console". The file's latency is now the batch's.
• S4 file.rs:277-288: degraded is now timed over a whole write(). That includes a catch-up of up to 1 MiB plus a rotation's sync and retention sweep; main timed only one round's write and sync. The first catch-up after a late open can report "answers but slowly" on a healthy stick.
• S5 sdk/abi/src/log.rs:67-68: the ABI's severity doc restates logkeeper's sync policy. Dropping that clause leaves the policy in one place (file::urgent).

The reader wake

Correct on inspection:

• The waker is registered before the thread first reads.
• The bell is taken before the thread parks.
• GONE is armed at every wait, including in the write path. A reader leaving mid-write now ends at once instead of after STALLED.
• A departed reader's waker is dropped at the next append, when ring answers Hungup.
• test_rs_pipe_other_end_gone holds the kernel side, including a read end that sits unreceived in a connection's queue and one held by a child.
• Logkeeper's own path from GONE to readers.fetch_sub is three direct lines.

I'm not asking for a row that asserts a slot coming back. To tell the new code from the old, it needs a quiet log, which a QEMU boot does not reliably give.

Note: no QEMU row reads the served log; all of its readers are metal-only jobs. So the new PipeSink's ordinary serving path runs only on the metal boots. machine_reboot will show that readers are still served, not that slots come back.

The coalescing test

It is a good test:

• 100 grew calls with one urgent among them leave one ask; the urgent flag is kept; a new ask follows the take.
• The || true control fails 100 vs 1 (exit 101), so the test catches the defect it targets.
• The interleaving of take and grow is a two-operation atomic protocol that holds on inspection: the growth is appended before grew, so a grow that finds TOLD set is covered by the pending ask's take.
• It does not cover B1's stale ask.

Evidence

• Host. 31 tests pass at ab336eb, exit 0. The two controls from a7ed602 still apply: git diff a7ed60211 ab336ebb3 leaves batch_due and due() unchanged.
• Guest. Run 43051944401 checked out ab336eb, and both rows passed.
  • The clean-stop row shows the mark goes through the file thread.
  • The stick row shows the flush under load: 2.46 MB in 6 files.

What each metal readback must show (queued at ab336eb)

• testcases A and B, each bench, same session:
  • test_rs_spawn_cost passed, with its line "… the machine busy Z us a spawn".
  • B's Z is below A's by about the measured log cost: ~0.37–0.48 ms on the T14, ~1.1–1.2 ms on the AMD bench.
  • min and median are no worse than the spread between the two runs. If Z does not drop, investigate it; that alone does not reject the design.
  • Both boots pass their verdict: Boot: complete, the supervisor's stop line, and the stop mark.
  • B's log contains none of "had not answered the stop's flush", "stop mark was asked … after its time" or "answers but slowly".
• metalcase B, each bench:
  • machine_reboot passes with the stop mark.
  • test_rs_ps2server_hold passed, meaning a served-log reader got its line through the new wait.
  • No "refusing reader" line.

B1 and B2 change only the idle wait and the stop mark's bookkeeping, not the per-round write path. If the fix diff confirms that, the testcases A/B readbacks can stand for the cost measurement. machine_reboot should run again at the fixed head, because the mark's path changes.

SEND BACK (B1, B2, B3)

[Japabu]

Round 2 at 9108a46 (one commit on ab336eb):

• B1 — growth and a refused stop go through owe, which starts the batch's age only where the replay holds bytes past the file. a_growth_already_written_starts_no_wait writes a round appended during the write, takes its stale ask, and asserts next_due() is None and nothing is urgent; then a refused stop that held nothing. The old behaviour (owe without its early return) fails it.
• B2 — the Writer records any mark it asked the volume for (marked), whatever the volume answered and whether the loop still waited, and takes it back at Resume. Stopping::marked, Ask::Resume's field and File::mark's Option<bool> are gone; the loop's timeout line no longer says the next boot will not count this one clean. The mark is now Volume::mark_stopped, in the volume's own directory (the same /log in production), which is what lets a_refused_stop_takes_back_the_mark_it_asked_for run on the host. A resume that does not unmark fails it.
• B3 — Hub::append's header rewritten.
• Suggestions: S1, S2 (rendered), S3, S5 taken; S4 declined in the body (5 s against a mebibyte).
• PR text: the flush-in-time claim corrected (cut short by its deadline: shortfall said, mark over it, as on main).

Checks at 9108a46: 33 tests pass; both controls exit 101; clippy has no finding in the change. Guest rows dispatched (43067018392).

Metal: the AMD A/B is judged (all pass), but busy CPU fell 70 µs a spawn (430 → 360), not 1.1–1.2 ms: the 50 spawns fit in one or two 10 ms rounds, and the old cost is one write and sync per round with lines in it (~3.5 ms on this bench, which is what the drop is). Details in the body's Checks. machine_reboot at 9108a46 is staged for both benches.

[Japabu]

Re-review of #1232 at 9108a46 (round 2)

Architecture

The stop mark's record now lives with the only code that calls /log, which is the simplification round 1 asked for.

• Stopping::marked, Ask::Resume's field and File::mark's Option<bool> are deleted.
• The loop can no longer pass a stale belief about the mark, because no type carries one.
• mark_stopped and unmark_stopped on Volume belong there: the mark sits in the volume's directory, and the test becomes hermetic.
• This round is +141/−77 lines, two of them new tests.

Previous blockers

• B2: resolved.
  • Recording. Writer::mark (file.rs:370-383) sets marked after the finished check and the deadline check, and before the call. A mark whose create or sync fails, or lands after the loop's recv_timeout, is therefore still recorded.
  • Unmarking. resume (387-396) takes the mark back from that record. The channel is FIFO and the thread is serial, so a Resume always follows the Mark it undoes.
  • The expect at 389 holds. marked needs finished, which needs a volume. Between Finish and Resume nothing sets volume = None: only write() does, and due() is false while stopped.
  • Where the mark lands: unchanged.
    • Production builds the volume only as Volume::open(DIR, …) (file.rs:159), which stores dir as given (store.rs:231). Rotation changes part, never dir.
    • So stopped_path() is /log/stopped, the same string as main's format!("{DIR}/{STOPPED}").
    • Durability is the same File::create(..)?.sync_all().
  • Anti-rollback: unaffected.
    • The loader opens and deletes stopped at the log partition's root, and credits an image only when the mark and a record are both present (loader/src/proof.rs:48-66).
    • build/bootlog.rs:135 reads the same name.
    • Neither file changed. The mark now exists under stricter conditions than before, because any refused stop takes it back.
  • Test. a_refused_stop_takes_back_the_mark_it_asked_for, with its control (the unmark disabled), fails as claimed.
• B3: resolved (serve.rs:115-117).
• B1: not fully resolved. See B1′ below. The paths it named are fixed: a stale Grew after a catch-up, and a refused stop that held nothing. a_growth_already_written_starts_no_wait and its control establish both.

Suggestions

• S1, S2, S3 and S5 were taken as described.
• S4 decline: accepted.
  • LOG_WRITE_BUDGET's doc already defines the bound as a batch time (policy.rs:3).
  • A false positive costs only a warning and a published Degraded until the next write within budget. Nothing is lost.
  • B's AMD boots logged no "answers but slowly".

Findings

BLOCKER B1′ — system/logkeeper/src/file.rs:282-293 with store.rs:352-353: if a write's catch-up spends its budget on the replay's last line, the batch's age stays set with nothing owed, and the file thread spins.

• The mechanism.
  • catch_up checks written >= budget at the top of its loop and returns Ok(false) without asking the replay again.
  • So in a call where the line that reaches MAX_LOG_BYTES is also the replay's last, it returns "not caught up" with through == end, and the current part unsynced.
  • write() clears owed_since only when caught, so the old instant stays.
• The spin.
  • due() is false because owed == 0.
  • next_due() is since + BATCH_AGE, which a write that large has already passed, so recv_timeout(0) returns at once, round after round, until the next line arrives.
  • That is round 1's spin. Meanwhile the part's tail stays unsynced, outside the 1 s bound the manual now states.
• Reachability.
  • It needs the file at least 1 MiB behind: a refused, late or slow volume, with the 16 MiB replay holding the rest.
  • Then the catch-up's last write() lands here when the replay ends within the line that crosses the budget.
  • That is rare, but once in it the thread stays there, and on a quiet machine it does not end.
• The claim. The commit says "the file is now owed a batch only where the replay holds bytes past it". This path still breaks that.
• Fix. For example, have catch_up ask the replay before it returns on its budget: on Nothing it syncs and answers Ok(true). The existing caught arm then clears the age, and the tail is made durable.
• Cheapest test. catch_up takes budget as a parameter, so a store test with a small budget and a replay that ends exactly on it can assert Ok(true) and a durable file. The current code is the negative control.

BLOCKER B4 — the round's evidence is not published.

• Every round-2 link in the PR resolves to nothing: b-test.log, b1-control.{log,patch}, b2-control.{log,patch}, b-clippy.log, judge-a-amd.log, judge-b-amd.log and amd-ab-extract.txt.
• Evidence commit 155007b0 adds only request-r2.txt, and pr-1232 has nothing after it.
• I read the implementer's local copies, and they show what the PR says:
  • 33 tests passed;
  • each control exits 101 on its own test;
  • the tested diff hash a7f24befabea equals git diff ab336ebb3 9108a464a | shasum;
  • both judges exit 0, with A PASS spawn_cost and B PASS spawn_cost, PASS machine_reboot.
• Publish them, so the claims can be checked by anyone other than this machine.

The AMD A/B explanation

It holds from the code.

• A (fd5d262) writes and syncs in the loop at every round with lines (to_volume(.., sync)). Rounds come every POLL_QUICK, 10 ms, while the rings have lines.
• B holds Info lines for BATCH_AGE, 1 s, or 64 KiB. These spawns' lines total about 16 KB (51 × 2 × ~157 B), so B writes them about 1 s later, outside the window spawn_cost measures. A's last round, which reads the final spawns' lines, also writes after the window.
• So the drop is A's writes at rounds inside the window.
• "51 spawns in 16 ms" is the log's first spawn to last exit: 14.727 → 14.743 for A, 14.706 → 14.722 for B.
• The 3.5 ms per write comes from the spawn-performance j1 build: /log's file server, nvme and logkeeper used about 290–316 ms over an 823–836 ms build, about 83 rounds. That attribution is itself an inference, and the PR labels it as one.

It is honest about the miss. It says plainly that the drop was 70 µs, not the expected 1.1–1.2 ms.

SUGGESTION, for the body:

• Say it is one boot per arm, with no spread for the busy figure.
• "One or two rounds" means 3.5 ms cannot tell one write of about 3.5 ms from two of about 1.75 ms. The match with the table is consistency, not confirmation.
• "So the saving is about 3.5 ms … a third of one CPU" is a projection from that inference, and should be labelled as one.

PR text (for the orchestrator)

"It writes the mark … only before the mark's deadline" should say it begins the mark only before its deadline. The next bullet already says the mark can land after the loop stops waiting.

LAND-pending, once B1′ and B4 are answered

• B1′'s fix: the new host test and its control, plus logkeeper's tests and clippy. A fix confined to the end condition of a budget-bounded catch-up does not invalidate the runs below at 9108a46.
• Guest 43067018392 at 9108a46 (still queued) must be green on both rows:
  • a_clean_stop_proves_its_image: the mark written through Volume, proven by the next loader pass;
  • the_log_lands_on_the_boot_stick.
• machine_reboot at 9108a46, both benches:
  • passes its verdict, with the stop mark and the supervisor's stop line;
  • the next pass says "Proof: … stopped cleanly";
  • none of "had not answered the stop mark", "after its time", "would not take the stop mark" or "answers but slowly".
• T14 testcases A/B:
  • both boots pass their verdict, and spawn_cost prints its busy line in each;
  • B is free of those stop lines.
  • A busy drop is not required. B's figure above A's by more than about one T14 write is a reason to investigate.

SEND BACK (B1′, B4)

[Japabu]

Round 3 at 9356faa (one commit on 9108a46; first pushed as 03ce0c8, its message since reworded, tree unchanged):

• B1′ — Volume::catch_up asks the replay before it returns on its budget: a file with every byte is synced and caught up whatever the budget left, so the writer clears the batch's age rather than spinning. (A stop's catch-up never spun: finish calls it again with a fresh budget, which finds nothing owed and syncs.) New store::tests::a_budget_spent_on_the_replays_last_line_is_caught_up_and_synced (four lines, a budget of exactly their bytes); the old return put back fails it at "the file has every byte" (exit 101). 34 tests pass; clippy has no finding in the change.
• B4 — my publishing script reset the evidence branch to the remote before each commit, so round 2's logs (commit 20b60191) were dropped when the next call ran. Restored as f2b0acee and pushed; the script now pushes after each commit. Every evidence link in the body was rechecked and resolves (21 links).
• PR text: one boot per arm on the AMD bench; one or two rounds cannot tell one 3.5 ms write from two; a third of a CPU labelled a projection; the mark is begun, not finished, before its deadline.

Evidence: pr-1232 @ 8886efce (round 3; 5f48598d corrects the ToyOS hash in its message) and @ f2b0acee (round 2).

[Japabu]

Re-review of #1232 at 03ce0c8 (round 3)

Scope: round 2's two blockers (B1′, B4), the round-3 diff, and whether the queued runs at 9108a46 still stand for the head.

Architecture

No change. 9108a464a..03ce0c881 touches only system/logkeeper/src/store.rs (+25/−9):

• catch_up's end condition: about 6 lines of code replace 8;
• its doc (2 lines for 1);
• one new store test (17 lines).

Nothing else in the tree changed. The rest of the round is PR text and evidence.

Previous blockers

B1′: resolved in the code. store.rs:353-359 now asks the replay before it returns at the budget:

• Nothing syncs and returns Ok(true).
• Text or Gap past the budget returns Ok(false), and something is still owed.
• With the budget spent, room is 0, so Replay::next hands back one whole line, which is then dropped. That is one line copied per MiB, which is harmless.

How each caller fares:

• Writer::write (file.rs:282-293). On the B1′ boundary it now gets caught, so it clears owed_since and urgent, and the part's tail is synced. This was the real spin, and it is fixed.
• Volume::finish (store.rs:389). Its result is unchanged, because this caller never spun. See B5.

No other return path leaves an age with nothing owed. I traced every path that sets or keeps owed_since:

• owe (file.rs:234-240) sets it only while hub.end() != through. end only grows, and only a write lowers what is owed.
• write → Ok(false) with the part open now means budget spent with Text or Gap still owed, so the next write is due at once. This drains the backlog 1 MiB per write, as intended.
• Ok(false) with the part closed (a refused continuation): next_due follows retry, not the age.
• Ok(true) implies an open part, because sync needs one.
• Err: lost() takes through back to durable_through. That is no further than where the write began, so bytes are owed, and the part is closed, so next_due follows retry.
• Err with the last part: volume = None, so next_due is None.
• finish clears both fields, and resume goes through owe.

The test. a_budget_spent_on_the_replays_last_line_is_caught_up_and_synced (store.rs:545-560) appends four lines and sets the budget to exactly their bytes. It asserts that the file is caught up and synced.

• It is hermetic (TempDir), deterministic, and makes one claim.
• A line that alone overshoots the budget goes through the same written >= budget arm.
• That write() clears the age when caught is plain from inspection.

The control. I applied the published r3-b1p-control.patch to 03ce0c8 in a scratch index.

• Its git diff 9108a464a hashes to b25417ac356d, which is the control log's header.
• The log fails at store.rs:561, the line-558 assert shifted by the patch's 3 lines, with "the file has every byte", exit 101.
• r3-test.log (34 passed, exit 0) and r3-clippy.log carry a915dacfe05b. That hash equals git diff 9108a464a 03ce0c881 | shasum.
• Clippy's four findings are in inspect.rs, main.rs and policy.rs, as in round 2. None is in store.rs.

B4: resolved.

• Links. All 23 evidence URLs in the body resolve: 21 files and 2 trees. I fetched each at its pinned commit.
• Commits. 6d597bad, a6338741, f2b0acee and 8886efce are all ancestors of pr-1232 (5f48598d), so none can be garbage-collected.
• Spot checks:
  • b-test.log: 33 passed, exit 0, header diff a7f24befabea, which equals git diff ab336ebb3 9108a464a.
  • b1-control.log and b2-control.log: each fails its own test, exit 101.
  • judge-a-amd.log: PASS spawn_cost, exit 0.
  • judge-b-amd.log: PASS spawn_cost and PASS machine_reboot, exit 0.
  • amd-ab-extract.txt: the 224/288/430 and 228/276/360 µs lines, 51 spawns, 14.727→14.743 and 14.706→14.722, and zero stop or reader warnings in all three boots.

Findings

BLOCKER B5. Commit 03ce0c8's message says "a stop's catch-up did the same until its deadline". That is false, and with this repository's merge commits the message lands on main as history.

• Volume::finish loops on while !self.catch_up(..)? && self.is_open() && more() {} (store.rs:389), and every catch_up call starts with written = 0.
• At 9108a46, the boundary call returned Ok(false) with through == end. The loop then called catch_up again, which got Nothing, synced and returned Ok(true). That is one extra call with the same final state, not a spin to the deadline.
• Writer::finish also clears the age and sets stopped, so no batch age can spin during a stop either.
• So 03ce0c8 fixes one path, write(), not two. The implementer's round-3 note ("and a stop's catch-up stops") and the brief repeat the claim.
• Fix, either of:
  • reword 03ce0c8's message to drop the clause. The tree stays identical, so git diff 03ce0c881 <new> is empty, and every log and queued run stands with no new review of code.
  • add a one-line correction to the PR body, which becomes the merge commit's message.

SUGGESTION. store.rs:332-334: "which a file that does is synced to, whatever the budget left" takes two reads to parse. "Whether the file has every byte the replay has, synced, whatever the budget left" says the same thing. Optional. Changing the tree would change the evidence hashes.

PR text (for the orchestrator)

• The AMD wording is now honest.
  • It says one boot per arm.
  • It says one or two rounds cannot tell one 3.5 ms write from two.
  • It labels the 3.5 ms a write as an inference and the third of a CPU as a projection.
  • It states plainly that the drop is 70 µs, not 1.1–1.2 ms.
  • "Latency did not move beyond the two runs' spread" can only mean each run's min-to-median range, because one boot per arm gives no run-to-run spread. That reading holds: a 4 µs and 12 µs shift against 64 µs and 48 µs ranges.
• Status line: "machine_reboot at the head is staged" should say "at 9108a46". The Checks section already says so.

The queued runs at 9108a46 stand for 03ce0c8

The only behavioural difference between the two is one boundary: a catch_up call that spends its 1 MiB budget and reaches the replay's end. There, 03ce0c8 syncs and reports caught up, where 9108a46 left the tail unsynced and spun until the next line. The stop's flush reaches the same final state in both.

• Guest 43067018392. Still queued. headSha is 9108a46, and guest-rows.yml checks out the dispatch's own commit.
  • On a_clean_stop_proves_its_image, the mark path (file.rs) is unchanged.
  • On the_log_lands_on_the_boot_stick, the head can differ only by an earlier sync at that boundary.
  • Green at 9108a46 stands for the head. A red there needs investigating, not re-dispatching at the head.
• T14 and AMD machine_reboot at 9108a46. The mark's path and the flush's outcome are identical, so the runs stand.
• T14 testcases A/B (B = ab336eb). This round does not touch the per-round write path or the batch policy, and spawn_cost's ~16 KB of lines never reach a 1 MiB budget. Round 2's judgement holds, and the A/B stands as the cost measurement.

The landing preconditions are as round 2 listed them:

• guest 43067018392 green on both rows;
• machine_reboot at 9108a46 passing on both benches, with "Proof: … stopped cleanly" and none of the stop or "slowly" lines;
• the T14 A/B passing both verdicts, B free of those lines, and B's busy figure not above A's by more than about one T14 write.

SEND BACK (B5 only: a commit-message clause; no code change is needed, and once it is corrected this is LAND pending the runs above)

[Japabu]

Orchestrator: verified 9356faa. Its tree (2314a39a1) is identical to 03ce0c8's; only the commit message changed, and the false clause about the stop's catch-up is gone. Round 3's B5 is resolved; the code was accepted in round 3. Lands when guest 43067018392 is green on both rows, machine_reboot at 9108a46 passes on the T14 (AMD already passed), and the T14 testcases A/B passes both verdicts.

[Japabu]

Orchestrator: landing under the benches-down rule. Review r3 LAND (code accepted; commit message fix verified). Guest run 43092231506 at head 79b15d3: success (re-dispatched after 9356faa's catch_up change). Owed on metal recorded in issues/redesign-the-log-subsystem.md (machine_reboot T14; spawn_cost A/B); the T14 speed-up is not yet measured on metal.