toyos-metal writes where each boot's wall time went into boot.txt, and the judge prints it

[Japabu]

Stage S0 of the two-tier T14 plan. toyos-metal now times each phase of a boot on the host clock and writes the times into the readback's boot.txt. The suite's "the boots" line prints them under each boot. The body also measures what the testcases image is made of, which was the owner's question about the C corpus ("why is it so big?"). This stage changes nothing about the image.

The owner's rulings on the plan (verbatim)

• The debug boot runs daily, so the fast tier is one boot: "Daily (fast tier = 1 boot) (Recommended)".
• The load phase is 2 s on the fast boot and 20 s daily: "2 s fast, 20 s daily (Recommended)".
• The daily batch runs at night on main's tip: "Night, on main's tip (Recommended)".
• On the C corpus: "why is it so big?" The composition below answers it.

What changed and why

• boot.txt carries eight new keys, all in wall seconds. They sit beside the existing back_secs and stick_secs, which keep their meaning:
  • preamble_secs: admitting the image, the sudo rule, the lid policy, the disk identity and the SMBIOS read.
  • wipe_secs.
  • flash_secs: dd over ssh, the settle and the table read back.
  • dd_secs: dd's own seconds for the write, as dd printed them.
  • entry_secs: the boot entry, --bootnext and reboot.
  • down_secs.
  • read_log_secs.
  • raw_log_secs: reading the volume whole plus the outside judge's check of it. It reads - on a run without --fat32-check, so an absent key and an unread volume are different answers.
• The loop's own verdict is not timed. It is a string scan of the log, so its time says nothing; judge_and_write_readback keeps main's signature.
• dd's rate is not stored. It is dd's own division of the image's bytes by dd_secs, and both are on hand.
• dd_secs does not split the wire from the stick. Job::Flash is dd … conv=fsync reading ssh's stdin, so dd_secs is whichever of the two is slower. No key here separates them, so this branch does not answer the plan's "measure first" for cut (b). Deciding S5 needs a reading of the wire alone, for example the image piped over the same ssh into /dev/null on the machine and timed. That is a one-off command, not code in this branch.
• The save of the log partition before the flash stays out. It is the orchestrator's script, not this loop.
• One type, metal::BootFile, writes boot.txt, and metal::phases reads its phases back. There is no second spelling of a key. boot_file(back, stick, machine) is gone.
• A boot file without the phases is refused. Readback::new refuses it the same way it refuses one without back_secs, since every loop at this head writes the phases. The two hand-written fixtures in tests/checks.rs and tests/checks/metal.rs now write their boot file through BootFile, the loop's own writer, which is public for that reason.
• dd's last line is now read for its seconds as well as its byte count. A line without them is refused, as a line without a count was before (dd_said replaces dd_copied).
• toyos-metal prints phases: preamble … before it judges, and "the boots" prints the same line under each label.

Net lines (git diff --shortstat origin/main...HEAD): 4 files, +248 −43.

Gates (head 52bb3de20, on main 8dbccd3ab)

