From c8c1b008089fa27c5d76acfcd1714b1f8db49089 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 16:05:20 +0200 Subject: [PATCH 1/2] toyos-metal writes where each boot's wall time went into boot.txt, and the judge prints it The two-tier T14 plan's weakest number is the flash: 132 s of a 273 s cycle was "flash and the rest", split by a fit over seven boots. The loop now times each phase it runs on the host clock and writes it beside back_secs and stick_secs: the preamble (admission, the rule, the lid policy, the disk and the machine read), the wipe, the flash with dd's own seconds and rate, the machine's entry into ToyOS (boot entry, bootnext, reboot), going down, read_log, raw_log (the volume read and the outside judge's check, "-" without --fat32-check) and the loop's verdict. The driver prints them on one line and the suite's "the boots" prints them under each boot. Coming back and the stick keep their existing keys. A readback written before this names no phases; the judge says so on that line rather than failing the boot, since a host measurement is no verdict on the machine. dd's line is now read for its seconds and rate as well as its count, and a line without them is refused as one without a count was. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_017cSFvbD35xJ2kGANVdm23C --- src/metal.rs | 289 ++++++++++++++++++++++++++++++++++++------ tests/common/metal.rs | 8 ++ 2 files changed, 257 insertions(+), 40 deletions(-) diff --git a/src/metal.rs b/src/metal.rs index c2abba366bf..83a154218ca 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -934,10 +934,22 @@ fn one_partition( }) } -/// How many bytes `dd` says it copied, out of its own last line. -fn dd_copied(stderr: &str) -> Option { +/// What `dd` said of a copy on its own last line, +/// ` bytes (…) copied, s, `. +#[derive(Debug, Clone, PartialEq)] +struct DdSaid { + bytes: u64, + secs: f64, + /// In whatever unit `dd` chose for it. + rate: String, +} + +fn dd_said(stderr: &str) -> Option { let line = stderr.lines().find(|l| l.contains(" bytes ") && l.contains("copied"))?; - line.split_whitespace().next()?.parse().ok() + let bytes = line.split_whitespace().next()?.parse().ok()?; + let (_, after) = line.split_once("copied, ")?; + let (secs, rate) = after.split_once(" s, ")?; + Some(DdSaid { bytes, secs: secs.parse().ok()?, rate: rate.trim().to_string() }) } /// The id and the partition GUID of every entry `efibootmgr` lists under @@ -1080,19 +1092,24 @@ impl Driver { /// count and then the table the kernel re-read are both compared. `wipefs` /// first, because the stick outlives the image and its old backup GPT would /// otherwise leave the firmware two tables. - fn flash(&self, image: &Flashable) -> Result<(), Refusal> { + /// + /// `None` is a dry run, which wrote nothing to time. + fn flash(&self, image: &Flashable) -> Result, Refusal> { + let began = std::time::Instant::now(); self.as_root("wiping the old signatures", Job::Wipe, None, None)?; + let wipe = began.elapsed().as_secs_f64(); + let began = std::time::Instant::now(); let out = self.as_root("flashing the stick", Job::Flash, None, Some(&image.path))?; - let Some(out) = out else { return Ok(()) }; + let Some(out) = out else { return Ok(None) }; let stderr = String::from_utf8_lossy(&out.stderr).to_string(); - let copied = dd_copied(&stderr).ok_or_else(|| Refusal::Remote { + let dd = dd_said(&stderr).ok_or_else(|| Refusal::Remote { what: "flashing the stick".to_string(), - status: "printed no byte count".to_string(), + status: "printed no byte count, seconds and rate".to_string(), stderr, })?; - if copied != image.bytes { + if dd.bytes != image.bytes { let what = "the byte count dd reported".to_string(); - return Err(Refusal::Landed { what, want: image.bytes, got: copied }); + return Err(Refusal::Landed { what, want: image.bytes, got: dd.bytes }); } self.ssh("settling the new table", "udevadm settle")?; for (name, part) in [("the ESP", image.esp), ("TOYOS-LOG", image.log)] { @@ -1109,7 +1126,7 @@ impl Driver { } } } - Ok(()) + Ok(Some(Flashed { wipe, flash: began.elapsed().as_secs_f64(), dd })) } /// The boot entry for *this* image's ESP. An entry carrying the label but @@ -1165,10 +1182,13 @@ impl Driver { /// **`reboot` is `systemctl` and returns before the machine goes down**, so /// the machine is watched down before it is watched back up: a probe that - /// caught dying Ubuntu would read a stick ToyOS had never booted. - fn ride_the_reboot(&self, secs: u64) -> Result { + /// caught dying Ubuntu would read a stick ToyOS had never booted. Answers + /// the wall seconds going down took, and the whole seconds coming back did. + fn ride_the_reboot(&self, secs: u64) -> Result<(f64, u64), Refusal> { + let began = std::time::Instant::now(); self.wait(GOING_DOWN_SECS, "go down", false)?; - self.wait(secs, "come back", true) + let down = began.elapsed().as_secs_f64(); + Ok((down, self.wait(secs, "come back", true)?)) } /// Wait for the log partition's device node, and say how long it took. @@ -1523,6 +1543,7 @@ pub fn run(args: &Args) -> Result, Refusal> { return Ok(None); } let driver = Driver { target: args.target.clone(), dry_run: args.dry_run }; + let began = std::time::Instant::now(); let Some(asked) = &args.image else { return Err(Refusal::Usage(String::from( @@ -1577,31 +1598,38 @@ pub fn run(args: &Args) -> Result, Refusal> { let machine = Machine::parse(&driver.ssh("reading the machine's SMBIOS", Machine::QUERY)?) .map_err(Refusal::Machine)?; println!("machine {} {}, BIOS {}", machine.vendor, machine.product, machine.bios); + let preamble = began.elapsed().as_secs_f64(); - driver.flash(&image)?; + let flashed = driver.flash(&image)?; + let began = std::time::Instant::now(); let entry = driver.boot_entry(&image.esp)?; driver.as_root("setting bootnext", Job::BootNext, Some(&entry), None)?; driver.as_root("rebooting", Job::Reboot, None, None)?; + let entry = began.elapsed().as_secs_f64(); if driver.dry_run { driver.as_root("mounting the log partition", Job::Mount, None, None)?; driver.as_root("unmounting the log partition", Job::Umount, None, None)?; println!("dry run: nothing was written and the machine was not rebooted"); return Ok(None); } + let flashed = flashed.expect("only a dry run flashes nothing, and it has returned"); - let back = driver.ride_the_reboot(wait_secs)?; + let (down, back) = driver.ride_the_reboot(wait_secs)?; println!("the machine answered ssh again after {back} s"); // Before the mount, so the stick's own answer is a number rather than // the reason a mount failed. let stick = driver.wait_for_the_stick()?; println!("the boot stick enumerated {stick} s after the machine answered"); + let began = std::time::Instant::now(); let (loader, log) = driver.read_log()?; + let read_log = began.elapsed().as_secs_f64(); print!("{loader}{log}"); // The outside judge, and it runs before the verdict: a volume this // cannot read is a finding about what the boot wrote, and the reason to // read the sectors rather than the mount is that a mount has already // had a FAT driver's opinion about them. + let began = std::time::Instant::now(); if args.fat32_check { let bytes = driver.raw_log(image.log.sectors)?; if let Some(dir) = &args.readback { @@ -1617,23 +1645,47 @@ pub fn run(args: &Args) -> Result, Refusal> { } println!("toyos-fat32-check: the log partition's {} bytes check out", bytes.len()); } - let boot = boot_file(back, stick, &machine); - judge_and_write_readback(&armed, &loader, &log, args.readback.as_deref(), &boot).map(Some) + let raw_log = args.fat32_check.then(|| began.elapsed().as_secs_f64()); + let phases = Phases { + preamble, + wipe: flashed.wipe, + flash: flashed.flash, + dd_secs: flashed.dd.secs, + dd_rate: flashed.dd.rate, + entry, + down, + read_log, + raw_log, + judge: 0.0, + }; + let boot = BootFile { back, stick, machine, phases }; + judge_and_write_readback(&armed, &loader, &log, args.readback.as_deref(), boot).map(Some) +} + +/// What [`Driver::flash`] took, on a run that was no rehearsal. +struct Flashed { + wipe: f64, + /// The write and the table read back after it. + flash: f64, + dd: DdSaid, } /// This boot's verdict, **judged before the readback is written, and written /// into it**, so a judge reading the directory later reads the verdict this -/// run returns. +/// run returns. `boot`'s judge phase is the verdict's own. fn judge_and_write_readback( armed: &[String], loader: &str, log: &str, readback: Option<&Path>, - boot: &str, + mut boot: BootFile, ) -> Result { + let began = std::time::Instant::now(); let verdict = boot_verdict(armed, loader, log); + boot.phases.judge = began.elapsed().as_secs_f64(); + println!("phases: {}", boot.phases); if let Some(dir) = readback { - write_readback(dir, loader, log, boot, &verdict_file(verdict.as_ref().err()))?; + write_readback(dir, loader, log, &boot.text(), &verdict_file(verdict.as_ref().err()))?; println!("readback written to {}", dir.display()); } verdict @@ -1830,6 +1882,127 @@ pub const VENDOR_KEY: &str = "machine_vendor"; pub const PRODUCT_KEY: &str = "machine_product"; pub const BIOS_KEY: &str = "machine_bios"; +/// [`Phases`]' keys, each in wall seconds but [`DD_RATE_KEY`], which is `dd`'s +/// own words; [`RAW_LOG_KEY`] reads [`NOT_READ`] on a run that read no volume. +const PREAMBLE_KEY: &str = "preamble_secs"; +const WIPE_KEY: &str = "wipe_secs"; +const FLASH_KEY: &str = "flash_secs"; +const DD_SECS_KEY: &str = "dd_secs"; +const DD_RATE_KEY: &str = "dd_rate"; +const ENTRY_KEY: &str = "entry_secs"; +const DOWN_KEY: &str = "down_secs"; +const READ_LOG_KEY: &str = "read_log_secs"; +const RAW_LOG_KEY: &str = "raw_log_secs"; +const JUDGE_KEY: &str = "judge_secs"; +const NOT_READ: &str = "-"; + +/// Where one run of the loop spent its wall time, by the host's clock, phase +/// by phase; coming back and the stick are [`BACK_SECS`] and +/// [`STICK_SECS_KEY`]. Any save of the log partition before the flash is no +/// phase of this loop's. +#[derive(Debug, Clone, PartialEq)] +pub struct Phases { + /// Admitting the image, then the rule, the lid policy, the disk and the + /// machine read off the machine. + pub preamble: f64, + pub wipe: f64, + /// `dd` over `ssh`, and the table read back. + pub flash: f64, + /// What `dd` itself said of the write. + pub dd_secs: f64, + pub dd_rate: String, + /// The boot entry, `--bootnext` and `reboot`. + pub entry: f64, + pub down: f64, + pub read_log: f64, + /// The volume read whole and the outside judge's check of it; `None` on a + /// run without `--fat32-check`. + pub raw_log: Option, + /// The loop's own verdict. + pub judge: f64, +} + +impl fmt::Display for Phases { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!( + f, + "preamble {:.1} s, wipe {:.1} s, flash {:.1} s (dd {:.1} s, {}), entry {:.1} s, down \ + {:.1} s, read_log {:.1} s, raw_log ", + self.preamble, + self.wipe, + self.flash, + self.dd_secs, + self.dd_rate, + self.entry, + self.down, + self.read_log + )?; + match self.raw_log { + Some(secs) => write!(f, "{secs:.1} s")?, + None => f.write_str(NOT_READ)?, + } + write!(f, ", judge {:.3} s", self.judge) + } +} + +/// [`READBACK_BOOT`]'s content: what the host measured about the boot, and the +/// machine it ran on. +struct BootFile { + back: u64, + stick: u64, + machine: Machine, + phases: Phases, +} + +impl BootFile { + fn text(&self) -> String { + let Self { back, stick, machine, phases } = self; + let secs = |s: f64| format!("{s:.3}"); + let rows = [ + (BACK_SECS, back.to_string()), + (STICK_SECS_KEY, stick.to_string()), + (VENDOR_KEY, machine.vendor.clone()), + (PRODUCT_KEY, machine.product.clone()), + (BIOS_KEY, machine.bios.clone()), + (PREAMBLE_KEY, secs(phases.preamble)), + (WIPE_KEY, secs(phases.wipe)), + (FLASH_KEY, secs(phases.flash)), + (DD_SECS_KEY, secs(phases.dd_secs)), + (DD_RATE_KEY, phases.dd_rate.clone()), + (ENTRY_KEY, secs(phases.entry)), + (DOWN_KEY, secs(phases.down)), + (READ_LOG_KEY, secs(phases.read_log)), + (RAW_LOG_KEY, phases.raw_log.map_or_else(|| NOT_READ.to_string(), secs)), + (JUDGE_KEY, secs(phases.judge)), + ]; + rows.iter().map(|(name, value)| format!("{name} {value}\n")).collect() + } +} + +/// The phases a readback names, or why it names none. +pub fn phases(text: &str) -> Result { + let named = |name: &str| word(text, name).ok_or_else(|| format!("names no `{name}`")); + let secs = |name: &str| -> Result { + let got = named(name)?; + got.parse().map_err(|_| format!("reads `{name} {got}`, which is no count of seconds")) + }; + Ok(Phases { + preamble: secs(PREAMBLE_KEY)?, + wipe: secs(WIPE_KEY)?, + flash: secs(FLASH_KEY)?, + dd_secs: secs(DD_SECS_KEY)?, + dd_rate: named(DD_RATE_KEY)?, + entry: secs(ENTRY_KEY)?, + down: secs(DOWN_KEY)?, + read_log: secs(READ_LOG_KEY)?, + raw_log: match named(RAW_LOG_KEY)?.as_str() { + NOT_READ => None, + _ => Some(secs(RAW_LOG_KEY)?), + }, + judge: secs(JUDGE_KEY)?, + }) +} + /// Every file a readback directory carries, so a run that writes none of them /// leaves none of the last run's behind. pub const READBACK_FILES: &[&str] = &[ @@ -1884,16 +2057,6 @@ fn write_readback( wrote(&dir.join(READBACK_VERDICT), verdict) } -/// [`READBACK_BOOT`]'s text: what the host measured about the boot, and the -/// machine it ran on. -fn boot_file(back: u64, stick: u64, machine: &Machine) -> String { - format!( - "{BACK_SECS} {back}\n{STICK_SECS_KEY} {stick}\n{VENDOR_KEY} {}\n{PRODUCT_KEY} {}\n\ - {BIOS_KEY} {}\n", - machine.vendor, machine.product, machine.bios - ) -} - /// Whether this boot was a loader pass that reported a record and booted no /// kernel, and what that pass said if so. /// @@ -2245,15 +2408,57 @@ mod tests { assert_eq!(back_secs("back_secs later\n"), None); } + fn t14() -> Machine { + Machine::parse("LENOVO\n20W0003AMZ\nN34ET71W (1.71 )\n").expect("three lines") + } + + fn phased(raw_log: Option) -> Phases { + Phases { + preamble: 3.104, + wipe: 0.412, + flash: 121.5, + dd_secs: 117.234, + dd_rate: "3.7 MB/s".to_string(), + entry: 2.25, + down: 8.0, + read_log: 1.375, + raw_log, + judge: 0.002, + } + } + #[test] fn the_machine_crosses_in_the_boot_file() { - let t14 = Machine::parse("LENOVO\n20W0003AMZ\nN34ET71W (1.71 )\n").expect("three lines"); - let boot = boot_file(47, 0, &t14); - assert_eq!(machine(&boot), Ok(t14)); + let boot = BootFile { back: 47, stick: 0, machine: t14(), phases: phased(None) }.text(); + assert_eq!(machine(&boot), Ok(t14())); assert_eq!(back_secs(&boot), Some(47)); assert!(machine("back_secs 47\nmachine_vendor LENOVO\n").is_err()); } + /// Every phase the loop timed is the one a judge reads back, the volume + /// read's absence included, and a file missing any phase names none. + #[test] + fn the_phases_cross_in_the_boot_file() { + for raw_log in [Some(9.875), None] { + let boot = + BootFile { back: 141, stick: 2, machine: t14(), phases: phased(raw_log) }.text(); + assert_eq!(phases(&boot), Ok(phased(raw_log)), "{boot}"); + assert_eq!((back_secs(&boot), stick_secs(&boot)), (Some(141), Some(2))); + for line in boot.lines().filter(|line| line.contains("_secs ") || line.starts_with("dd_")) { + if line.starts_with(BACK_SECS) || line.starts_with(STICK_SECS_KEY) { + continue; + } + let short = boot.replace(&format!("{line}\n"), ""); + assert!(phases(&short).is_err(), "{line:?} gone still names phases"); + } + } + assert!(phases("back_secs 47\nstick_secs 0\n").is_err()); + let garbled = BootFile { back: 1, stick: 0, machine: t14(), phases: phased(None) } + .text() + .replace("flash_secs 121.500", "flash_secs later"); + assert!(phases(&garbled).is_err()); + } + /// A judge reading the readback later rules on the boot as the loop did. #[test] fn the_loops_verdict_crosses_in_the_readback() { @@ -2274,7 +2479,7 @@ mod tests { fn the_readback_carries_the_verdict_the_loop_returns() { let dir = toyos_tmpdir::TempDir::new("verdict"); let armed = [alloc_deadline()]; - let boot = "back_secs 40\nstick_secs 0\n"; + let boot = || BootFile { back: 40, stick: 0, machine: t14(), phases: phased(None) }; let written = || { let at = dir.join(READBACK_VERDICT); loop_verdict(&std::fs::read_to_string(&at).expect("the verdict is written")) @@ -2282,7 +2487,7 @@ mod tests { let hung = format!("{}\n{}\n", bootlog::LOADER_FIRST_LINE, bootlog::HUNG_WITHOUT_A_RECORD); assert_eq!( - judge_and_write_readback(&armed, &hung, "", Some(dir.path()), boot), + judge_and_write_readback(&armed, &hung, "", Some(dir.path()), boot()), Err(Refusal::HungWithoutARecord) ); assert_eq!(written(), Err(Refusal::HungWithoutARecord.to_string().trim_end().to_string())); @@ -2305,10 +2510,12 @@ mod tests { bootlog::STOPPING ); assert_eq!( - judge_and_write_readback(&armed, &loader, &log, Some(dir.path()), boot), + judge_and_write_readback(&armed, &loader, &log, Some(dir.path()), boot()), Ok(1151) ); assert_eq!(written(), Ok(())); + let boot = std::fs::read_to_string(dir.join(READBACK_BOOT)).expect("the boot file"); + assert_eq!(phases(&boot).map(|p| p.preamble), Ok(phased(None).preamble)); } #[test] @@ -2624,12 +2831,14 @@ mod tests { fn dd_is_believed_only_where_it_states_a_count() { let real = "44+0 records in\n44+0 records out\n\ 184549376 bytes (185 MB, 176 MiB) copied, 12.3169 s, 15.0 MB/s\n"; - assert_eq!(dd_copied(real), Some(184_549_376)); + let said = |bytes, secs, rate: &str| Some(DdSaid { bytes, secs, rate: rate.to_string() }); + assert_eq!(dd_said(real), said(184_549_376, 12.3169, "15.0 MB/s")); let short = "10+0 records in\n10+0 records out\n\ 41943040 bytes (42 MB, 40 MiB) copied, 3.1 s, 13.5 MB/s\n"; - assert_eq!(dd_copied(short), Some(41_943_040)); - assert_eq!(dd_copied("44+0 records in\n44+0 records out\n"), None); - assert_eq!(dd_copied(""), None); + assert_eq!(dd_said(short), said(41_943_040, 3.1, "13.5 MB/s")); + assert_eq!(dd_said("44+0 records in\n44+0 records out\n"), None); + assert_eq!(dd_said(""), None); + assert_eq!(dd_said("41943040 bytes (42 MB, 40 MiB) copied\n"), None); } #[test] diff --git a/tests/common/metal.rs b/tests/common/metal.rs index 7810ecabe11..c0759dcefe3 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -211,6 +211,9 @@ pub struct Readback { pub stick_secs: u64, /// The machine the loop read before the flash. pub machine: Result, + /// Where the loop's wall time went, or why the boot file names no phases: + /// a readback written before the loop timed them. + phases: Result, /// What was measured on this boot and no owner has taken yet /// ([`Self::taken`]). numbers: RefCell>, @@ -235,6 +238,7 @@ impl Readback { stick_secs, machine: toyos_build::metal::machine(boot) .map_err(|why| format!("{label}'s boot file {why}")), + phases: toyos_build::metal::phases(boot), numbers: RefCell::new(BTreeMap::new()), }) } @@ -1107,6 +1111,10 @@ pub fn judge_readbacks( back.back_secs, back.stick_secs ); + match &back.phases { + Ok(phases) => eprintln!(" phases: {phases}"), + Err(why) => eprintln!(" phases: its boot file {why}"), + } let panel = back.panel(); if let Some(panel) = panel { eprintln!( From 52bb3de208a71a16640a3ba762d581dfcf4eea41 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 16:33:38 +0200 Subject: [PATCH 2/2] boot.txt's phases drop judge_secs and dd_rate, and a boot file without them is refused judge_secs timed boot_verdict, a string scan, and was the only reason judge_and_write_readback took the boot file by value; it goes, and that function takes the boot file's text as it did before. dd_rate was dd's own division of the image's bytes by dd_secs, both already on hand; it goes, and dd's line is refused only for want of its byte count or its seconds. dd_secs is whichever of the wire and the stick is slower, since dd reads ssh's stdin; the field says so, and no key splits them. Readback::new now refuses a boot file that names no phases, as it refuses one without back_secs: every loop at this head writes them. The two fixtures that wrote boot files by hand (tests/checks.rs and tests/checks/metal.rs) now write one through BootFile, the loop's own writer, which becomes public for it. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_017cSFvbD35xJ2kGANVdm23C --- src/metal.rs | 86 +++++++++++++++++-------------------------- tests/checks.rs | 5 +-- tests/checks/metal.rs | 25 +++++++++---- tests/common/metal.rs | 14 +++---- 4 files changed, 59 insertions(+), 71 deletions(-) diff --git a/src/metal.rs b/src/metal.rs index 83a154218ca..5e94fed3919 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -940,16 +940,14 @@ fn one_partition( struct DdSaid { bytes: u64, secs: f64, - /// In whatever unit `dd` chose for it. - rate: String, } fn dd_said(stderr: &str) -> Option { let line = stderr.lines().find(|l| l.contains(" bytes ") && l.contains("copied"))?; let bytes = line.split_whitespace().next()?.parse().ok()?; let (_, after) = line.split_once("copied, ")?; - let (secs, rate) = after.split_once(" s, ")?; - Some(DdSaid { bytes, secs: secs.parse().ok()?, rate: rate.trim().to_string() }) + let (secs, _) = after.split_once(" s, ")?; + Some(DdSaid { bytes, secs: secs.parse().ok()? }) } /// The id and the partition GUID of every entry `efibootmgr` lists under @@ -1104,7 +1102,7 @@ impl Driver { let stderr = String::from_utf8_lossy(&out.stderr).to_string(); let dd = dd_said(&stderr).ok_or_else(|| Refusal::Remote { what: "flashing the stick".to_string(), - status: "printed no byte count, seconds and rate".to_string(), + status: "printed no byte count and seconds".to_string(), stderr, })?; if dd.bytes != image.bytes { @@ -1126,7 +1124,7 @@ impl Driver { } } } - Ok(Some(Flashed { wipe, flash: began.elapsed().as_secs_f64(), dd })) + Ok(Some(Flashed { wipe, flash: began.elapsed().as_secs_f64(), dd: dd.secs })) } /// The boot entry for *this* image's ESP. An entry carrying the label but @@ -1650,16 +1648,15 @@ pub fn run(args: &Args) -> Result, Refusal> { preamble, wipe: flashed.wipe, flash: flashed.flash, - dd_secs: flashed.dd.secs, - dd_rate: flashed.dd.rate, + dd_secs: flashed.dd, entry, down, read_log, raw_log, - judge: 0.0, }; - let boot = BootFile { back, stick, machine, phases }; - judge_and_write_readback(&armed, &loader, &log, args.readback.as_deref(), boot).map(Some) + println!("phases: {phases}"); + let boot = BootFile { back, stick, machine, phases }.text(); + judge_and_write_readback(&armed, &loader, &log, args.readback.as_deref(), &boot).map(Some) } /// What [`Driver::flash`] took, on a run that was no rehearsal. @@ -1667,25 +1664,23 @@ struct Flashed { wipe: f64, /// The write and the table read back after it. flash: f64, - dd: DdSaid, + /// `dd`'s own seconds for the write. + dd: f64, } /// This boot's verdict, **judged before the readback is written, and written /// into it**, so a judge reading the directory later reads the verdict this -/// run returns. `boot`'s judge phase is the verdict's own. +/// run returns. fn judge_and_write_readback( armed: &[String], loader: &str, log: &str, readback: Option<&Path>, - mut boot: BootFile, + boot: &str, ) -> Result { - let began = std::time::Instant::now(); let verdict = boot_verdict(armed, loader, log); - boot.phases.judge = began.elapsed().as_secs_f64(); - println!("phases: {}", boot.phases); if let Some(dir) = readback { - write_readback(dir, loader, log, &boot.text(), &verdict_file(verdict.as_ref().err()))?; + write_readback(dir, loader, log, boot, &verdict_file(verdict.as_ref().err()))?; println!("readback written to {}", dir.display()); } verdict @@ -1882,18 +1877,16 @@ pub const VENDOR_KEY: &str = "machine_vendor"; pub const PRODUCT_KEY: &str = "machine_product"; pub const BIOS_KEY: &str = "machine_bios"; -/// [`Phases`]' keys, each in wall seconds but [`DD_RATE_KEY`], which is `dd`'s -/// own words; [`RAW_LOG_KEY`] reads [`NOT_READ`] on a run that read no volume. +/// [`Phases`]' keys, each in wall seconds; [`RAW_LOG_KEY`] reads [`NOT_READ`] +/// on a run that read no volume. const PREAMBLE_KEY: &str = "preamble_secs"; const WIPE_KEY: &str = "wipe_secs"; const FLASH_KEY: &str = "flash_secs"; const DD_SECS_KEY: &str = "dd_secs"; -const DD_RATE_KEY: &str = "dd_rate"; const ENTRY_KEY: &str = "entry_secs"; const DOWN_KEY: &str = "down_secs"; const READ_LOG_KEY: &str = "read_log_secs"; const RAW_LOG_KEY: &str = "raw_log_secs"; -const JUDGE_KEY: &str = "judge_secs"; const NOT_READ: &str = "-"; /// Where one run of the loop spent its wall time, by the host's clock, phase @@ -1908,9 +1901,9 @@ pub struct Phases { pub wipe: f64, /// `dd` over `ssh`, and the table read back. pub flash: f64, - /// What `dd` itself said of the write. + /// What `dd` itself said of the write. It reads `ssh`'s stdin, so this is + /// whichever of the wire and the stick is slower, and splits neither out. pub dd_secs: f64, - pub dd_rate: String, /// The boot entry, `--bootnext` and `reboot`. pub entry: f64, pub down: f64, @@ -1918,44 +1911,40 @@ pub struct Phases { /// The volume read whole and the outside judge's check of it; `None` on a /// run without `--fat32-check`. pub raw_log: Option, - /// The loop's own verdict. - pub judge: f64, } impl fmt::Display for Phases { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { write!( f, - "preamble {:.1} s, wipe {:.1} s, flash {:.1} s (dd {:.1} s, {}), entry {:.1} s, down \ - {:.1} s, read_log {:.1} s, raw_log ", + "preamble {:.1} s, wipe {:.1} s, flash {:.1} s (dd {:.1} s), entry {:.1} s, down {:.1} \ + s, read_log {:.1} s, raw_log ", self.preamble, self.wipe, self.flash, self.dd_secs, - self.dd_rate, self.entry, self.down, self.read_log )?; match self.raw_log { - Some(secs) => write!(f, "{secs:.1} s")?, - None => f.write_str(NOT_READ)?, + Some(secs) => write!(f, "{secs:.1} s"), + None => f.write_str(NOT_READ), } - write!(f, ", judge {:.3} s", self.judge) } } /// [`READBACK_BOOT`]'s content: what the host measured about the boot, and the /// machine it ran on. -struct BootFile { - back: u64, - stick: u64, - machine: Machine, - phases: Phases, +pub struct BootFile { + pub back: u64, + pub stick: u64, + pub machine: Machine, + pub phases: Phases, } impl BootFile { - fn text(&self) -> String { + pub fn text(&self) -> String { let Self { back, stick, machine, phases } = self; let secs = |s: f64| format!("{s:.3}"); let rows = [ @@ -1968,12 +1957,10 @@ impl BootFile { (WIPE_KEY, secs(phases.wipe)), (FLASH_KEY, secs(phases.flash)), (DD_SECS_KEY, secs(phases.dd_secs)), - (DD_RATE_KEY, phases.dd_rate.clone()), (ENTRY_KEY, secs(phases.entry)), (DOWN_KEY, secs(phases.down)), (READ_LOG_KEY, secs(phases.read_log)), (RAW_LOG_KEY, phases.raw_log.map_or_else(|| NOT_READ.to_string(), secs)), - (JUDGE_KEY, secs(phases.judge)), ]; rows.iter().map(|(name, value)| format!("{name} {value}\n")).collect() } @@ -1991,7 +1978,6 @@ pub fn phases(text: &str) -> Result { wipe: secs(WIPE_KEY)?, flash: secs(FLASH_KEY)?, dd_secs: secs(DD_SECS_KEY)?, - dd_rate: named(DD_RATE_KEY)?, entry: secs(ENTRY_KEY)?, down: secs(DOWN_KEY)?, read_log: secs(READ_LOG_KEY)?, @@ -1999,7 +1985,6 @@ pub fn phases(text: &str) -> Result { NOT_READ => None, _ => Some(secs(RAW_LOG_KEY)?), }, - judge: secs(JUDGE_KEY)?, }) } @@ -2418,12 +2403,10 @@ mod tests { wipe: 0.412, flash: 121.5, dd_secs: 117.234, - dd_rate: "3.7 MB/s".to_string(), entry: 2.25, down: 8.0, read_log: 1.375, raw_log, - judge: 0.002, } } @@ -2444,7 +2427,7 @@ mod tests { BootFile { back: 141, stick: 2, machine: t14(), phases: phased(raw_log) }.text(); assert_eq!(phases(&boot), Ok(phased(raw_log)), "{boot}"); assert_eq!((back_secs(&boot), stick_secs(&boot)), (Some(141), Some(2))); - for line in boot.lines().filter(|line| line.contains("_secs ") || line.starts_with("dd_")) { + for line in boot.lines().filter(|line| line.contains("_secs ")) { if line.starts_with(BACK_SECS) || line.starts_with(STICK_SECS_KEY) { continue; } @@ -2479,7 +2462,7 @@ mod tests { fn the_readback_carries_the_verdict_the_loop_returns() { let dir = toyos_tmpdir::TempDir::new("verdict"); let armed = [alloc_deadline()]; - let boot = || BootFile { back: 40, stick: 0, machine: t14(), phases: phased(None) }; + let boot = "back_secs 40\nstick_secs 0\n"; let written = || { let at = dir.join(READBACK_VERDICT); loop_verdict(&std::fs::read_to_string(&at).expect("the verdict is written")) @@ -2487,7 +2470,7 @@ mod tests { let hung = format!("{}\n{}\n", bootlog::LOADER_FIRST_LINE, bootlog::HUNG_WITHOUT_A_RECORD); assert_eq!( - judge_and_write_readback(&armed, &hung, "", Some(dir.path()), boot()), + judge_and_write_readback(&armed, &hung, "", Some(dir.path()), boot), Err(Refusal::HungWithoutARecord) ); assert_eq!(written(), Err(Refusal::HungWithoutARecord.to_string().trim_end().to_string())); @@ -2510,12 +2493,10 @@ mod tests { bootlog::STOPPING ); assert_eq!( - judge_and_write_readback(&armed, &loader, &log, Some(dir.path()), boot()), + judge_and_write_readback(&armed, &loader, &log, Some(dir.path()), boot), Ok(1151) ); assert_eq!(written(), Ok(())); - let boot = std::fs::read_to_string(dir.join(READBACK_BOOT)).expect("the boot file"); - assert_eq!(phases(&boot).map(|p| p.preamble), Ok(phased(None).preamble)); } #[test] @@ -2831,11 +2812,10 @@ mod tests { fn dd_is_believed_only_where_it_states_a_count() { let real = "44+0 records in\n44+0 records out\n\ 184549376 bytes (185 MB, 176 MiB) copied, 12.3169 s, 15.0 MB/s\n"; - let said = |bytes, secs, rate: &str| Some(DdSaid { bytes, secs, rate: rate.to_string() }); - assert_eq!(dd_said(real), said(184_549_376, 12.3169, "15.0 MB/s")); + assert_eq!(dd_said(real), Some(DdSaid { bytes: 184_549_376, secs: 12.3169 })); let short = "10+0 records in\n10+0 records out\n\ 41943040 bytes (42 MB, 40 MiB) copied, 3.1 s, 13.5 MB/s\n"; - assert_eq!(dd_said(short), said(41_943_040, 3.1, "13.5 MB/s")); + assert_eq!(dd_said(short), Some(DdSaid { bytes: 41_943_040, secs: 3.1 })); assert_eq!(dd_said("44+0 records in\n44+0 records out\n"), None); assert_eq!(dd_said(""), None); assert_eq!(dd_said("41943040 bytes (42 MB, 40 MiB) copied\n"), None); diff --git a/tests/checks.rs b/tests/checks.rs index a1b2ea80492..f48dc76f464 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -957,9 +957,8 @@ mod checks { /// One boot's readback, out of a `loader.log` and a `logkeeper` text. fn readback(label: &str, loader: &str, log: &str) -> metal::Readback { - let boot = "back_secs 50\nstick_secs 0\n"; - metal::Readback::new(label, loader.into(), log.into(), boot) - .expect("a boot file naming both numbers") + metal::Readback::new(label, loader.into(), log.into(), &metal_checks::boot_file()) + .expect("a boot file as the loop writes it") } /// The pass before the handoff, which every `loader.log` opens with. diff --git a/tests/checks/metal.rs b/tests/checks/metal.rs index 9b20fc8c72d..2b950d83cca 100644 --- a/tests/checks/metal.rs +++ b/tests/checks/metal.rs @@ -4,8 +4,8 @@ use super::*; use metal::{Metal, Readback}; use toyos_build::metal::{ - verdict_file, Refusal, BACK_SECS, BIOS_KEY, PRODUCT_KEY, READBACK_BOOT, READBACK_KERNEL, - READBACK_LOADER, READBACK_VERDICT, STICK_SECS_KEY, VENDOR_KEY, + verdict_file, BootFile, Phases, Refusal, READBACK_BOOT, READBACK_KERNEL, READBACK_LOADER, + READBACK_VERDICT, }; use toyos_build::metaltimings::{Machine, Record}; @@ -53,6 +53,21 @@ fn expired_at(reached: i64) -> String { const STARTED: &str = "[2026-09-29 18:22:38 0.050 cpu0 kernel] spawn: /system/bin/logkeeper pid=6\n\ [2026-09-29 18:22:38 0.050 supervisor] supervisor: started logkeeper\n"; +/// A T14 boot's `boot.txt` as the loop writes it. +pub(super) fn boot_file() -> String { + let phases = Phases { + preamble: 3.1, + wipe: 0.4, + flash: 121.5, + dd_secs: 117.2, + entry: 2.3, + down: 8.0, + read_log: 1.4, + raw_log: Some(9.9), + }; + BootFile { back: 40, stick: 0, machine: t14(), phases }.text() +} + /// One boot's readback as the loop writes it. pub(super) fn plant( dir: &Path, @@ -63,14 +78,10 @@ pub(super) fn plant( ) { let home = metal::at(dir, label); fs::create_dir_all(&home).expect("a readback directory"); - let boot = format!( - "{BACK_SECS} 40\n{STICK_SECS_KEY} 0\n{VENDOR_KEY} LENOVO\n{PRODUCT_KEY} 20W0003AMZ\n\ - {BIOS_KEY} N34ET71W (1.71 )\n" - ); for (name, text) in [ (READBACK_LOADER, loader(page)), (READBACK_KERNEL, format!("{STARTED}{kernel}")), - (READBACK_BOOT, boot), + (READBACK_BOOT, boot_file()), (READBACK_VERDICT, verdict_file(verdict)), ] { fs::write(home.join(name), text).expect("a planted file"); diff --git a/tests/common/metal.rs b/tests/common/metal.rs index c0759dcefe3..9f1ce1f8dd5 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -211,9 +211,8 @@ pub struct Readback { pub stick_secs: u64, /// The machine the loop read before the flash. pub machine: Result, - /// Where the loop's wall time went, or why the boot file names no phases: - /// a readback written before the loop timed them. - phases: Result, + /// Where the loop's wall time went. + phases: toyos_build::metal::Phases, /// What was measured on this boot and no owner has taken yet /// ([`Self::taken`]). numbers: RefCell>, @@ -228,6 +227,8 @@ impl Readback { .ok_or_else(|| format!("{label}'s boot file names no `back_secs`: {boot:?}"))?; let stick_secs = toyos_build::metal::stick_secs(boot) .ok_or_else(|| format!("{label}'s boot file names no `stick_secs`: {boot:?}"))?; + let phases = toyos_build::metal::phases(boot) + .map_err(|why| format!("{label}'s boot file {why}: {boot:?}"))?; Ok(Readback { label: label.to_string(), boot_ms: bootlog::boot_millis(&kernel), @@ -238,7 +239,7 @@ impl Readback { stick_secs, machine: toyos_build::metal::machine(boot) .map_err(|why| format!("{label}'s boot file {why}")), - phases: toyos_build::metal::phases(boot), + phases, numbers: RefCell::new(BTreeMap::new()), }) } @@ -1111,10 +1112,7 @@ pub fn judge_readbacks( back.back_secs, back.stick_secs ); - match &back.phases { - Ok(phases) => eprintln!(" phases: {phases}"), - Err(why) => eprintln!(" phases: its boot file {why}"), - } + eprintln!(" phases: {}", back.phases); let panel = back.panel(); if let Some(panel) = panel { eprintln!(