gate	exit
cargo test --lib -- metal (toyos-build, 63 tests)	0
cargo test --test toyos-checks -- metal (the harness's metal checks, 20 tests)	0
cargo run -- --ci host (Host: 78 step(s), all green)	0
cargo run -- --build-only	0
cargo test --test toyos-build -- --metal --metal-readback <scratch> boot:testcases (stages only; touches no machine)	2, the Staged verdict by design

Test. the_phases_cross_in_the_boot_file round-trips boot.txt with the volume read present and with it absent. It also checks that deleting any single phase line, or garbling one value, leaves a file that names no phases. The metal checks in tests/checks.rs and tests/checks/metal.rs now read their readbacks through the refusal.

Mutation. A parser that reads wipe from flash_secs turns the round-trip test red at 52bb3de20: exit 101, then restored. The patch is posted as a comment.

T14 boot at 52bb3de20, run by the orchestrator. boot:testcases as two images, each hash checked against request.txt before its flash (testcases 430,964,736 bytes, sha256 ffab49cbde0ded4caf653dc51f969d667ce5ea3e059077ee305e8833212f2e0b; testcases-watchdog 119,537,664 bytes, sha256 ad47af34f4856b0376c311889564a26434ddd6816ce7ede875f62cd980c5b8e5), each cargo run --bin toyos-metal -- --image <img> --readback <dir> --fat32-check; testcases-watchdog ran first. Each run's stdout is kept in the orchestrator's run log.

1. toyos-metal exited 0 on both, and each run's stdout carries its phases: line:
   • testcases: phases: preamble 1.7 s, wipe 0.7 s, flash 68.2 s (dd 66.6 s), entry 5.4 s, down 11.0 s, read_log 7.5 s, raw_log 2.8 s
   • testcases-watchdog: phases: preamble 1.5 s, wipe 0.8 s, flash 17.6 s (dd 16.1 s), entry 4.7 s, down 11.0 s, read_log 3.1 s, raw_log 2.9 s
2. Both boot.txt carry all eight keys; dd_secs < flash_secs (66.603 < 68.192; 16.143 < 17.584); raw_log_secs 2.800 and 2.937.
3. The judge, cargo test --test toyos-build -- --metal --metal-readback <dir> boot:testcases, EXIT=0, [metal] 249 passed, 0 failed, 2 boot(s), prints the same phases: line under each boot.
4. Phases + back + stick: 201.3 s of the driver's 205 s (testcases, back 104 s) and 106.7 s of 110 s (testcases-watchdog, back 65 s), the wall time measured from the end of the stick's log save to boot.txt's write, cargo run's start included.

No guest test is reached by this change: it is host code on both sides, and the judge side only prints.

Measured: what the testcases image is made of

This comes from the staged testcases image at origin/main a944746d5. ROOT's file list is from the build's own root: adding lines (--nocapture). Each file was then read back off the image through toyos_build::image::root_file_on and its ELF section table summed. The partition table and zero blocks were read off the image.

The whole image is 429,916,160 bytes (410 MiB):

partition	MiB	of which zero
ROOT A (bcachefs)	305.00	0.13
ESP	34.00	33.68
log	34.00	33.98
slot A (kernel)	34.00	31.62
slots table	1.00	1.00

So about 100.3 MiB of every flash is zeros, which is what S5 targets.

ROOT holds 389 files (302.9 MiB) and 152 symlinks:

kind	files	MiB	DWARF	.symtab+.strtab	.text	rodata+eh	other
C cases bin/test_c_*	137	224.17	96.48	44.05	56.31	21.82	5.19
Rust test binaries bin/test_rs_*	100	59.03	0.00	14.81	31.95	8.86	3.18
test cdylibs lib/*.so	4	11.22	0.00	2.71	6.50	1.46	0.54
shipped programs bin/	9	8.44	0.00	2.21	4.40	1.35	0.46
expect/ (corpus expectations)	137	0.02	–	–	–	–	–
etc/	2	0.01	–	–	–	–	–

The shipped programs are fileserver, supervisor, toybox, acpiserver, soundserver, logkeeper, diskserver, test-runner and symbolize. No data files ship on this ROOT: no doom1.wad and no soundfont.

Files over 1 MiB. All 137 C cases, each between 1,715,016 and 1,726,568 bytes. Then lib/libtls_cranelift.so (9.67 MiB, which test_rs_std_tls_cranelift loads), bin/fileserver (1.40), bin/supervisor (1.24) and bin/toybox (1.05).

Links or copies: both reports were right

• There are 137 symlinks. Each bin/<case> points to /system/bin/test_rs_ccheck, the 0.6 MiB comparator. It reads argv[0], runs /system/bin/test_c_<case> and compares the output with /system/expect/<case>. The symlink gives each run the case's name in the kernel's exit: record. This is what the reviewer saw.
• There are also 137 separate case binaries, bin/test_c_<case>, 1.64 MiB each and 224.17 MiB together. This is what the plan's subtraction found.

Each case is a static PIE that clang links against libtoyos_c.a. That archive is libc's staticlib with Rust's std inside it. So each case carries:

• a full copy of libc+std (.text 430,525 to 435,085 bytes; the case's own code is at most about 5 KB of it, judging by the spread);
• std's DWARF, 0.70 MiB per case. Its producer is clang LLVM (rustc version …), so the DWARF is the sysroot's, not the corpus's.

Debug information and symbols

• The Rust binaries carry no DWARF. Only a 34-byte .debug_gdb_scripts remains, because [profile.toyos] sets strip = "debuginfo" ("DWARF stays out of the image").
• The C cases are linked by clang, not cargo, so nothing strips them. They carry 96.48 MiB of DWARF that no judge reads.
• Every ELF keeps .symtab, and it is read:
  • symbolize names a killed program's frames from it;
  • the kernel binds a dlopened library's GLOB_DAT/JUMP_SLOT slots against the executable's .symtab (kernel/src/loader/symbols.rs, static_map).

What could shrink it, and what each costs

Flash is costed at 0.27 s/MB and ROOT read at 30.5 ms/MiB, the plan's measured rates.

cut	saves MiB	flash s	ROOT read s	what a test loses
Strip DWARF from the C cases' link (-Wl,--strip-debug at the corpus link, or the C sysroot's default)	96.48	27.3	2.94	Nothing: ccheck compares output, and symbolize reads .symtab, not DWARF. The image then follows the "DWARF stays out of the image" rule that the Rust binaries already follow.
Strip .symtab from the C cases as well	44.05	12.5	1.34	A crashed case's frames can no longer be named, and a case that dlopens loses the kernel's executable-side binding. Not recommended.
A shared libtoyos_c.so for the corpus (the kernel already loads DT_NEEDED)	about 124 (estimate: 127.7 MiB of non-DWARF corpus bytes, minus one about-1 MiB library and about 20 KB left per case)	about 35	about 3.8	No shared libc exists today; this would be new sysroot work. It also changes what the corpus tests: static linking is how a C port links here. Owner's call.
The plan's cut (a): the corpus, ccheck and expect/ leave the fast boot	224.80	63.6	6.86	The C corpus on real hardware, per change (the guest suite still runs it on every change).
The Rust tests' .symtab	14.81	–	–	Keep: symbolize and the loader read it.
The flashed zeros (S5 compression, or not writing them)	100.28 (not ROOT)	up to 28.4 if the wire is the bottleneck	–	Nothing.

The DWARF strip alone takes ROOT from 305 to about 209 MiB with nothing lost. Combined with cut (a), the fast boot's ROOT would be about 78 MiB.

What I am unsure of

• The shared-libc saving is an estimate. The per-case residue (dynamic tables, PLT, the case's own code) was not built.
• Two findings off this task are recorded on another branch, not here: the absolute host paths in every guest binary's .rodata, and the C cases' unstripped DWARF.
• dd's line through ssh and sudo is parsed from hand-typed fixtures. The orchestrator's saved stderr shows the T14's dd printing <n> bytes (…) copied, <secs> s, <rate>, which dd_said reads. Only the boot above proves this code reads it.

🤖 Generated with Claude Code

https://claude.ai/code/session_017cSFvbD35xJ2kGANVdm23C

[Japabu]

Mutation for the_phases_cross_in_the_boot_file, applied with git apply --check then git apply at 94cc6f20c, run with cargo test --lib -- metal::tests::the_phases_cross_in_the_boot_file: exit 101 (red), the test panicking on the round-trip assertion. It was then reverted with git apply -R, leaving the tree clean.

--- a/src/metal.rs
+++ b/src/metal.rs
@@ -1988,7 +1988,7 @@
     };
     Ok(Phases {
         preamble: secs(PREAMBLE_KEY)?,
-        wipe: secs(WIPE_KEY)?,
+        wipe: secs(FLASH_KEY)?,
         flash: secs(FLASH_KEY)?,
         dd_secs: secs(DD_SECS_KEY)?,
         dd_rate: named(DD_RATE_KEY)?,

[Japabu]

Review of #804 at head 94cc6f20c, against .claude/agents/reviewer.md.

Net lines (git diff --shortstat origin/main...94cc6f20c): 2 files, +257 −40. Production (src/metal.rs outside its test module): +194 −31. Tests: +56 −10 in src/metal.rs's test module, plus +8 in the harness (tests/common/metal.rs).

Gate logs (s0/logs/) match this head. ci-host.log starts at 14:05:36Z, after the commit at 14:05:20Z, from the clean toyos-t14-phases worktree, and ends Host: 78 step(s), all green, EXIT=0. build-only.log ends EXIT=0. mutation-swap.log shows the posted patch turning the_phases_cross_in_the_boot_file red at the wipe field. No guest test is reached. The change is not on root CLAUDE.md's high-risk list.

BLOCKER

• src/metal.rs:1097-1129, 1543-1663 — A T14 boot is owed before landing, and it is the orchestrator's to run. This changes the loop that drives the machine, and in one place it changes behaviour there: flash now refuses a boot whenever dd's line on the T14 does not parse for its seconds and rate, where before only a missing byte count was refused. Every timer also wraps a remote step that has only ever run against the T14. The dd_said fixtures are typed in by hand. The orchestrator's own t14-saves/*.err show that the machine's dd prints 35651584 bytes (36 MB, 34 MiB) copied, 1.75592 s, 20.3 MB/s through ssh and sudo, so the format is very likely right. Even so, that reading is not of this code, and S0 exists to produce the numbers. One routine --metal boot at this head, with --fat32-check, must show:

  1. toyos-metal exits 0, and its stdout carries the phases: line.
  2. The readback's boot.txt carries all ten new keys, with dd_secs < flash_secs, dd_rate exactly as dd printed it, and raw_log_secs a number rather than -.
  3. The judge's "the boots" prints phases: preamble … for that label, not its boot file names no ….
  4. preamble + wipe + flash + entry + down + back + stick + read_log + raw_log comes within a few seconds of the driver's wall time in the harness log, so no phase is left untimed.

  The run's command, exit code and log go into the body.

NOTE

• src/metal.rs:1896, 1922, 1685 — judge_secs times boot_verdict, which is a string scan (the fixture says 0.002 s). It is the only reason judge_and_write_readback takes mut boot and times itself. The plan's "judge" in its 132 s "flash and the rest" is not this. Cut the key, the field, the const and the timing.
• src/metal.rs:1891, 1913, 947-953 — dd_rate is dd's own division of image.bytes by dd_secs, and both are already on hand. Storing it as a free-form string adds a key and a field, and adds a refusal condition on the flash path, for nothing a reader cannot compute. Drop it, or say in the body why dd's rounded words are needed beside the exact numbers.
• tests/common/metal.rs:214, 1114-1117 — The Err arm of phases exists only for boot files written before this change and for the fixtures in tests/checks.rs and tests/checks/metal.rs. Every loop at this head writes the phases. A missing back_secs or stick_secs refuses the readback, and so does a missing machine (via one_machine); only phases are tolerated, which is a legacy path. The orchestrator should widen the fence to those two fixtures and have Readback::new refuse a boot file with no phases, as it already does for back_secs.
• PR body, "These are the S0 numbers the plan's flash/wire split … depend on" — this is false of the code. Job::Flash is dd … conv=fsync fed by ssh's stdin, so dd_secs is the time of the slower of wire and stick, and no key here separates them. Plan cut (b)'s "measure first (stage 0)" stays unanswered. The decision on S5 needs a reading of the wire alone, for example the image piped over the same ssh into /dev/null on the machine and timed. That is a one-off command, not code in this branch.
• PR body, "What I am unsure of" — the absolute host paths found in every guest binary's .rodata contradict issues/two-checkouts-of-one-tree-build-different-guest-bytes.md:20 (snake carries no path). The same goes for the 96.48 MiB of unstripped DWARF in the C cases, which breaks "DWARF stays out of the image". Both were found off the task and are owed a record in issues/ (or the existing issue corrected) with an owner. A report to the orchestrator is not a record.

SEND BACK

[Japabu]

Mutation for the_phases_cross_in_the_boot_file at 52bb3de20, applied with git apply --check then git apply, run with cargo test --lib -- metal::tests::the_phases_cross_in_the_boot_file: exit 101 (red), panicking at the round-trip assertion (src/metal.rs:2428). Reverted with git apply -R; git status --porcelain then printed nothing.

diff --git a/src/metal.rs b/src/metal.rs
index 5e94fed39..57c31644e 100644
--- a/src/metal.rs
+++ b/src/metal.rs
@@ -1975,7 +1975,7 @@ pub fn phases(text: &str) -> Result<Phases, String> {
     };
     Ok(Phases {
         preamble: secs(PREAMBLE_KEY)?,
-        wipe: secs(WIPE_KEY)?,
+        wipe: secs(FLASH_KEY)?,
         flash: secs(FLASH_KEY)?,
         dd_secs: secs(DD_SECS_KEY)?,
         entry: secs(ENTRY_KEY)?,

[Japabu]

T14 at 52bb3de20, boot:testcases (two boots, each toyos-metal --image <img> --readback <dir> --fat32-check, image hashes checked against request.txt: testcases ffab49cb…f2e0b, testcases-watchdog ad47af34…8b5e5). Both toyos-metal exit 0; judge cargo test --test toyos-build -- --metal --metal-readback <dir> boot:testcases EXIT=0, [metal] 249 passed, 0 failed, 2 boot(s).

The review's four points:

1. toyos-metal exit 0 on both, each with a phases: line.
2. boot.txt holds the eight phase keys; dd_secs < flash_secs (66.603 < 68.192; 16.143 < 17.584); raw_log_secs a number (2.800; 2.937).
3. The judge's "the boots" prints, per boot:
   • testcases: phases: preamble 1.7 s, wipe 0.7 s, flash 68.2 s (dd 66.6 s), entry 5.4 s, down 11.0 s, read_log 7.5 s, raw_log 2.8 s
   • testcases-watchdog: phases: preamble 1.5 s, wipe 0.8 s, flash 17.6 s (dd 16.1 s), entry 4.7 s, down 11.0 s, read_log 3.1 s, raw_log 2.9 s
4. Phases + back + stick against the driver's wall time (from the end of the sda3 save to boot.txt's write, which includes cargo run's start): testcases 201.3 s of 205 s; testcases-watchdog 106.6 s of 110 s. Nothing large goes untimed.

What it already says: on the fast boot, back (104 s, the boot itself plus firmware) and the flash (68 s) are the two costs; the flash of the C corpus image is 4x the watchdog image's.

[Japabu]

Second review of #804 at head 52bb3de20, on main 8dbccd3ab, against .claude/agents/reviewer.md.

Round-one findings

• BLOCKER (a T14 boot owed at this head): CLOSED. The orchestrator ran it (comment 6083512910), and the readbacks under onebootmetal/s0/metal/ agree with that comment:
  • request.txt was staged from wt/toyos-t14-phases at 52bb3de20, a clean tree, and the worktree still sits at 52bb3de208a7… with nothing in git status --porcelain.
  • Both verdict.txt files read passed.
  • Both boot.txt files carry all eight keys. dd_secs < flash_secs (66.603 < 68.192 and 16.143 < 17.584), and raw_log_secs is a number (2.800 and 2.937). So dd_said parsed the T14's real dd line through ssh and sudo.
  • judge.log prints phases: preamble … under both labels and ends [metal] 249 passed, 0 failed, 2 boot(s).
  • I re-summed the phases with back and stick: 201.274 s for testcases and 106.656 s for testcases-watchdog. The boot.txt mtimes are 17:00:47 and 16:57:07. Subtracting the stated walls of 205 s and 110 s puts testcases' start 15 s after watchdog's end, which is consistent with the sda3 save between them. Nothing large is left untimed.
• NOTE judge_secs: CLOSED. The key, the field and the timing are gone, and judge_and_write_readback keeps main's signature.
• NOTE dd_rate: CLOSED. It is dropped, and DdSaid holds only bytes and seconds.
• NOTE the Err arm of phases in the harness: CLOSED. Readback::new refuses a boot file with no phases (tests/common/metal.rs:230). Both fixtures write through BootFile, and git grep finds no other writer of boot.txt.
• NOTE the body's false "flash/wire split" claim: CLOSED. The body now says dd_secs does not separate the wire from the stick, and that cut (b) is still unmeasured.
• NOTE the two off-task findings owed a record: CLOSED. Draft The C cases link without DWARF: the testcases ROOT goes from 305 to 209 MiB, and the checkout-path issue records the paths every guest binary carries #806 (wt/toyos-cstrip) does two things. It strips DWARF from the C cases' link (tests/common/compile.rs). It also corrects issues/two-checkouts-of-one-tree-build-different-guest-bytes.md with the paths that every guest binary carries.

Gates at this head

r2-ci-host.log starts 14:33:42Z, four seconds after the commit at 14:33:38Z, ends Host: 78 step(s), all green and EXIT=0. r2-build-only.log ends EXIT=0. r2-mutation.log applies the posted wipe: secs(FLASH_KEY)? patch at 52bb3de20 and gets EXIT=101 at src/metal.rs:2428, then restores the tree. No guest test is reached.

Net lines (git diff --shortstat origin/main...52bb3de20): 4 files, +248 −43. Counting src/metal.rs by non-blank lines: production +166 −25 and its test module +45 −7. The harness adds +6 (tests/common/metal.rs), and the fixtures change by +20 −10 (tests/checks.rs, tests/checks/metal.rs). I accept the production growth. The eight timed phases are what S0 exists to measure. BootFile/phases replace the old format! writer, so one type now both writes and reads every key. git grep finds no remaining reference to dd_copied, boot_file(, judge_secs or dd_rate.

I checked the fix round for new defects and found none:

• flashed.expect is reached only after the dry-run return. as_root answers None only when dry_run is set.
• The Display line continuation renders down 11.0 s, read_log … correctly in judge.log.
• word's strip_prefix lookup has no key that is a prefix of another.

BLOCKER

None open.

NOTE

• PR body, "T14 boot: owed, not run": this is false at this head. The reading exists, but only in comment 6083512910. Its command, exit codes and readback paths belong in the body, which becomes the merge commit's record.
• onebootmetal/s0/metal/: neither toyos-metal run's stdout nor its exit code was saved. The comment's "Both toyos-metal exit 0 … each with a phases: line" therefore rests on verdict.txt (passed) and judge.log, not on a log of the runs. That covers the substance, because the judge prints the same Phases Display from the same boot.txt. The body should name the runs as evidenced this way, not as logged. Also, the mtimes show testcases-watchdog ran before testcases, the reverse of request.txt's order.

LAND

[Japabu]

CI at 52bb3de20, read from each job's log: host 79 steps all green (the loom FAILED lines are its negative-control arms, which the step requires red); toolchain restored (llvm a2cc063281d9f279, compiler 6c76c19e5ffcc869, freestanding 0f5a5faab7bbc78c, sysroot fcaf4949f5310fa6); guest suite 41/41 ok. Merges clean with main d6298c83e. Queued.