diff --git a/issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md b/issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md new file mode 100644 index 00000000000..abfa2374a27 --- /dev/null +++ b/issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md @@ -0,0 +1,25 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# A ready marker read off the 16550 file can end the boot wait mid-line + +`638L-638r5-whole.log` (`wt/toyos-tight` `59940c452`, "ceilings paid at +1.00x"): `root_candidate_malformed` — "the loader did not refuse a ROOT its +signature does not cover: Slot A: REFUSED, its root is". The loader's line is +"Slot A: REFUSED, its root is not the bytes its signed header names" +(`648-648-whole.log`, the same test passing), so the capture holds the first +half of it. + +`wait_for_ready` (`tests/common/qemu.rs`), for a marker other than the +default, looks for it in the 16550's log file once a second, and that file is +QEMU's, written a byte at a time while the loader prints. `ROOT_REFUSED` is +"Slot A: REFUSED, ", so a read between those bytes and the rest of the line +ends the wait, and `boot_expecting_root_refusal` hands back a line cut short. +Every test booted to a 16550 marker can read one; this is the one that has. +The `aio failed: Input/output error` beside it in the log is +`root_chunk_refused`'s injected bad sector, not this test's. + +**Exit**: the boot wait ends on a whole line; then the row goes. diff --git a/issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md b/issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md new file mode 100644 index 00000000000..1054677390d --- /dev/null +++ b/issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md @@ -0,0 +1,31 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# `iommu_virtio_platform` reads netd's lines off a boot log that ends before them + +Red on four branches that do not touch it, in two words of one race: + +- `650-libcllvm-whole.log` (`wt/toyos-libcllvm`, libc only) and + `634r2-whole.log` (`wt/toyos-sk6` `fb0fc7b56`): `"netd: this claim answers + 4096 bytes of configuration space and refuses every access outside them" + never reached the boot console`. +- `637r2-whole-suite.log` (`wt/toyos-libcxx` `26a4bfbe1`) and + `641f-r3-whole.log` (`wt/toyos-tonefix` `597d60a4e`): `QEMU created 3 virtio + function(s) … and the guest negotiated features with 2`, the missing one + being netd's own function. + +`tests/common/iommu.rs`'s `iommu_virtio_platform` judges `Serial::boot`, the +capture `wait_for_ready` ends at test-runner's `===READY===`. init starts netd +before test-runner, and netd's claim and its feature negotiation come after +netd starts, so test-runner's marker can come first: in the 650 run netd +started at 4.905 and the marker came at 5.098 with neither of netd's lines +before it. + +`wt/toyos-noredlist` (#639) carries a fix, `d773a4306`: each arm waits on the +guest for the daemons' lines it reads. + +**Exit**: the test waits for netd's lines rather than reading them off the +boot log; then the row goes. diff --git a/issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md b/issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md new file mode 100644 index 00000000000..7d67f0d0001 --- /dev/null +++ b/issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md @@ -0,0 +1,25 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# `lan_dhcp_lease` asserts a line its wait does not wait for + +`638L-638r5-whole.log` (`wt/toyos-tight` `59940c452`, "ceilings paid at +1.00x"): `"netd: ready, at most " never reached the the lan boot after "netd: +DHCP: lease "`. The capture ends at the harness's ready marker: + +``` +{1.281 netd} netd: DHCP: lease 10.0.2.15/24 from 10.0.2.2, gateway 10.0.2.2, dns [10.0.2.3], 43 ms after netd came up +{1.290 test-runner} ===READY=== +``` + +`tests/common/lan.rs`'s `lan_dhcp_lease` awaits the lease line, drops the +guest, and then holds the capture to `READY` coming after `LEASE`. The boot +log already carries the lease, so the await returns at once and the capture is +whatever arrived before `===READY===`; netd says it is ready after its lease, +and test-runner's marker can come first. The branch does not touch the test, +netd's lease path or the boot's order, and the race is the same on `main`. + +**Exit**: the test waits for the line it asserts; then the row goes. diff --git a/issues/build/process-stats-exits-101-beside-other-guests.md b/issues/build/process-stats-exits-101-beside-other-guests.md index 3ffe2ddfe30..1a3387b2bd4 100644 --- a/issues/build/process-stats-exits-101-beside-other-guests.md +++ b/issues/build/process-stats-exits-101-beside-other-guests.md @@ -1,5 +1,5 @@ --- -status: open +status: expected-red kind: defect opened: 2026-09-06 --- @@ -23,3 +23,19 @@ Exit: a rate — the same suite run repeatedly with and without a second worktree's build on the host — that says whether this is contention the harness should schedule around or a defect the guest has, and the name is fixed at the cause. + +**2026-10-01: two more, each with its assertion.** `640r3-loaderlines-r3-whole.log` +(`wt/toyos-loaderlines` `6e0d7da82`, "fastest boot 480 ms … ceilings paid at +1.00x") at `process_stats.rs:280`: "a child that parked writing a full +connection charged 0 ns to ipc and 0 ns to pipe". `648-648-whole.log` +(`wt/toyos-proclife1` `60ec86df3`, load average 84) at `process_stats.rs:263`: +"a child that parked reading a connection charged 0 ns to ipc and 0 ns to +pipe". Neither branch touches the test, `WaitClass` or the charge. The +premise both arms read is `roster::await_true` seeing the child's main thread +`BLOCKED`, and nothing ties that park to the connection: a park on anything +else before the child reaches its `read` or `write` satisfies it, the parent +releases, and the connection's wait never parks. The assertion prints two of +the five classes, so which park was charged is not on record. + +Exit: the arm waits for a park it can name as the connection's, or the +assertion prints every class and a red names the park; then the row goes. diff --git a/issues/diagnostics/an-idle-guest-and-a-hung-one-print-the-same-sched-line.md b/issues/diagnostics/an-idle-guest-and-a-hung-one-print-the-same-sched-line.md new file mode 100644 index 00000000000..d8eb1af8072 --- /dev/null +++ b/issues/diagnostics/an-idle-guest-and-a-hung-one-print-the-same-sched-line.md @@ -0,0 +1,26 @@ +--- +status: open +kind: tooling +opened: 2026-10-01 +--- + +# An idle guest and a hung one print the same `sched:` line + +`blockd_serves_partitions`' guest (`650-libcllvm-whole.log`) logged +`sched: cpu=1 ready=0 … parked=4 current=None` every ten seconds for an hour +with its test's end never reported +(`issues/kernel/a-job-that-exited-was-never-reported-ended.md`). The +harness's ceiling read that as a guest still talking. Only the backstop could +end it, at the test's own 600 s once a stopped guest's clock runs at the +wall's rate. + +The line cannot do better. `scheduler::log_health` counts parked threads and +says nothing of what each waits on. A guest waiting out a timer, such as +`lan_no_lease` riding netd's 20 s lease bound or a job asleep under its +deadline, prints the same line as one whose every thread waits on a wake that +will never come. A wait that ended a run on `ready=0` would red the first kind. + +**Exit**: the kernel's idle line also counts the parks that carry a deadline, +and a wait on a guest ends, by name, once every CPU has reported `ready=0` +with no such park for the quiet span. The case it ends early is this file's +sighting. diff --git a/issues/kernel/a-job-that-exited-was-never-reported-ended.md b/issues/kernel/a-job-that-exited-was-never-reported-ended.md new file mode 100644 index 00000000000..136b6aa17b9 --- /dev/null +++ b/issues/kernel/a-job-that-exited-was-never-reported-ended.md @@ -0,0 +1,37 @@ +--- +status: expected-red +kind: defect +opened: 2026-10-01 +--- + +# A job that exited was never reported ended + +`650-libcllvm-whole.log` (`wt/toyos-libcllvm`, userland/libc alone): +`blockd_serves_partitions` — "role bench exited None" after 3559 s, ended by +hand. The bench passed and its process ended: + +``` +{35.962 pid=11 test-runner} blockd_io: PASS bench +[kernel 35.969 cpu0] exit: blockd pid=12 code=137 cpu=1450ms +[kernel 35.978 cpu0 tid=1] exit: test_rs_blockd_io pid=11 code=0 cpu=23247ms +``` + +and `===TEST_END test_rs_blockd_io exit=0===` never came. From 35.978 s to +3540 s the only lines are the kernel's own ten-second `sched:` and `PMM:` +lines, every CPU `ready=0` with its threads parked. test-runner prints the +marker after `child.wait()` (SYS_PROCESS_WAIT, parked on the process object's +watch until `publish_exit` posts it), and its line reaches the console +through logd. So either the wait missed the post, or the marker was written +and logd stopped forwarding: every userland line stops at 35.962, and the +capture cannot tell which. + +logd reads its sources through a poller. #655 (`wt/toyos-winitstall`) found +that a poller can report a source readable again for data already read, and +a blocking read after it then waits forever. That shape would stop logd +silently while the kernel's lines go on. blockd finished its bench and was +killed after it, so the blockd ring-reset ordering #643 fixes is not on this +path. + +**Exit**: the parked thread named — the next sighting needs a blocked-task +dump of a guest whose kernel still logs — and the defect fixed; then the row +goes. diff --git a/issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md b/issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md new file mode 100644 index 00000000000..1396bd70242 --- /dev/null +++ b/issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md @@ -0,0 +1,35 @@ +--- +status: expected-red +kind: defect +opened: 2026-10-01 +--- + +# `redirty_mid_flush` went silent after spawning its child + +`642r2-642-whole.log` (`wt/toyos-proclife` `6e9d6a4df`, "ceilings paid at +1.29x", 5882 s for the run): the guest's last words were the child's spawn, +and nothing came after them — not a line from the test, not the kernel's own +ten-second `sched:` lines: + +``` +[kernel 1.447 cpu1] spawn: /system/bin/test_rs_redirty_mid_flush pid=9 ... +[kernel 1.690 cpu1] spawn: /system/bin/test_rs_redirty_mid_flush pid=10 ... + STALL redirty_mid_flush (4484s) +``` + +The boot is `Profile::Metal` with `test-small-caches`, and `/log` — the file +the two processes race fsyncs on — is the boot stick's, behind xHCI and the +kernel's mass-storage driver. A kernel whose every CPU is inside a call on a +held disk takes no pass and prints nothing +(`issues/kernel/a-held-disk-waits-for-a-pass-no-cpu-takes-when-every-cpu-is-in-a-call-on-it.md`), +and a loaded host is what breaks a stick's transport in its 2000 ms data-phase +budget (`issues/build/smp-ap-hole-and-log-reserve-window-red-under-a-loaded-host.md`); +that is a reading, not a measurement, because the capture holds no kernel line +to confirm it. The test passed in every other whole-suite log kept for this +job, `wt/toyos-proclife` `a8acd2aaa` among them; between that head and +`6e9d6a4df` the branch's own kernel change is two retired-syscall lines, and +the rest is `main`'s merge, which rewrote `drivers/xhci/wait/msc.rs`. + +**Exit**: a sighting whose capture names where every CPU was — the next one +needs the console the guard's verdict carries, or a QMP register dump of a +silent guest — and the defect fixed; then the row goes. diff --git a/kernel/src/arch/x86_64/nmi_gate.rs b/kernel/src/arch/x86_64/nmi_gate.rs index d1d49b24753..d2302d35e4d 100644 --- a/kernel/src/arch/x86_64/nmi_gate.rs +++ b/kernel/src/arch/x86_64/nmi_gate.rs @@ -60,7 +60,7 @@ pub mod hold { /// One turn of the entry's spin, in the budget the word carries above the flags. pub const SPIN: u64 = 1 << 8; /// Turns an ask grants. A count and not a time, because the entry can read no clock without a register; a bound, not a measurement. - pub const TURNS: u64 = 1 << 25; + pub const TURNS: u64 = 1 << 31; /// What the storm stores to ask. pub const ASK: u64 = ASKED | (TURNS * SPIN); } @@ -177,12 +177,12 @@ const ENOUGH: u64 = 64; /// Wait budget per NMI before the next goes out; a delivery that misses it still counts as sent. const DELIVERY_BUDGET_NS: u64 = 100_000; -/// Asks before the spray goes out without a held arrival, and how long each waits for the entry's acknowledgement, and a released victim for its next syscall. Bounds, not measurements. +/// Asks before the spray goes out without a held arrival, and how long each waits for the entry's acknowledgement, and a released victim for its next syscall: a bound on a dead CPU and not on one its host has not scheduled, so `DEAF_CPU`'s. const HOLD_ATTEMPTS: u32 = 10; -const HOLD_ACK_NS: u64 = 100_000_000; +const HOLD_ACK_NS: u64 = crate::time::DEAF_CPU.nanos(); -/// How long the held NMI is waited for: the one delivery whose landing is the premise gets a host's scheduling latency rather than [`DELIVERY_BUDGET_NS`], and the held CPU spins with `IF` clear throughout, which keeps this well under `hardlockup`'s bound. A bound, not a measurement. -const HELD_DELIVERY_NS: u64 = 100_000_000; +/// How long the held NMI is waited for: the one delivery whose landing is the premise gets [`HOLD_ACK_NS`]'s bound on a dead CPU rather than [`DELIVERY_BUDGET_NS`], and the held CPU spins with `IF` clear throughout, which keeps this well under `hardlockup`'s bound. +const HELD_DELIVERY_NS: u64 = HOLD_ACK_NS; // The budget outlasts the storm's longest lawful hold wherever a turn — a `pause`, a locked subtract and a test — takes 3 ns or more, which is an estimate of hardware and not a measurement. const _: () = assert!(hold::TURNS * 3 >= HELD_DELIVERY_NS); diff --git a/kernel/src/time.rs b/kernel/src/time.rs index 092c1559222..1b948b86846 100644 --- a/kernel/src/time.rs +++ b/kernel/src/time.rs @@ -242,9 +242,12 @@ impl fmt::Display for Budget { } } -/// How long the boot CPU waits for an AP it started to echo its token. +/// How long the boot CPU waits for an AP it started to echo its token: a bound +/// on a dead CPU and not on a slow one, so [`DEAF_CPU`]'s span — a vCPU its +/// host has not scheduled is slow, and no CPU that is alive goes that long +/// unheard. pub const AP_START: Budget = Budget::of( - Duration::from_millis(100), + Duration::from_nanos(DEAF_CPU.nanos()), "the machine boots with the CPUs that came up before the first that did not", ); diff --git a/src/redlist.rs b/src/redlist.rs index c08804b93d1..0b6d91f7da6 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -25,6 +25,10 @@ pub struct Disabled { /// Every disabled test. pub const DISABLED: &[Disabled] = &[ + Disabled { + test: "blockd_serves_partitions", + issue: "issues/kernel/a-job-that-exited-was-never-reported-ended.md", + }, Disabled { test: "console_locale_detect", issue: "issues/build/the-console-input-path-can-stop-after-a-ps2-overflow.md", @@ -40,7 +44,15 @@ pub const DISABLED: &[Disabled] = &[ test: "i8042_mouse", issue: "issues/hardware/i8042-mouse-ends-four-packets-short-with-a-clean-exit.md", }, + Disabled { + test: "iommu_virtio_platform", + issue: "issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md", + }, Disabled { test: "kill_while_blocked", issue: "issues/kernel/deferred-release-outlives-its-syscall.md" }, + Disabled { + test: "lan_dhcp_lease", + issue: "issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md", + }, Disabled { test: "log_ring_keeps_the_owners_slots", issue: "issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md", @@ -53,6 +65,7 @@ pub const DISABLED: &[Disabled] = &[ test: "partition_claim_departure", issue: "issues/boot-media/partition-claim-departure-exits-clean-with-none-of-its-refusals-said.md", }, + Disabled { test: "process_stats", issue: "issues/build/process-stats-exits-101-beside-other-guests.md" }, Disabled { test: "quiesce_stops_the_machine", issue: "issues/kernel/a-quiesce-writers-first-pass-outlasts-the-jobs-five-second-spin-up.md", @@ -65,6 +78,14 @@ pub const DISABLED: &[Disabled] = &[ test: "quiesce_wakes_on_the_last_teardown", issue: "issues/kernel/quiesce-wakes-on-the-last-park-gave-up-on-one-thread-beside-the-held-one.md", }, + Disabled { + test: "redirty_mid_flush", + issue: "issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md", + }, + Disabled { + test: "root_candidate_malformed", + issue: "issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md", + }, Disabled { test: "root_chunk_refused_on_a_usb_stick", issue: "issues/boot-media/an-unreadable-sector-on-a-usb-boot-stick-hangs-the-loader-past-the-firmware-watchdog.md", @@ -257,7 +278,7 @@ mod tests { fn a_row_disables_its_whole_name_and_nothing_that_extends_it() { for row in DISABLED { assert_eq!(disabled(DISABLED, row.test), Some(row)); - assert_eq!(disabled(DISABLED, &format!("{}_controls", row.test)), None); + assert_ne!(disabled(DISABLED, &format!("{}_controls", row.test)), Some(row)); } assert_eq!(disabled(DISABLED, ""), None); } diff --git a/tests/checks.rs b/tests/checks.rs index 7012d12945f..d2e7f6f5dc7 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -19,6 +19,8 @@ mod checks { mod screen_checks; #[path = "serial.rs"] mod serial_checks; + #[path = "steal.rs"] + mod steal_checks; #[path = "usb.rs"] mod usb_checks; @@ -102,6 +104,15 @@ mod checks { clock_checks::self_check() } + /// A guest's clock: the arithmetic, the host's accounting it reads, and a + /// process that is gone. + #[test] + fn steal_clock() -> Result<(), String> { + steal_checks::served_self_check()?; + steal_checks::demand_self_check()?; + steal_checks::gone_self_check() + } + /// What a suspend is worth to a verdict, staged rather than reasoned about. /// /// `clock_checks::self_check` gates the detector; this gates what the suite diff --git a/tests/checks/steal.rs b/tests/checks/steal.rs new file mode 100644 index 00000000000..90c2bc60736 --- /dev/null +++ b/tests/checks/steal.rs @@ -0,0 +1,77 @@ +use super::*; +use common::steal::{demand, served, Clock}; + +/// [`served`] against the cases it is the derivation of, staged with no guest. +pub fn served_self_check() -> Result<(), String> { + let ms = Duration::from_millis; + let second = ms(1000); + let cases = [ + ("a guest that wanted nothing had the whole span", ms(0), ms(0), second), + ("light demand lost the moments it waited", ms(100), ms(200), ms(800)), + ("one thread busy throughout had what it ran", ms(150), ms(850), ms(150)), + ("four busy threads served a quarter had a quarter", ms(1000), ms(3000), ms(250)), + ("a guest the host never ran had nothing", ms(0), ms(2000), ms(0)), + ]; + for (what, ran, waited, want) in cases { + let got = served(second, ran, waited); + if got != want { + return Err(format!("{what}: ran {ran:?} and waited {waited:?} of a second gave {got:?}, not {want:?}")); + } + } + Ok(()) +} + +/// The host's accounting read where the clock reads it: this process's own +/// threads, more of them than the host has cores, both run and wait, and the +/// clock that reads them runs slower than the wall while they do. +pub fn demand_self_check() -> Result<(), String> { + let me = std::process::id(); + let (ran_before, waited_before) = demand(me).ok_or("this process has no accounting")?; + let clock = Clock::of(me); + let (wall, moment) = (std::time::Instant::now(), clock.now()); + let spinners = 2 * common::qemu::host_cores(); + let until = std::time::Instant::now() + Duration::from_millis(300); + let threads: Vec<_> = (0..spinners) + .map(|_| { + thread::spawn(move || { + while std::time::Instant::now() < until { + std::hint::spin_loop(); + } + }) + }) + .collect(); + // Read while the spinners stand: an exited thread's share leaves Linux's sum. + while std::time::Instant::now() < until { + thread::sleep(Duration::from_millis(20)); + } + let (ran, waited) = demand(me).ok_or("this process has no accounting")?; + let (had, took) = (clock.since(moment), wall.elapsed()); + for spinner in threads { + spinner.join().map_err(|_| "a spinner panicked")?; + } + let (ran, waited) = (ran.saturating_sub(ran_before), waited.saturating_sub(waited_before)); + if ran.is_zero() || waited.is_zero() { + return Err(format!("{spinners} spinners on {} cores ran {ran:?} and waited {waited:?}", spinners / 2)); + } + if had >= took { + return Err(format!("the clock gave {had:?} of {took:?} to a process whose threads waited {waited:?}")); + } + eprintln!(" [steal] {spinners} spinners ran {ran:?} and waited {waited:?}; the clock gave {had:?} of {took:?}"); + Ok(()) +} + +/// A process that is gone wants nothing, so its clock is the wall's. +pub fn gone_self_check() -> Result<(), String> { + let exe = std::env::current_exe().map_err(|e| format!("this test's own binary: {e}"))?; + let mut child = std::process::Command::new(exe) + .arg("--list") + .stdout(std::process::Stdio::null()) + .spawn() + .map_err(|e| format!("spawn a child that lists and leaves: {e}"))?; + let pid = child.id(); + child.wait().map_err(|e| format!("reap it: {e}"))?; + match demand(pid) { + None => Ok(()), + Some(said) => Err(format!("pid {pid} is reaped and its accounting still answered {said:?}")), + } +} diff --git a/tests/common/devices.rs b/tests/common/devices.rs index 64f91c5fe69..1ef5d8d4acb 100644 --- a/tests/common/devices.rs +++ b/tests/common/devices.rs @@ -88,7 +88,7 @@ pub fn metal_device_probe( ); serial::Serial::boot(&qemu).must_be_clean()?; - let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(WAIT)); + let mut stop = qemu::QmpShutdown::open(&qemu, qemu.budget(WAIT)); let _ = stop.reason(); let tail = qemu.drain_serial(WAIT); let text = format!("{}{tail}", qemu.boot_log()); diff --git a/tests/common/faults.rs b/tests/common/faults.rs index e3805d09ae4..f3376d180e3 100644 --- a/tests/common/faults.rs +++ b/tests/common/faults.rs @@ -472,10 +472,10 @@ pub fn diskless_boot( Ok(()) } -/// How long the guest spins. The storm arms about 190 ms after the spinner -/// starts — a million syscalls at its measured rate — and this is what covers a -/// slow arming plus the storm itself on a shard with company. -const SPIN_SECS: u32 = 10; +/// A guard on the storm and not its length: it arms about 190 ms after the +/// spinner starts — a million syscalls at its measured rate — and the spinner +/// runs until this boot is ended. +const STORM_CEILING: Duration = Duration::from_secs(30); /// The kernel's own summary line, printed last so a drain that ends on it has /// every per-CPU line and the symbolized `rip` under it already. @@ -670,7 +670,7 @@ pub fn syscall_window_nmi( // One traversal each per iteration, so the two counts are of one order. const SAME_ORDER: u64 = 10; - let survived = storm(test_config, c_bins, rust_bins, &["syscall-window-nmi"], SPIN_SECS, |l| { + let survived = storm(test_config, c_bins, rust_bins, &["syscall-window-nmi"], |l| { l.contains(NMI_REPORT) || l.contains(HOLD_EXPIRED) })?; if survived.contains("DOUBLE FAULT") { @@ -925,7 +925,6 @@ pub fn syscall_window_nmi_controls( c_bins, rust_bins, &["syscall-window-nmi", "nmi-without-ist"], - SPIN_SECS, |l| l.contains("Scanning kernel stack") || l.contains(HOLD_EXPIRED), )?; hold_expired(&unfixed)?; @@ -1012,7 +1011,6 @@ pub fn syscall_window_nmi_controls( c_bins, rust_bins, &["syscall-window-nmi", "nmi-nested"], - SPIN_SECS, |l| l.contains("NESTED NMI"), )?; let Some(loud) = nested.lines().find(|l| l.contains("NESTED NMI")) else { @@ -1055,14 +1053,13 @@ fn storm( c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)], params: &'static [&'static str], - secs: u32, done: impl Fn(&str) -> bool, ) -> Result { let mut qemu = QemuInstance::boot_with_options(test_config, c_bins, rust_bins, storm_options(params)); - writeln!(qemu.stdin_mut(), "run test_rs_nmi_window_spin {secs}").expect("write to QEMU stdin"); + writeln!(qemu.stdin_mut(), "run test_rs_nmi_window_spin").expect("write to QEMU stdin"); qemu.flush_stdin(); - Ok(qemu.drain_until(Duration::from_secs(u64::from(secs) + 20), |line| done(line))) + Ok(qemu.drain_until(STORM_CEILING, |line| done(line))) } /// `[ist1] used N of M bytes, ...` diff --git a/tests/common/logstream.rs b/tests/common/logstream.rs index e991aab264d..ac0a3fb9216 100644 --- a/tests/common/logstream.rs +++ b/tests/common/logstream.rs @@ -12,7 +12,7 @@ use std::io::Write; use std::net::{Ipv4Addr, SocketAddr, TcpStream}; use std::path::PathBuf; -use std::time::{Duration, Instant}; +use std::time::Duration; use toyos_build::metaltalk::{Peer, Stream}; @@ -279,10 +279,10 @@ pub fn stalled_reader( // them only on a host fast enough. When `logd` lets each one go is its own // clock's business and no verdict here: the ceiling is the harness's, and // a `logd` that never lets a reader go is a hang it reds. - let deadline = Instant::now() + guest.budget(FLOOD_CEILING); + let deadline = guest.now() + guest.budget(FLOOD_CEILING); let mut floods = 0usize; while seen(&console) < NETWORK_READERS { - let left = deadline.saturating_duration_since(Instant::now()); + let left = deadline.saturating_duration_since(guest.now()); if left.is_zero() { break; } diff --git a/tests/common/mod.rs b/tests/common/mod.rs index 8158bc6d87e..6e7353b3cbe 100644 --- a/tests/common/mod.rs +++ b/tests/common/mod.rs @@ -34,6 +34,8 @@ pub mod screen; pub mod segment; pub mod serial; pub mod ssh; +/// A guest's own time: the wall clock less what the host withheld. +pub mod steal; pub mod storage; pub mod swap; pub mod toybox; diff --git a/tests/common/origin.rs b/tests/common/origin.rs index fcc8cd09531..8757beb8f04 100644 --- a/tests/common/origin.rs +++ b/tests/common/origin.rs @@ -9,7 +9,7 @@ //! every judge of the kernel's records reads through (`bootlog::kernel_records`). use std::net::{Ipv4Addr, UdpSocket}; -use std::time::{Duration, Instant}; +use std::time::Duration; use toyos_build::bootlog; use toyos_build::metaldevices::exit_of; @@ -380,7 +380,7 @@ pub fn resume_meets_its_flush(rust_bins: &[(String, Vec)]) -> Result<(), Str ..Default::default() }, ); - let mut stop = qemu::QmpShutdown::open(guest.qmp_socket(), guest.budget(Duration::from_secs(120))); + let mut stop = qemu::QmpShutdown::open(&guest, guest.budget(Duration::from_secs(120))); let reason = stop.reason(); let tail = guest.drain_serial(Duration::from_secs(20)); drop(guest); @@ -443,7 +443,7 @@ pub fn keeps_the_owners_slots(rust_bins: &[(String, Vec)]) -> Result<(), Str ..Default::default() }, ); - let mut stop = qemu::QmpShutdown::open(guest.qmp_socket(), guest.budget(Duration::from_secs(120))); + let mut stop = qemu::QmpShutdown::open(&guest, guest.budget(Duration::from_secs(120))); let reason = stop.reason(); let tail = guest.drain_serial(Duration::from_secs(20)); drop(guest); @@ -629,12 +629,13 @@ pub fn mdns(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)]) -> Re let mut console = guest.boot_log().to_string(); qemu::await_marker(&mut guest, &mut console, "netd: DHCP: lease ", "netd's lease")?; let mut wire = guest.segment()?; - let deadline = || Instant::now() + Duration::from_secs(10); + let clock = guest.clock(); + let deadline = || clock.now() + Duration::from_secs(10); wire.send(&segment::arp_request(NEIGHBOUR_MAC, NEIGHBOUR, GUEST))?; let until = deadline(); let guest_mac = loop { - let frame = wire.next(until).map_err(|e| format!("no ARP reply for {GUEST:?} in 10 s: {e}"))?; + let frame = wire.next(&clock, until).map_err(|e| format!("no ARP reply for {GUEST:?} in 10 s: {e}"))?; if let Some(mac) = segment::arp_reply_for(&frame, GUEST) { break mac; } @@ -665,7 +666,7 @@ pub fn mdns(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)]) -> Re let until = deadline(); let (answer, to) = loop { - let frame = wire.next(until).map_err(|e| format!("no answer for {host}.local in 10 s: {e}"))?; + let frame = wire.next(&clock, until).map_err(|e| format!("no answer for {host}.local in 10 s: {e}"))?; let Some(udp) = segment::udp_in(&frame) else { continue }; if udp.src != (GUEST, MDNS_PORT) || udp.payload.len() < 2 { continue; diff --git a/tests/common/pkg.rs b/tests/common/pkg.rs index f49c9b2697a..d3db80dc253 100644 --- a/tests/common/pkg.rs +++ b/tests/common/pkg.rs @@ -220,8 +220,8 @@ fn guest_probes(qemu: &mut QemuInstance, log: &mut String) -> Result<(), String> /// compositor's own clock rather than a span of host wall clock: the ceiling /// is a liveness guard and the `windows=1` field is the verdict. fn window_seen(qemu: &mut QemuInstance, log: &mut String, from: usize) -> bool { - let deadline = std::time::Instant::now() + Duration::from_secs(30); - while std::time::Instant::now() < deadline { + let deadline = qemu.now() + Duration::from_secs(30); + while qemu.now() < deadline { log.push_str(&qemu.drain_serial(Duration::from_millis(500))); if log[from.min(log.len())..] .lines() diff --git a/tests/common/power.rs b/tests/common/power.rs index 3e2aa24e99f..34fa7834008 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -55,7 +55,7 @@ pub fn machine_reboot( // 0xcf9 without reading the FADT satisfies this and the stop reason both. boot.must_say("ACPI: reset register SystemIO 0xcf9 <- 0x0f")?; - let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(WAIT)); + let mut stop = qemu::QmpShutdown::open(&qemu, qemu.budget(WAIT)); writeln!(qemu.stdin_mut(), "run reboot").expect("write to QEMU stdin"); qemu.flush_stdin(); @@ -102,7 +102,7 @@ pub fn metal_job_reboot( serial::Serial::boot(&qemu).must_be_clean()?; let console = qemu.boot_log().to_string(); - let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(WAIT)); + let mut stop = qemu::QmpShutdown::open(&qemu, qemu.budget(WAIT)); let reason = stop.reason(); let tail = qemu.drain_serial(WAIT); @@ -270,7 +270,7 @@ fn stopped_boot( ); serial::Serial::boot(&qemu).must_be_clean()?; let booted = qemu.boot_log().to_string(); - let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(WAIT)); + let mut stop = qemu::QmpShutdown::open(&qemu, qemu.budget(WAIT)); let reason = stop.reason(); let tail = qemu.drain_serial(WAIT); let whole = format!("{booted}{tail}"); @@ -475,7 +475,7 @@ pub fn job_deadline_reboots( ); serial::Serial::boot(&qemu).must_be_clean()?; - let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(WAIT)); + let mut stop = qemu::QmpShutdown::open(&qemu, qemu.budget(WAIT)); let reason = stop.reason(); let tail = qemu.drain_serial(WAIT); @@ -525,7 +525,7 @@ pub fn watchdog_resets( boot.must_be_clean()?; boot.must_say(ARMED)?; - let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(WAIT)); + let mut stop = qemu::QmpShutdown::open(&qemu, qemu.budget(WAIT)); let reason = stop.reason(); let tail = qemu.drain_serial(WAIT); @@ -774,7 +774,7 @@ pub fn panic_reboots( /// emitted before its client connected. fn watch_the_bound(qemu: &QemuInstance) -> (qemu::QmpShutdown, Duration) { let budget = qemu.budget(Duration::from_secs(PANIC_FAST_SECS) + RESET_ALLOWANCE); - (qemu::QmpShutdown::open(qemu.qmp_socket(), budget), budget) + (qemu::QmpShutdown::open(qemu, budget), budget) } /// QEMU's own `guest-reset` on `watch`, and the serial the guest wrote after @@ -1095,7 +1095,7 @@ pub fn blackbox_panic_chain( // `blackbox_unclaimed_page`'s to say and is not restated here. let first = serial::Serial::boot(&qemu); // Opened before either reset: events queue on the socket from here. - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); first.must_say(&armed_line())?; // Nothing was harvested on a machine whose RAM QEMU zeroed, so the pass // below is reading this boot's page and not a claim about every boot. @@ -1157,7 +1157,7 @@ pub fn blackbox_done_chain( let case = config.parent().expect("system.toml has a directory"); let mut qemu = QemuInstance::boot_with_options(case, &[], &[], chained(&[])); let first = serial::Serial::boot(&qemu); - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); first.must_say(&armed_line())?; let second = after_the_reset(&mut qemu, bootlog::CHAIN_ENDS_LINE); @@ -1182,7 +1182,7 @@ pub fn transport_break_chain() -> Result<(), String> { let mut qemu = QemuInstance::boot_with_options(case, &[], &[], chained(&["usb-transport-break"])); let first = serial::Serial::boot(&qemu); - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); first.must_say(&armed_line())?; // One capture from the first boot's handoff on, so it is the kernel's @@ -1247,7 +1247,7 @@ pub fn boot_deadline_ends_a_wedge( )?; let mut qemu = QemuInstance::boot_with_options(case, &[], &[], options); let first = serial::Serial::boot(&qemu); - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); first.must_say(&armed_line())?; // One capture from the first boot's handoff to the pass that reports it: @@ -1408,7 +1408,7 @@ pub fn hard_lockup_ends_a_deaf_cpu( )?; let mut qemu = QemuInstance::boot_with_options(case, &[], &[], options); let first = serial::Serial::boot(&qemu); - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); first.must_say(&armed_line())?; // One capture from the first boot's handoff to the pass that reports it: @@ -1580,7 +1580,7 @@ pub fn panic_outlives_the_deadline( let params: &[&str] = &["test-late-panic", "panic-reboot-fast", PANIC_OUTLIVES_DEADLINE]; let mut qemu = QemuInstance::boot_with_options(test_config, c_bins, rust_bins, chained(params)); let first = serial::Serial::boot(&qemu); - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); first.must_say(&armed_line())?; // This capture opens at the first boot's handoff, so it carries that @@ -1783,7 +1783,7 @@ fn the_load_refuses_a_disk_with_no_room() -> Result<(), String> { chained(&["usb-reset-under-load", WEDGE_DEADLINE]), ); let first = serial::Serial::boot(&qemu); - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); first.must_say(&armed_line()).map_err(|why| format!("usb-reset-under-load: {why}"))?; let second = after_the_reset(&mut qemu, bootlog::CHAIN_ENDS_LINE); @@ -1816,7 +1816,7 @@ fn one_wedge_phase(params: &'static [&'static str], phase: Phase) -> Result<(), let (options, kept) = chained_on_a_kept_image(case, params, &format!("{arm}-boot.img"))?; let mut qemu = QemuInstance::boot_with_options(case, &[], &[], options); let first = serial::Serial::boot(&qemu); - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); first.must_say(&armed_line()).map_err(|why| format!("{arm}: {why}"))?; // The account is the page's head, so it is on the console; the wedge's own @@ -2321,7 +2321,7 @@ pub fn blackbox_early_panic_sealed_muted( /// read once. Only the panicking guest writes it, so a poll cannot observe a /// state some other writer put there. fn sealed_state(qemu: &mut QemuInstance, within: Duration) -> Result<(State, Vec), String> { - let deadline = std::time::Instant::now() + within; + let deadline = qemu.now() + within; let mut last = None; loop { let page = qemu.guest_memory(PHYS, toyos_blackbox::BYTES)?; @@ -2334,7 +2334,7 @@ fn sealed_state(qemu: &mut QemuInstance, within: Duration) -> Result<(State, Vec Some((state, _, _, text)) => last = Some((state, text.to_vec())), None => {} } - if std::time::Instant::now() >= deadline { + if qemu.now() >= deadline { return match last { Some(seen) => Ok(seen), None => Err(format!( @@ -2469,7 +2469,7 @@ fn one_reset_path(case: &Path, arm: &ResetPath) -> Result<(), String> { let (path, flushes) = (arm.what, arm.flushes); let mut qemu = QemuInstance::boot_with_options(case, &[], &[], chained(arm.params)); let _ = serial::Serial::boot(&qemu); - let mut resets = qemu::QmpResets::open(qemu.qmp_socket(), qemu.budget(CHAIN_WAIT)); + let mut resets = qemu::QmpResets::open(&qemu, qemu.budget(CHAIN_WAIT)); let after = after_the_reset(&mut qemu, bootlog::CHAIN_ENDS_LINE); let head = toyos_build::metaldevices::QUIESCE_HEAD; diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 7feb27c1729..a560c991a41 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -9,6 +9,7 @@ use std::time::{Duration, Instant}; use std::{fs, thread}; use super::compile; +use super::steal::{self, Moment}; use toyos_build::arch::{Accel, Arch}; use toyos_build::tether::Tether; use toyos_tmpdir::TempDir; @@ -192,54 +193,35 @@ pub fn boot_census() -> (u32, u32, Vec) { pub const DECLARED_KERNEL_BUILDS: [&str; 5] = toyos_build::build::TEST_SUITE_KERNEL_BUILDS; -/// How many guests the phase now running may have up at once. -/// -/// The harness's own wall-clock margins are margins on the *host*, and they were -/// all derived when one guest had it to itself. Four guests is a different -/// machine, so such a margin has to be stated against the regime it runs in -/// rather than widened outright — which is what this multiplies. A serial phase -/// sets it back to 1 and gets the number it always had. -static WIDTH: AtomicU32 = AtomicU32::new(1); - -pub fn set_width(width: u32) { - assert!(width >= 1, "a phase runs at least one guest"); - WIDTH.store(width, Ordering::SeqCst); -} - -/// A liveness ceiling, stated for one guest and paid out for the phase's. +/// A liveness ceiling: the number one guest's author reasoned about, on the +/// host the reasoning was done on, read on the guest's own [`steal::Clock`]. /// /// Every timeout a test hands [`QemuInstance::run_test`] and its relatives is a /// guard against a wedge, never a verdict: the assertion is what the guest /// *said*, and a test whose pass depended on a deadline expiring would be -/// asserting on the host's clock. So the number in the source stays the number -/// its author reasoned about — one guest, this host — and the phase multiplies -/// it, exactly as `wait_for_ready` has multiplied the boot timeout since the -/// parallel phase landed. +/// asserting on the host's clock. Sharing the host is the clock's to take out, +/// as steal, so nothing here scales by the host's load. /// -/// The cost of getting this wrong in the generous direction is that a wedge -/// takes longer to report. The cost in the other direction is a red run that -/// says a guest hung when it was only sharing a machine, which is the failure -/// mode that put the whole shared block in the serial tail. -/// -/// This corrects for width and for how fast the host is, both host-wide facts. -/// It does not correct for a guest being wider than the host — an `smp:8` guest -/// on a four-core runner is oversubscribed and a mostly-serial boot never -/// showed it — which is [`budget_smp`]'s job and [`QemuInstance::budget`]'s -/// default. Callers that hold a guest want that one, so its ceiling reflects -/// the vCPUs it actually asked for. +/// This corrects for how fast the host is. It does not correct for a guest +/// being wider than the host — an `smp:8` guest on a four-core runner is +/// oversubscribed and a mostly-serial boot never showed it — which is +/// [`budget_smp`]'s job and [`QemuInstance::budget`]'s default. Callers that +/// hold a guest want that one, so its ceiling reflects the vCPUs it actually +/// asked for. pub fn budget(one_guest: Duration) -> Duration { let (num, den) = host_scale(); - one_guest * WIDTH.load(Ordering::SeqCst) * num / den + one_guest * num / den } -/// The fastest boot-to-ready this run has seen, in milliseconds. +/// The fastest boot-to-ready this run has seen, in milliseconds of the booting +/// guest's own clock. /// /// A boot is the one piece of guest work every test does and no test asserts on /// — `wait_for_ready`'s own comment names the two exceptions, and both read the /// guest's stamps rather than this clock — so it is a measurement of the host -/// that costs nothing to take. The *fastest* rather than the mean because a boot -/// taken with three other guests up measures the phase; the minimum over a run -/// is the closest this can get to the machine with nothing else on it. +/// that costs nothing to take. The *fastest* rather than the mean because the +/// minimum over a run is the closest this can get to the machine with nothing +/// else on it. static FASTEST_BOOT_MS: AtomicU32 = AtomicU32::new(u32::MAX); /// The same measurement on the host every ceiling in this tree was written for. @@ -259,12 +241,10 @@ fn record_boot(took: Duration) { /// How much slower than the host these ceilings were written on this one is, as /// a fraction so that a 1.4× host is not rounded to 1. /// -/// [`budget`] corrects a ceiling for how many guests share the machine. It never -/// corrected for how fast the machine *is*, and that is the other half of the -/// same mistake: a number reasoned about on an M4 Pro is not a liveness ceiling -/// on a four-core Azure vCPU, it is a verdict about which of the two is running -/// the test. 307 bare timeouts were counted in one CI run and every one of -/// them was that. +/// A number reasoned about on an M4 Pro is not a liveness ceiling on a +/// four-core Azure vCPU, it is a verdict about which of the two is running the +/// test. 307 bare timeouts were counted in one CI run and every one of them was +/// that. /// /// **Only ever upward.** On a faster host the number in the source stands, /// because it is the number its author reasoned about, and a ceiling that shrank @@ -353,7 +333,7 @@ fn oversubscription(smp: u32) -> (u32, u32) { /// [`budget`] widened by a guest's own vCPU oversubscription. /// -/// The guest-agnostic [`budget`] scales by phase width and boot-derived host +/// The guest-agnostic [`budget`] scales by boot-derived host /// speed; this multiplies in `smp/cores` on top, so a wide-SMP guest that a /// mostly-serial boot said little about is given the extra room the derivation /// above says it needs. `smp <= cores` leaves it exactly [`budget`], which is @@ -365,17 +345,10 @@ pub fn budget_smp(one_guest: Duration, smp: u32) -> Duration { /// A liveness guard that watches the guest instead of the host's clock. /// -/// [`budget`] corrects a ceiling for how many guests share the machine, which -/// is the part of "how fast is the host today" the harness knows. It does not -/// know the rest, and a retry loop bounded by elapsed time has that ceiling for -/// a *verdict* the moment the rest moves: a guest that is merely late reports -/// exactly what a wedged one reports. -/// -/// The two are distinguishable and the console is what distinguishes them: a -/// guest still printing is a guest still working. So the ceiling here is time in -/// which **nothing arrived**, and a guest that keeps talking is given as long as -/// it needs. That is the whole idea — no number in this type is a statement -/// about the host. +/// A guest still printing is a guest still working. So the ceiling here is time +/// in which **nothing arrived**, and a guest that keeps talking is given as long +/// as it needs. That is the whole idea — no number in this type is a statement +/// about the host, and both are read on the guest's own [`steal::Clock`]. /// /// `total` is the second half, and it is a wedge guard rather than a verdict /// too. A guest can be stuck and chatty: the compositor prints an interval line @@ -384,33 +357,35 @@ pub fn budget_smp(one_guest: Duration, smp: u32) -> Duration { /// /// The caller owns the capture, so progress is "did it grow" and costs nothing. pub struct Liveness { + clock: steal::Clock, quiet_for: Duration, - last_growth: Instant, + last_growth: Moment, seen: usize, - give_up: Instant, + give_up: Moment, } impl Liveness { - /// `quiet_for` of silence ends the wait, and so does `total` however loud - /// the guest is. - pub fn new(quiet_for: Duration, total: Duration) -> Self { - let now = Instant::now(); - Self { quiet_for, last_growth: now, seen: 0, give_up: now + total } + /// `quiet_for` of `guest`'s silence ends the wait, and so does `total` + /// however loud it is. + pub fn new(guest: &QemuInstance, quiet_for: Duration, total: Duration) -> Self { + let clock = guest.clock(); + let now = clock.now(); + Self { clock, quiet_for, last_growth: now, seen: 0, give_up: now + total } } /// Whether the guest may still be working, given everything it has said. pub fn working(&mut self, capture: &str) -> bool { + let now = self.clock.now(); if capture.len() != self.seen { self.seen = capture.len(); - self.last_growth = Instant::now(); + self.last_growth = now; } - let now = Instant::now(); - now < self.give_up && now.duration_since(self.last_growth) < self.quiet_for + now < self.give_up && now.saturating_duration_since(self.last_growth) < self.quiet_for } /// What ended the wait, for a caller putting it in a failure message. pub fn why(&self) -> &'static str { - if Instant::now() >= self.give_up { + if self.clock.now() >= self.give_up { "it never stopped talking and never got there" } else { "it went quiet" @@ -462,8 +437,8 @@ pub const GUEST_QUIET: Duration = Duration::from_secs(15); /// worse than one that reds. pub const GUEST_WEDGED: Duration = Duration::from_secs(300); -pub fn guest_liveness() -> Liveness { - Liveness::new(GUEST_QUIET, GUEST_WEDGED) +pub fn guest_liveness(guest: &QemuInstance) -> Liveness { + Liveness::new(guest, GUEST_QUIET, GUEST_WEDGED) } /// A kernel line without its `[kernel cpu] ` stamp. @@ -572,8 +547,8 @@ impl std::fmt::Display for WaitVerdict { /// `halt_all_cpus` stops every CPU, so the guest goes silent and the ceiling /// expires on a machine that has been dead since the panic. /// -/// **The wall clock is not the wedge; silence is.** A test's `ceiling` is the -/// budgeted wall clock (`budget_smp`-scaled, so it already carries #256's +/// **The wall clock is not the wedge; silence is.** A test's `ceiling` is its +/// budget (`budget_smp`-scaled, so it already carries #256's /// `vcpus/cores` oversubscription widening), and until this it ended the wait /// the instant it passed — so a merely-slow guest reported exactly what a wedged /// one did. `launcher_refusals` was killed at `192s "still talking 1s ago"` on a @@ -649,7 +624,7 @@ pub fn await_guest( ) -> Result<(), String> { // Where this wait's own evidence starts. let from = log.len(); - let mut live = guest_liveness(); + let mut live = guest_liveness(qemu); while !done(log) && live.working(log) { let more = qemu.drain_serial(Duration::from_millis(200)); log.push_str(&more); @@ -770,7 +745,7 @@ pub fn await_reset( refused: &[&str], ) -> Result<(), String> { let from = log.len(); - let mut live = guest_liveness(); + let mut live = guest_liveness(qemu); loop { if refused.iter().any(|line| log[from..].contains(line)) { return Ok(()); @@ -2422,6 +2397,7 @@ pub struct QemuInstance { /// The test binaries this boot put on ROOT, by the name `run` takes; `None` /// for a staged image, whose contents its builder chose. carried: Option>, + clock: steal::Clock, } /// The test binaries one boot carries onto ROOT, out of the suite's catalogue. @@ -3047,10 +3023,10 @@ impl QemuInstance { interval: Duration, done: impl Fn(&super::screen::Ppm) -> bool, ) -> super::screen::Ppm { - let deadline = Instant::now() + budget_smp(timeout, self.smp); + let deadline = self.now() + budget_smp(timeout, self.smp); loop { let dump = self.screendump(); - if done(&dump) || Instant::now() >= deadline { + if done(&dump) || self.now() >= deadline { return dump; } thread::sleep(interval); @@ -3089,7 +3065,7 @@ impl QemuInstance { done: impl Fn(&super::screen::Ppm) -> bool, ) -> super::screen::Ppm { let ceiling = budget_smp(timeout, self.smp); - let start = Instant::now(); + let start = self.now(); let mut last_change = start; let mut prev: Option> = None; loop { @@ -3097,16 +3073,16 @@ impl QemuInstance { if done(&dump) { return dump; } - let now = Instant::now(); + let now = self.now(); if prev.as_deref() != Some(dump.pixels.as_slice()) { last_change = now; prev = Some(dump.pixels.clone()); } if ceiling_verdict( None, - now.duration_since(start), + now.saturating_duration_since(start), ceiling, - now.duration_since(last_change), + now.saturating_duration_since(last_change), 0, ) .is_some() @@ -3121,6 +3097,15 @@ impl QemuInstance { self.child.id() } + /// This guest's own clock, which every wait on it reads. + pub fn clock(&self) -> steal::Clock { + self.clock.clone() + } + + pub fn now(&self) -> Moment { + self.clock.now() + } + /// Every console line the guest printed before the ready marker. /// /// The kernel's own boot lines sit in the log ring until the scheduler @@ -3162,19 +3147,19 @@ impl QemuInstance { /// A file QEMU finishes only at its exit is whole once this answers, and is /// still there until this instance is dropped. pub fn await_exit(&mut self, by: Duration) -> Result { - let deadline = Instant::now() + by; + let deadline = self.now() + by; let mut said = String::new(); loop { - let left = deadline.checked_duration_since(Instant::now()).unwrap_or_default(); + let Some(left) = deadline.checked_duration_since(self.now()) else { + return Err(format!("QEMU had not exited {} s after it was asked to\n{said}", by.as_secs())); + }; match self.rx.recv_timeout(left) { Ok(line) => { said.push_str(&line); said.push('\n'); } Err(RecvTimeoutError::Disconnected) => break, - Err(RecvTimeoutError::Timeout) => { - return Err(format!("QEMU had not exited {} s after it was asked to\n{said}", by.as_secs())) - } + Err(RecvTimeoutError::Timeout) => {} } } let status = self.child.wait().map_err(|e| format!("QEMU could not be waited for: {e}"))?; @@ -3216,13 +3201,9 @@ impl QemuInstance { self.stdin.flush().expect("Failed to flush QEMU stdin"); } - /// Keep collecting serial output for `dur` after a test has returned. - /// **Not scaled by the width**, and it is the one duration in this file that - /// is not. Callers use it to *pace* — "let the guest run for 400 ms and tell - /// me what it said" — so multiplying it does not buy a slow guest more room, - /// it buys the test a longer sleep. `metal_sim_pointer_churn` has - /// twenty-four of these; scaled, they made it an 86 s job at width 8 and the - /// critical path of the whole phase. + /// Keep collecting serial output for `dur` of the guest's time after a test + /// has returned. Callers use it to *pace* — "let the guest run for 400 ms + /// and tell me what it said" — so it is not a ceiling and does not scale. pub fn drain_serial(&mut self, dur: Duration) -> String { self.drain_for(dur, |_| false) } @@ -3244,10 +3225,10 @@ impl QemuInstance { } fn drain_for(&mut self, dur: Duration, line: impl Fn(&str) -> bool) -> String { - let deadline = Instant::now() + dur; + let deadline = self.now() + dur; let mut out = String::new(); loop { - let Some(remaining) = deadline.checked_duration_since(Instant::now()) else { + let Some(remaining) = deadline.checked_duration_since(self.now()) else { return out; }; match self.rx.recv_timeout(remaining) { @@ -3258,7 +3239,7 @@ impl QemuInstance { return out; } } - Err(RecvTimeoutError::Timeout) => return out, + Err(RecvTimeoutError::Timeout) => {} Err(RecvTimeoutError::Disconnected) => return out, } } @@ -3269,15 +3250,15 @@ impl QemuInstance { /// A console is a stream and this consumes it: every line up to and /// including the marker is taken from whatever reads next. pub fn wait_for_console(&mut self, marker: &str, timeout: Duration) -> bool { - let deadline = Instant::now() + budget_smp(timeout, self.smp); + let deadline = self.now() + budget_smp(timeout, self.smp); loop { - let Some(left) = deadline.checked_duration_since(Instant::now()) else { + let Some(left) = deadline.checked_duration_since(self.now()) else { return false; }; match self.rx.recv_timeout(left) { Ok(line) if line.contains(marker) => return true, - Ok(_) => continue, - Err(_) => return false, + Ok(_) | Err(RecvTimeoutError::Timeout) => continue, + Err(RecvTimeoutError::Disconnected) => return false, } } } @@ -3374,7 +3355,7 @@ impl QemuInstance { } let timeout = budget_smp(timeout, self.smp); - let start = Instant::now(); + let start = self.now(); let mut stdout = String::new(); let mut serial = String::new(); // Every line seen before this test announced itself. Kept, never @@ -3384,7 +3365,7 @@ impl QemuInstance { // **Which of the two things the ceiling caught**: a guest that has said // nothing for [`GUEST_QUIET`] has stopped, and one still talking at the // ceiling has not. - let mut last_line = Instant::now(); + let mut last_line = self.now(); let mut lines = 0usize; // **The line on which the kernel said it was dying, if it ever did.** // The first one only: a crash report's later lines carry the spelling @@ -3397,9 +3378,9 @@ impl QemuInstance { loop { if let Some(error) = ceiling_verdict( dying.as_deref(), - start.elapsed(), + self.clock.since(start), timeout, - last_line.elapsed(), + self.clock.since(last_line), lines, ) { // The window in the order the guest wrote it: `before` holds @@ -3421,7 +3402,7 @@ impl QemuInstance { match self.rx.recv_timeout(Duration::from_millis(100)) { Ok(line) => { - last_line = Instant::now(); + last_line = self.now(); lines += 1; step(self.sockets.qmp.as_deref(), &line); if dying.is_none() @@ -3573,11 +3554,30 @@ struct Qmp { pending: Vec, } +/// How long QEMU's monitor has to answer a command: QEMU's own bound, not a +/// guest's. +const QMP_REPLY: Duration = Duration::from_secs(20); + impl Qmp { fn connect(socket: &Path) -> Self { Self::connect_while(socket, || {}) } + /// One read of what QEMU sent into `pending`, or of nothing inside the + /// socket's poll; `false` once the socket has ended. + fn take(&mut self) -> bool { + let mut buf = [0u8; 4096]; + match self.stream.read(&mut buf) { + Ok(0) => false, + Ok(n) => { + self.pending.extend_from_slice(&buf[..n]); + true + } + Err(e) if matches!(e.kind(), std::io::ErrorKind::WouldBlock | std::io::ErrorKind::TimedOut) => true, + Err(_) => false, + } + } + /// `on_retry` runs between connect attempts. It is where a caller holding /// the QEMU process turns "connection refused" into "QEMU is gone, and /// here is its exit status" — see [`QemuInstance::screendump`]. @@ -3598,7 +3598,7 @@ impl Qmp { } } }; - stream.set_read_timeout(Some(Duration::from_secs(20))).unwrap(); + stream.set_read_timeout(Some(QMP_REPLY)).unwrap(); let mut qmp = Self { stream, pending: Vec::new() }; qmp.await_reply("\"QMP\""); qmp.execute("{\"execute\":\"qmp_capabilities\"}"); @@ -3625,7 +3625,7 @@ impl Qmp { ); } assert!( - start.elapsed() < Duration::from_secs(20), + start.elapsed() < QMP_REPLY, "qmp: no {want} in reply: {}", String::from_utf8_lossy(&self.pending) ); @@ -3684,33 +3684,19 @@ impl Qmp { /// QEMU's own account of why a guest stopped, off the `SHUTDOWN` event. Held /// open across the stop: the event is emitted once and QEMU exits behind it, so /// a connection opened afterwards finds nothing. -pub struct QmpShutdown(Qmp); +pub struct QmpShutdown(EventWait); impl QmpShutdown { - /// `budget` bounds the wait and is set here, while the peer is still there - /// to accept it: macOS refuses a `setsockopt` on a socket already closed. - pub fn open(socket: &Path, budget: Duration) -> Self { - let qmp = Qmp::connect(socket); - qmp.stream.set_read_timeout(Some(budget)).expect("qmp: the shutdown-event budget"); - Self(qmp) + /// `budget` bounds the wait, on `guest`'s clock. + pub fn open(guest: &QemuInstance, budget: Duration) -> Self { + Self(EventWait::open(guest, budget)) } /// The `reason` the `SHUTDOWN` event names — `guest-reset`, /// `guest-shutdown`, `host-signal` — or `None` if the guest never stopped. pub fn reason(&mut self) -> Option { - use std::io::Read; - let qmp = &mut self.0; - loop { - if let Some(reason) = shutdown_reason(&qmp.pending) { - return Some(reason); - } - let mut buf = [0u8; 4096]; - match qmp.stream.read(&mut buf) { - // Budget spent, or the socket ended: what it had is in `pending`. - Ok(0) | Err(_) => return shutdown_reason(&qmp.pending), - Ok(n) => qmp.pending.extend_from_slice(&buf[..n]), - } - } + self.0.until(|pending| shutdown_reason(pending).is_some()); + shutdown_reason(&self.0.qmp.pending) } } @@ -3722,15 +3708,12 @@ impl QmpShutdown { /// keeps going emits `RESET` instead, and the *count* is what a chain is read /// by — one is a kernel that reset itself, two is a loader pass that ended the /// chain by resetting rather than returning to the boot manager. -pub struct QmpResets(Qmp); +pub struct QmpResets(EventWait); impl QmpResets { - /// `budget` bounds every wait and is set here, while the peer is still there - /// to accept it — as [`QmpShutdown::open`], and for the same reason. - pub fn open(socket: &Path, budget: Duration) -> Self { - let qmp = Qmp::connect(socket); - qmp.stream.set_read_timeout(Some(budget)).expect("qmp: the reset-event budget"); - Self(qmp) + /// `budget` bounds every wait, on `guest`'s clock. + pub fn open(guest: &QemuInstance, budget: Duration) -> Self { + Self(EventWait::open(guest, budget)) } /// How many guest resets have arrived, waiting for up to `want` of them. @@ -3738,20 +3721,36 @@ impl QmpResets { /// Events queue on the socket from the moment it is connected, so a caller /// that opened this before the guest reset reads them here whenever it asks. pub fn seen(&mut self, want: usize) -> usize { - use std::io::Read; - let qmp = &mut self.0; - loop { - let seen = guest_resets(&qmp.pending); - if seen >= want { - return seen; - } - let mut buf = [0u8; 4096]; - match qmp.stream.read(&mut buf) { - // Budget spent, or the socket ended: what it had is in `pending`. - Ok(0) | Err(_) => return guest_resets(&qmp.pending), - Ok(n) => qmp.pending.extend_from_slice(&buf[..n]), - } - } + self.0.until(|pending| guest_resets(pending) >= want); + guest_resets(&self.0.qmp.pending) + } +} + +/// A QMP connection read for events, each wait bounded on its guest's clock. +struct EventWait { + qmp: Qmp, + clock: steal::Clock, + budget: Duration, +} + +/// How long one read of an event stream blocks before the wait asks its +/// guest's clock again. +const EVENT_POLL: Duration = Duration::from_millis(200); + +impl EventWait { + /// The poll is set here, while the peer is still there to accept it: + /// macOS refuses a `setsockopt` on a socket already closed. + fn open(guest: &QemuInstance, budget: Duration) -> Self { + let qmp = Qmp::connect(guest.qmp_socket()); + qmp.stream.set_read_timeout(Some(EVENT_POLL)).expect("qmp: the event stream's poll"); + Self { qmp, clock: guest.clock(), budget } + } + + /// Read events into `pending` until `done` holds of them, the budget is + /// spent, or the socket ends. + fn until(&mut self, done: impl Fn(&[u8]) -> bool) { + let began = self.clock.now(); + while !done(&self.qmp.pending) && self.clock.since(began) < self.budget && self.qmp.take() {} } } @@ -3759,45 +3758,42 @@ impl QmpResets { /// reset pauses it with its memory — the black box — as the reset left it, so /// a test can change what the next pass reads off the disk after the kernel's /// last write and before the loader's first read, and then let it go. -pub struct QmpHold(Qmp); +pub struct QmpHold { + qmp: Qmp, + clock: steal::Clock, +} impl QmpHold { - /// The guest's next reset pauses the machine instead. - pub fn arm(socket: &Path) -> Self { - let mut qmp = Qmp::connect(socket); + /// `guest`'s next reset pauses the machine instead. + pub fn arm(guest: &QemuInstance) -> Self { + let mut qmp = Qmp::connect(guest.qmp_socket()); qmp.execute("{\"execute\":\"set-action\",\"arguments\":{\"reboot\":\"shutdown\",\"shutdown\":\"pause\"}}"); - Self(qmp) + Self { qmp, clock: guest.clock() } } - /// Wait up to `budget` for the machine to stop at its reset. + /// Wait up to `budget` of the guest's clock for the machine to stop at its + /// reset. pub fn held(&mut self, budget: Duration) -> Result<(), String> { - use std::io::Read; - let qmp = &mut self.0; - qmp.stream.set_read_timeout(Some(budget)).map_err(|e| format!("qmp: the hold's budget: {e}"))?; - let began = Instant::now(); - loop { - if qmp.pending.windows(6).any(|w| w == b"\"STOP\"") { - return Ok(()); - } - let mut buf = [0u8; 4096]; - match qmp.stream.read(&mut buf) { - Ok(n) if n > 0 && began.elapsed() < budget => qmp.pending.extend_from_slice(&buf[..n]), - _ => { - return Err(format!( - "the machine did not stop at a reset within {} s: {}", - budget.as_secs(), - String::from_utf8_lossy(&qmp.pending) - )) - } - } + let qmp = &mut self.qmp; + qmp.stream.set_read_timeout(Some(EVENT_POLL)).map_err(|e| format!("qmp: the hold's poll: {e}"))?; + let began = self.clock.now(); + let stopped = |pending: &[u8]| pending.windows(6).any(|w| w == b"\"STOP\""); + while !stopped(&qmp.pending) && self.clock.since(began) < budget && qmp.take() {} + if !stopped(&qmp.pending) { + return Err(format!( + "the machine did not stop at a reset within {} s: {}", + budget.as_secs(), + String::from_utf8_lossy(&qmp.pending) + )); } + qmp.stream.set_read_timeout(Some(QMP_REPLY)).map_err(|e| format!("qmp: the reply bound: {e}")) } /// Take the held reset and run on, taking every later reset as before. pub fn release(mut self) { - self.0.execute("{\"execute\":\"set-action\",\"arguments\":{\"reboot\":\"reset\",\"shutdown\":\"poweroff\"}}"); - self.0.execute("{\"execute\":\"system_reset\"}"); - self.0.execute("{\"execute\":\"cont\"}"); + self.qmp.execute("{\"execute\":\"set-action\",\"arguments\":{\"reboot\":\"reset\",\"shutdown\":\"poweroff\"}}"); + self.qmp.execute("{\"execute\":\"system_reset\"}"); + self.qmp.execute("{\"execute\":\"cont\"}"); } } @@ -4637,6 +4633,7 @@ fn spawn_and_wait_ready(mut qemu: Command, options: &BootOptions, files: Files) eprintln!("[qemu {seq}] Launching QEMU..."); } let (mut child, tether) = toyos_build::tether::spawn(qemu).expect("Failed to launch QEMU"); + let clock = steal::Clock::of(child.id()); let stdin: Box = match input { Some(fifo) => Box::new(fifo), @@ -4710,7 +4707,7 @@ fn spawn_and_wait_ready(mut qemu: Command, options: &BootOptions, files: Files) let boot_log = if options.mute { String::new() } else { - wait_for_ready(&mut child, &rx, options, &uart_log) + wait_for_ready(&mut child, &rx, options, &uart_log, &clock) }; QemuInstance { @@ -4731,6 +4728,7 @@ fn spawn_and_wait_ready(mut qemu: Command, options: &BootOptions, files: Files) smp: options.smp, ssh_port: options.ssh_port, carried, + clock, } } @@ -4770,18 +4768,13 @@ fn wait_for_ready( rx: &Receiver, options: &BootOptions, uart_log: &Path, + clock: &steal::Clock, ) -> String { let no_timeout = options.debug_wait; let ready = options.ready_marker; let panic_aborts = ready == DEFAULT_READY; - // Ten seconds per guest this phase may have up, and never fewer than two - // guests' worth — the tree runs 15-25 suites a day across several agents, - // so one guest on a quiet host stopped being - // the regime some time before this did. Measured on 2026-08-03 with other - // agents building: two boots exceeded the flat ten seconds, one of them in a - // phase running a single guest. - // - // A wedge costs that much longer to report and nothing else. + // Twenty seconds of the guest's own clock: what a phase of one guest gave + // it, and sharing the host is the clock's to take out. // // Scaled by the host too, and the first boot of a run is the one that // cannot be: nothing has been measured yet, so it gets the flat number and @@ -4796,12 +4789,11 @@ fn wait_for_ready( // of `vcpus/cores`; on a host with a core per vCPU it multiplies by one. let (num, den) = host_scale(); let (onum, oden) = oversubscription(options.smp); - let boot_timeout = - Duration::from_secs(10) * WIDTH.load(Ordering::SeqCst).max(2) * num / den * onum / oden; - let start = Instant::now(); + let boot_timeout = Duration::from_secs(20) * num / den * onum / oden; + let start = clock.now(); let mut seen = String::new(); loop { - if !no_timeout && start.elapsed() > boot_timeout { + if !no_timeout && clock.since(start) > boot_timeout { let _ = child.kill(); // With what it did say. A timeout that discards the console is the // one failure in this harness that arrives with no evidence at all, @@ -4884,6 +4876,6 @@ fn wait_for_ready( } } } - record_boot(start.elapsed()); + record_boot(clock.since(start)); seen } diff --git a/tests/common/segment.rs b/tests/common/segment.rs index 4716b3f9c2e..0acd31ac63e 100644 --- a/tests/common/segment.rs +++ b/tests/common/segment.rs @@ -14,10 +14,11 @@ use std::io::{Read, Write}; use std::os::unix::net::UnixStream; use std::path::{Path, PathBuf}; use std::sync::mpsc::{self, Receiver, RecvTimeoutError}; -use std::time::Instant; use toyos_build::icmp::checksum; +use super::steal::{Clock, Moment}; + /// The two sockets QEMU serves the segment on, in the socket directory of the /// [`super::qemu::QemuInstance`] that booted with them. #[derive(Debug)] @@ -87,13 +88,18 @@ impl Segment { .map_err(|e| format!("put a frame on the segment: {e}")) } - /// The next frame the guest sends, before `deadline`. - pub fn next(&self, deadline: Instant) -> Result, String> { - let left = deadline.saturating_duration_since(Instant::now()); - self.frames.recv_timeout(left).map_err(|e| match e { - RecvTimeoutError::Timeout => "the guest sent no frame in time".to_string(), - RecvTimeoutError::Disconnected => "QEMU closed the segment".to_string(), - }) + /// The next frame the guest sends, before `deadline` on its `clock`. + pub fn next(&self, clock: &Clock, deadline: Moment) -> Result, String> { + loop { + let Some(left) = deadline.checked_duration_since(clock.now()) else { + return Err("the guest sent no frame in time".to_string()); + }; + match self.frames.recv_timeout(left) { + Ok(frame) => return Ok(frame), + Err(RecvTimeoutError::Timeout) => {} + Err(RecvTimeoutError::Disconnected) => return Err("QEMU closed the segment".to_string()), + } + } } } diff --git a/tests/common/steal.rs b/tests/common/steal.rs new file mode 100644 index 00000000000..a5f38e4d3c4 --- /dev/null +++ b/tests/common/steal.rs @@ -0,0 +1,207 @@ +//! A guest's own time: the host's wall clock with every stretch the host kept +//! the guest's QEMU waiting for a CPU taken out. +//! +//! A wait on a guest is a hang detector, and a hang is a guest that does not +//! progress while it has the host. A loaded host stretches a guest's work by +//! however long its threads sat runnable and unserved, and a wait on the wall +//! clock reads that stretch as a hang; this clock does not run across it. What +//! the host withheld is steal, as a hypervisor accounts it to a vCPU. A guest +//! that wanted nothing had nothing withheld, so an idle guest's clock is the +//! wall's, and so is a stopped one's: a guest that stopped is called stopped on +//! time however loaded the host is. + +use std::ops::Add; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Arc, Mutex, PoisonError}; +use std::time::{Duration, Instant}; + +/// A point on one guest's [`Clock`]; two guests' moments are not comparable. +#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Debug)] +pub struct Moment(Duration); + +impl Moment { + pub fn checked_duration_since(self, earlier: Moment) -> Option { + self.0.checked_sub(earlier.0) + } + + pub fn saturating_duration_since(self, earlier: Moment) -> Duration { + self.0.saturating_sub(earlier.0) + } +} + +impl Add for Moment { + type Output = Moment; + + fn add(self, span: Duration) -> Moment { + Moment(self.0 + span) + } +} + +/// The share of `wall` a guest had, given the time its threads spent on a CPU +/// (`ran`) and runnable waiting for one (`waited`) across it. +/// +/// Demand under one thread's worth lost the moments it waited and nothing +/// else; demand over it had the share of itself the host served. +pub fn served(wall: Duration, ran: Duration, waited: Duration) -> Duration { + let wanted = ran + waited; + if wanted <= wall { + return wall.saturating_sub(waited); + } + let share = wall.as_nanos() * ran.as_nanos() / wanted.as_nanos(); + Duration::from_nanos(u64::try_from(share).expect("a share of a wall span fits the span")) +} + +/// One guest's clock, reading its QEMU process; clones read the same clock. +#[derive(Clone)] +pub struct Clock(Arc>); + +struct Reading { + pid: u32, + wall: Instant, + ran: Duration, + waited: Duration, + had: Duration, +} + +/// The least wall time between two readings of a process's accounting: a +/// console flood reads the clock once a line. +const RESAMPLE: Duration = Duration::from_millis(5); + +/// Every guest's read spans this run, in nanoseconds: the wall clock, and what +/// of it the guest had. +static WALL_NS: AtomicU64 = AtomicU64::new(0); +static HAD_NS: AtomicU64 = AtomicU64::new(0); + +/// The wall clock this run's guests' waits read across, and what of it they +/// had: the host's load, measured where it fell, which a fastest boot taken at +/// the run's quietest moment cannot see. `None` before any guest's clock has +/// been read. +pub fn run_share() -> Option<(Duration, Duration)> { + let wall = WALL_NS.load(Ordering::Relaxed); + (wall != 0).then(|| (Duration::from_nanos(wall), Duration::from_nanos(HAD_NS.load(Ordering::Relaxed)))) +} + +impl Clock { + /// The clock of process `pid`, at zero now. + pub fn of(pid: u32) -> Self { + let (ran, waited) = demand(pid).unwrap_or_default(); + let reading = Reading { pid, wall: Instant::now(), ran, waited, had: Duration::ZERO }; + Self(Arc::new(Mutex::new(reading))) + } + + pub fn now(&self) -> Moment { + let mut reading = self.0.lock().unwrap_or_else(PoisonError::into_inner); + let wall = Instant::now(); + let span = wall.duration_since(reading.wall); + if span < RESAMPLE { + return Moment(reading.had); + } + // A process that is gone wants nothing, so the span was all its own. + let had = match demand(reading.pid) { + Some((ran, waited)) => { + let had = + served(span, ran.saturating_sub(reading.ran), waited.saturating_sub(reading.waited)); + (reading.ran, reading.waited) = (ran, waited); + had + } + None => span, + }; + reading.wall = wall; + reading.had += had; + WALL_NS.fetch_add(u64::try_from(span.as_nanos()).expect("a span fits u64 nanoseconds"), Ordering::Relaxed); + HAD_NS.fetch_add(u64::try_from(had.as_nanos()).expect("a span fits u64 nanoseconds"), Ordering::Relaxed); + Moment(reading.had) + } + + /// Time this guest has had since `earlier`. + pub fn since(&self, earlier: Moment) -> Duration { + self.now().saturating_duration_since(earlier) + } +} + +/// What process `pid`'s threads have spent on a CPU and runnable waiting for +/// one, summed over its life; `None` once the process is gone. +#[cfg(target_os = "macos")] +pub fn demand(pid: u32) -> Option<(Duration, Duration)> { + // SAFETY: integers and a byte array, for which all zeroes is a value. + let mut info: libc::rusage_info_v4 = unsafe { std::mem::zeroed() }; + // SAFETY: `info` is the `rusage_info_v4` that `RUSAGE_INFO_V4` names, and + // the call writes that struct and nothing past it. + let answered = unsafe { + libc::proc_pid_rusage( + pid as libc::c_int, + libc::RUSAGE_INFO_V4, + (&mut info as *mut libc::rusage_info_v4).cast(), + ) + }; + if answered != 0 { + let error = std::io::Error::last_os_error(); + if error.raw_os_error() == Some(libc::ESRCH) { + return None; + } + panic!("proc_pid_rusage({pid}): {error}"); + } + let ticks = |count: u64| Duration::from_nanos(mach_nanos(count)); + Some((ticks(info.ri_user_time + info.ri_system_time), ticks(info.ri_runnable_time))) +} + +/// Mach absolute time units, which `proc_pid_rusage` counts in, as nanoseconds. +/// +/// `libc` deprecates its binding of the timebase for the `mach2` crate's +/// binding of the same call, which this tree does not take. +#[cfg(target_os = "macos")] +#[allow(deprecated)] +fn mach_nanos(count: u64) -> u64 { + static TIMEBASE: std::sync::OnceLock<(u64, u64)> = std::sync::OnceLock::new(); + let (numer, denom) = *TIMEBASE.get_or_init(|| { + let mut base = libc::mach_timebase_info { numer: 0, denom: 0 }; + // SAFETY: one out-parameter the call fills. + let answered = unsafe { libc::mach_timebase_info(&mut base) }; + assert_eq!(answered, 0, "mach_timebase_info answered {answered}"); + (u64::from(base.numer), u64::from(base.denom)) + }); + u64::try_from(u128::from(count) * u128::from(numer) / u128::from(denom)) + .expect("a process's CPU time in nanoseconds fits a u64") +} + +/// The same, summed over `/proc//task/*/schedstat`: nanoseconds on a CPU, +/// then nanoseconds waiting on a run queue. A thread that has exited takes its +/// share with it, which [`Clock::now`] reads as no demand. +#[cfg(target_os = "linux")] +pub fn demand(pid: u32) -> Option<(Duration, Duration)> { + use std::io::ErrorKind::NotFound; + // Without it every thread's file is absent and a starved guest reads as one + // that wanted nothing. + assert!( + std::path::Path::new("/proc/self/schedstat").is_file(), + "this kernel keeps no per-task schedstat (CONFIG_SCHED_INFO), which a guest's clock reads" + ); + let tasks = match std::fs::read_dir(format!("/proc/{pid}/task")) { + Ok(tasks) => tasks, + Err(e) if e.kind() == NotFound => return None, + Err(e) => panic!("/proc/{pid}/task: {e}"), + }; + let (mut ran, mut waited) = (0u64, 0u64); + for task in tasks { + let path = task.unwrap_or_else(|e| panic!("/proc/{pid}/task: {e}")).path().join("schedstat"); + let text = match std::fs::read_to_string(&path) { + Ok(text) => text, + Err(e) if e.kind() == NotFound => continue, + Err(e) => panic!("{}: {e}", path.display()), + }; + let mut fields = text.split_whitespace().map(|field| { + field.parse::().unwrap_or_else(|e| panic!("{}: {field:?}: {e}", path.display())) + }); + let (Some(on_cpu), Some(queued)) = (fields.next(), fields.next()) else { + panic!("{}: {text:?} is not ` `", path.display()); + }; + ran += on_cpu; + waited += queued; + } + Some((Duration::from_nanos(ran), Duration::from_nanos(waited))) +} + +#[cfg(not(any(target_os = "macos", target_os = "linux")))] +pub fn demand(_: u32) -> Option<(Duration, Duration)> { + unimplemented!("this host's scheduler accounting is not read here") +} diff --git a/tests/common/update.rs b/tests/common/update.rs index b4ff7f4a6b4..36fd7b58642 100644 --- a/tests/common/update.rs +++ b/tests/common/update.rs @@ -19,7 +19,6 @@ //! layout ([`fwvars`]). use std::path::{Path, PathBuf}; -use std::time::Instant; use toyos_build::bootlog; use toyos_build::build::{self, Plan}; @@ -187,7 +186,7 @@ impl Rig { marker: &str, ) -> Result<(usize, usize), String> { let (from, uart) = (console.len(), guest.uart_log().len()); - let mut hold = qemu::QmpHold::arm(guest.qmp_socket()); + let mut hold = qemu::QmpHold::arm(guest); let asked = ssh::ssh_fire(HOST, self.port, &self.identity, "reboot")?; eprintln!(" [update] `reboot` answered {asked:?}"); hold.held(qemu::GUEST_WEDGED)?; @@ -242,8 +241,9 @@ impl Rig { /// bounds are the harness's, [`qemu::GUEST_QUIET`] of silence on both and /// [`qemu::GUEST_WEDGED`] in all. fn await_machine(guest: &mut QemuInstance, console: &mut String, doing: &str, done: impl Fn(&str) -> bool) -> Result<(), String> { - let began = Instant::now(); - let (mut heard, mut grew) = (0usize, Instant::now()); + let clock = guest.clock(); + let began = clock.now(); + let (mut heard, mut grew) = (0usize, began); loop { if done(console) { return Ok(()); @@ -252,16 +252,16 @@ fn await_machine(guest: &mut QemuInstance, console: &mut String, doing: &str, do console.push_str(&more); let now = console.len() + guest.uart_log().len(); if now != heard { - (heard, grew) = (now, Instant::now()); + (heard, grew) = (now, clock.now()); } - if grew.elapsed() >= qemu::GUEST_QUIET { + if clock.since(grew) >= qemu::GUEST_QUIET { return Err(format!( "{} waiting for {doing}: the console and the 16550 both went quiet for {} s", qemu::STALLED, qemu::GUEST_QUIET.as_secs() )); } - if began.elapsed() >= qemu::GUEST_WEDGED { + if clock.since(began) >= qemu::GUEST_WEDGED { return Err(format!("{} waiting for {doing}: it never stopped talking and never got there", qemu::STALLED)); } } diff --git a/tests/common/usb.rs b/tests/common/usb.rs index fbbaaa641f3..970bd8c353d 100644 --- a/tests/common/usb.rs +++ b/tests/common/usb.rs @@ -818,7 +818,7 @@ fn optional_flush_keeps_the_log( // the sink is still running, and the only place that is visible is the // device while the machine is up. The ceiling is the harness's: a stick // with no write cache that cost the machine its log is a hang here. - let give_up = std::time::Instant::now() + qemu.budget(qemu::GUEST_WEDGED); + let give_up = qemu.now() + qemu.budget(qemu::GUEST_WEDGED); loop { let on_device = String::from_utf8_lossy( &super::volumes::newest_log(&image_path, start, len)?.1, @@ -827,7 +827,7 @@ fn optional_flush_keeps_the_log( if on_device.contains("Boot: complete") { break; } - if std::time::Instant::now() >= give_up { + if qemu.now() >= give_up { return Err(format!( "{} waiting for `Boot: complete` in the log on a stick with no write cache: {} \ bytes there", @@ -1989,8 +1989,8 @@ fn abandoned_write_is_taken_offline( ); let mut log = qemu.boot_log().to_string(); // The slot goes back from the poll, which the boot log may end before. - let deadline = std::time::Instant::now() + Duration::from_secs(20); - while std::time::Instant::now() < deadline + let deadline = qemu.now() + Duration::from_secs(20); + while qemu.now() < deadline && !log.split_once(" is offline: ").is_some_and(|(_, after)| after.contains(" disabled")) { log.push_str(&qemu.drain_serial(Duration::from_millis(250))); @@ -2563,18 +2563,18 @@ fn transport_gives_up( let boot = qemu.boot_log().to_string(); let mut plugged = String::new(); let wait_for = |qemu: &mut QemuInstance, plugged: &mut String, line: &str| { - let deadline = std::time::Instant::now() + Duration::from_secs(20); - while std::time::Instant::now() < deadline && !plugged.contains(line) { + let deadline = qemu.now() + Duration::from_secs(20); + while qemu.now() < deadline && !plugged.contains(line) { plugged.push_str(&qemu.drain_serial(Duration::from_millis(250))); } }; // The offline disk's slot goes back from the poll, which the boot log may // end before: it is waited for, so the pull below is not what gave it back. - let deadline = std::time::Instant::now() + Duration::from_secs(20); + let deadline = qemu.now() + Duration::from_secs(20); let gone_back = |text: &str| { text.split_once(" is offline: ").is_some_and(|(_, after)| after.contains(" disabled")) }; - while std::time::Instant::now() < deadline && !gone_back(&format!("{boot}{plugged}")) { + while qemu.now() < deadline && !gone_back(&format!("{boot}{plugged}")) { plugged.push_str(&qemu.drain_serial(Duration::from_millis(250))); } // It is pulled before the next disk is plugged, so the plug's port and diff --git a/tests/common/volumes.rs b/tests/common/volumes.rs index db12e842490..ead64b949ff 100644 --- a/tests/common/volumes.rs +++ b/tests/common/volumes.rs @@ -560,7 +560,7 @@ pub fn kernel_log_file( // Polled until logd has written through `Boot: complete`, with the // harness's ceiling and no deadline of this test's own: when logd writes // is its own business, and one that never does is a hang. - let give_up = std::time::Instant::now() + qemu.budget(qemu::GUEST_WEDGED); + let give_up = qemu.now() + qemu.budget(qemu::GUEST_WEDGED); let mut running; let mut running_text; let mut running_name; @@ -570,7 +570,7 @@ pub fn kernel_log_file( if running_text.contains("Boot: complete") { break; } - if std::time::Instant::now() >= give_up { + if qemu.now() >= give_up { return Err(format!( "{} waiting for logd to write `Boot: complete` to the device: {} bytes there, \ starting {:?}", diff --git a/tests/toyos-rust-tests/src/bin/nmi_window_spin.rs b/tests/toyos-rust-tests/src/bin/nmi_window_spin.rs index 7dd722641c3..022f34b9e78 100644 --- a/tests/toyos-rust-tests/src/bin/nmi_window_spin.rs +++ b/tests/toyos-rust-tests/src/bin/nmi_window_spin.rs @@ -7,6 +7,10 @@ //! its `sysretq`. Nothing here asserts: the counts are the kernel's, and //! `tests/common/faults.rs` holds the verdict. //! +//! **It never stops on its own.** The storm fires on a count of syscalls and +//! then waits on this loop to enter its hold, and only the harness reading the +//! kernel's report knows when the storm is over, so the harness ends the boot. +//! //! **The loop is written as assembly because its instruction count is part of //! the derivation.** Four instructions per iteration — `mov`, `syscall`, `dec`, //! `jnz` — so the boundaries at which an NMI can be delivered while this program @@ -20,29 +24,16 @@ //! no argument and touches no state: what should dominate the iteration is the //! entry and the exit, which is what the window is part of. -use toyos_abi::clock::nanos_since_boot as clock_nanos; use toyos_abi::syscall::SYS_GETPID; -/// Iterations between two clock reads. Large enough that the clock's own -/// read is a rounding error in the mix, small enough to stop promptly. +/// Iterations of one counted loop between two returns to Rust. const CHUNK: u64 = 50_000; fn main() { - let secs: u64 = std::env::args() - .nth(1) - .and_then(|a| a.parse().ok()) - .unwrap_or(10); - - println!("nmi-window-spin: spinning on SYS_GETPID for {secs}s"); - - let until = clock_nanos() + secs * 1_000_000_000; - let mut done: u64 = 0; - while clock_nanos() < until { + println!("nmi-window-spin: spinning on SYS_GETPID until the boot ends"); + loop { chunk(); - done += CHUNK; } - - println!("nmi-window-spin: {done} syscalls"); } /// [`CHUNK`] iterations of exactly four instructions. diff --git a/tests/toyos.rs b/tests/toyos.rs index 52ce975d3e7..b24b3bb3ac8 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -5,7 +5,7 @@ use std::fs; use std::io::Write; use std::path::Path; use std::thread; -use std::time::{Duration, Instant}; +use std::time::Duration; use common::qemu::{ self, await_guest, await_marker, await_marker_new, BootOptions, QemuInstance, TestResult, @@ -84,10 +84,7 @@ const DEFAULT_WIDTH: usize = 12; /// tail because at width 4 `allocator_stress` went from 1 s to past its 5 s and /// `demand_paging_sse` past its — but not one of those numbers is an assertion. /// They are liveness guards on a guest that might wedge, and the verdict in -/// every case is the exit code and the expected stdout. [`qemu::budget`] now -/// pays them out per guest the phase may have up, which is what -/// `wait_for_ready`'s boot timeout has done since the phase existed, so the -/// number each author reasoned about is still the number for one guest. +/// every case is the exit code and the expected stdout. /// /// What that leaves is one boot's worth of tests costing about thirteen seconds /// between them, which is far too little to be worth a tail slot of its own: @@ -334,8 +331,8 @@ const RUST_SKIP: &[&str] = &[ // `locale_detect_unrecognized` drive it. "locale_gate", // A victim, not a test: it spins on `SYS_GETPID` so that another CPU's NMIs - // have somewhere to land, and on its own it asserts nothing and costs ten - // seconds. `syscall_window_nmi` runs it on the kernel that storms it. + // have somewhere to land, and on its own it asserts nothing and never ends. + // `syscall_window_nmi` runs it on the kernel that storms it. "nmi_window_spin", // A victim, not a test: the load `dump-in-blocking-pass` files Ctrl+Alt+D // inside, and on its own it asserts nothing. `dump_left_pending_is_owed` runs @@ -5346,8 +5343,8 @@ fn run_screen_test( // A liveness ceiling on a machine that is halted and paging, so // there is no console to read progress off and this is the case // `qemu::budget` exists for. - let deadline = Instant::now() + qemu.budget(Duration::from_secs(40)); - while Instant::now() < deadline + let deadline = qemu.now() + qemu.budget(Duration::from_secs(40)); + while qemu.now() < deadline && !(head_seen && report.is_some() && judged.len() >= JUDGED_PAGES) { let dump = qemu.screendump(); @@ -5451,12 +5448,12 @@ fn run_screen_test( } None }; - let deadline = Instant::now() + qemu.budget(Duration::from_secs(30)); + let deadline = qemu.now() + qemu.budget(Duration::from_secs(30)); let mut last = loop { if let Some(f) = footer(&mut qemu) { break f; } - if Instant::now() >= deadline { + if qemu.now() >= deadline { return Err(format!( "{STALLED} no `[page n/m]` footer ever appeared; nothing was paging" )); @@ -5476,7 +5473,7 @@ fn run_screen_test( last = now; break; } - if Instant::now() >= deadline { + if qemu.now() >= deadline { return Err(format!( "{STALLED} the pager did not advance on its own — nothing here can say \ whether a keystroke stops it" @@ -5500,7 +5497,7 @@ fn run_screen_test( }; for key in 1..=SAMPLES { qemu::qmp_send_keys(&socket, &[("pgup", true), ("pgup", false)]); - let by = Instant::now() + qemu.budget(Duration::from_secs(20)); + let by = qemu.now() + qemu.budget(Duration::from_secs(20)); let now = loop { let Some(now) = footer(&mut qemu) else { return Err(format!( @@ -5511,7 +5508,7 @@ fn run_screen_test( if now != last { break now; } - if Instant::now() >= by { + if qemu.now() >= by { return Err(format!( "{STALLED} keystroke {key} of {SAMPLES} left the pager on {last:?}: a \ PageUp reached a halted machine and no page came of it" @@ -6918,23 +6915,6 @@ fn locale_detect_unrecognized(qemu: &mut QemuInstance) -> Result<(), String> { Ok(()) } -/// A round trip through a guest that is **demonstrably up**, corrected for how -/// fast this host is and not for how many guests it is running. -/// -/// [`qemu::budget`] is the ceiling on a guest that might be wedged, and it -/// multiplies by the width because a guest with a twelfth of the machine takes -/// longer over everything. This is the other case, and the width is wrong for -/// it: what these callers wait on is the shell echoing a line it has not run -/// yet, which is microseconds of guest time however little of the machine the -/// guest has. Ten of those establishing nothing is a keystroke path that is not -/// working, and a width-scaled ceiling turns that into four minutes of a lane — -/// measured, on the run this was written from: 285 s of a terminal parked on a -/// pipe it had been parked on since 1.4 s. -fn round_trip(one_guest: Duration) -> Duration { - let (_, _, num, den) = qemu::host_speed(); - one_guest * num / den -} - /// Keep collecting serial into `log` until `marker` shows up. /// /// **A pace, not a guard.** The two remaining callers retype at the guest and @@ -6947,8 +6927,8 @@ fn serial_until( marker: &str, timeout: Duration, ) -> bool { - let deadline = Instant::now() + timeout; - while Instant::now() < deadline { + let deadline = qemu.now() + timeout; + while qemu.now() < deadline { log.push_str(&qemu.drain_serial(Duration::from_millis(200))); if log.contains(marker) { return true; @@ -6970,8 +6950,8 @@ fn serial_until_new( from: usize, timeout: Duration, ) -> bool { - let deadline = Instant::now() + timeout; - while Instant::now() < deadline { + let deadline = qemu.now() + timeout; + while qemu.now() < deadline { log.push_str(&qemu.drain_serial(Duration::from_millis(200))); if log[from.min(log.len())..].contains(marker) { return true; @@ -7015,8 +6995,7 @@ fn answer_swiss_wizard( /// What is being waited for is a shell echoing a line it has not run yet, which /// is a round trip and not work — so this is short, and it is paid only when the /// line did not arrive. [`shell_type_line`] widens it by the guest's own -/// oversubscription; the two callers that retype at a surface which may not be -/// reading yet scale it per host with [`round_trip`] instead. +/// oversubscription. const ECHO_TRY: Duration = Duration::from_secs(2); /// How long one burst of typing has to reach the panel. @@ -7249,13 +7228,13 @@ fn await_drained( )) } Drained::Bytes => { - let deadline = Instant::now() + ceiling; + let deadline = qemu.now() + ceiling; loop { let drained = i8042_drained(&qemu.console_stream().since(mark)); if drained >= bytes { return Ok(()); } - if Instant::now() >= deadline { + if qemu.now() >= deadline { return Err(format!( "the kernel took {drained} of the {bytes} set-1 bytes typed so far off \ the i8042 inside {ceiling:?}, so the burst {burst:?} went out against a \ @@ -7358,13 +7337,13 @@ fn shell_type_once( let mut input = qemu::QmpInput::open(qemu.qmp_socket()); input.keys(&[("ret", true), ("ret", false)]); } - let deadline = Instant::now() + echo; + let deadline = qemu.now() + echo; loop { let said = qemu.console_stream().since(mark); if said.contains(line) { return Ok(()); } - if Instant::now() >= deadline { + if qemu.now() >= deadline { return Err(said); } thread::sleep(Duration::from_millis(5)); @@ -7427,8 +7406,7 @@ fn shell_echoes( // **A count of attempts, not a span of host seconds.** This used to be a // flat twenty, which is a fixed number of round trips on the host it was // written on and a different number on any other. Ten is the number, and - // each gets a round trip scaled to this host — see [`round_trip`] for why - // that and not the phase width. + // each gets a round trip scaled to this host. const TRIES: usize = 10; let mut lost = String::new(); for _ in 0..TRIES { @@ -7436,12 +7414,12 @@ fn shell_echoes( // loop's ordinary step: the surface is up and the shell may still not // be reading, which is what the retype exists for. if let Err(said) = - shell_type_once(qemu, &format!("echo {nonce}"), round_trip(ECHO_TRY), ack) + shell_type_once(qemu, &format!("echo {nonce}"), qemu::budget(ECHO_TRY), ack) { lost = said; continue; } - if serial_until(qemu, log, nonce, round_trip(Duration::from_secs(2))) { + if serial_until(qemu, log, nonce, qemu::budget(Duration::from_secs(2))) { return Ok(()); } } @@ -7479,13 +7457,13 @@ fn shell_echoes( /// The ceiling is the guest's own liveness rather than a phase-scaled clock, /// and here that cuts both ways: #156 is a *freeze*, so the machine this /// retries against goes silent, and the wait ends in fifteen seconds instead of -/// spending `qemu.budget(20 s)` — up to four minutes at width 12 — hammering -/// GUI+Q at a desktop that has stopped. `issues/design-debt/` names that -/// cost as a lane this test holds for a quarter of every run, which is what puts +/// spending `qemu.budget(20 s)` hammering GUI+Q at a desktop that has stopped. +/// `issues/design-debt/` names that cost as a lane this test holds for a +/// quarter of every run, which is what puts /// whichever desktop is dispatched beside it into a red nobody acts on. fn close_focused_window(qemu: &mut QemuInstance, log: &mut String, new: usize) -> bool { const CLOSED: &str = "compositor: window closed"; - let mut live = qemu::Liveness::new(Duration::from_secs(15), Duration::from_secs(60)); + let mut live = qemu::Liveness::new(qemu, Duration::from_secs(15), Duration::from_secs(60)); while !log[new..].contains(CLOSED) && live.working(log) { { let mut input = qemu::QmpInput::open(qemu.qmp_socket()); @@ -7805,9 +7783,9 @@ fn toolkit_iced() -> Result<(), String> { // Its exit ends the wait too: an app that dies before it has a window // would otherwise hold the lane for the whole budget. let exited = format!("exit: {app} pid="); - let deadline = Instant::now() + qemu.budget(Duration::from_secs(60)); + let deadline = qemu.now() + qemu.budget(Duration::from_secs(60)); while !log[launched..].contains("compositor: window opened") { - if log[launched..].contains(&exited) || Instant::now() >= deadline { + if log[launched..].contains(&exited) || qemu.now() >= deadline { return Err(format!("{app} never got a window:\n{}", &log[launched..])); } log.push_str(&qemu.drain_serial(Duration::from_millis(200))); @@ -7943,7 +7921,7 @@ fn toolkit_launch( fn toolkit_window_wake(rust_bins: &[(String, Vec)]) -> Result<(), String> { let (mut qemu, mut log, launched) = toolkit_launch(rust_bins, "window_wake", "test_rs_window_wake")?; let log = &mut log; - let mut live = qemu::Liveness::new(Duration::from_secs(30), Duration::from_secs(120)); + let mut live = qemu::Liveness::new(&qemu, Duration::from_secs(30), Duration::from_secs(120)); while live.working(log) { let said = &log[launched..]; if said.contains("WINDOW-WAKE-OK") { @@ -7974,7 +7952,7 @@ fn toolkit_window_wake(rust_bins: &[(String, Vec)]) -> Result<(), String> { fn toolkit_winit_loop(rust_bins: &[(String, Vec)]) -> Result<(), String> { let (mut qemu, mut log, launched) = toolkit_launch(rust_bins, "winit_loop", "test_rs_winit_loop")?; let log = &mut log; - let mut live = qemu::Liveness::new(Duration::from_secs(40), Duration::from_secs(240)); + let mut live = qemu::Liveness::new(&qemu, Duration::from_secs(40), Duration::from_secs(240)); let mut closed = false; while live.working(log) { let said = &log[launched..]; @@ -8036,7 +8014,7 @@ fn toolkit_winit_pace(rust_bins: &[(String, Vec)]) -> Result<(), String> { let (mut qemu, mut log, launched) = toolkit_launch(rust_bins, "winit_pace", "test_rs_winit_pace")?; let log = &mut log; let drew = format!("WINIT-PACE drew {PACE_FRAMES} frames"); - let mut live = qemu::Liveness::new(Duration::from_secs(30), Duration::from_secs(120)); + let mut live = qemu::Liveness::new(&qemu, Duration::from_secs(30), Duration::from_secs(120)); while live.working(log) && !log[launched..].contains(&drew) { let said = &log[launched..]; if said.contains("WINIT-PACE-FAIL") || said.contains("panicked") { @@ -8299,7 +8277,7 @@ fn desktop_typing_damage() -> Result<(), String> { // Two: the shell echoes the command as it is typed and again as its // output. The same arithmetic the verdict below makes. let want = ((line + 1) * 2) as usize; - let mut live = qemu::Liveness::new(Duration::from_secs(15), Duration::from_secs(60)); + let mut live = qemu::Liveness::new(&qemu, Duration::from_secs(15), Duration::from_secs(60)); while log[before..].matches(NONCE).count() < want && live.working(&log) { let seen = qemu.drain_serial(Duration::from_millis(100)); log.push_str(&seen); @@ -13065,8 +13043,8 @@ fn run_machine_test( // A baseline first: churn against a compositor that was never // drawing would be a green run proving nothing. - let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(20)); - while std::time::Instant::now() < deadline && frames(&console) < 1 { + let deadline = qemu.now() + qemu.budget(Duration::from_secs(20)); + while qemu.now() < deadline && frames(&console) < 1 { console.push_str(&qemu.drain_serial(Duration::from_millis(250))); } if frames(&console) < 1 { @@ -13117,8 +13095,8 @@ fn run_machine_test( // changed is that a console behind the guest costs wall clock instead // of a verdict. let bindings = |text: &str| text.matches("merges as source").count(); - let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(20)); - while std::time::Instant::now() < deadline && bindings(&console) < CYCLES { + let deadline = qemu.now() + qemu.budget(Duration::from_secs(20)); + while qemu.now() < deadline && bindings(&console) < CYCLES { console.push_str(&qemu.drain_serial(Duration::from_millis(250))); } let bound = bindings(&console); @@ -13152,8 +13130,8 @@ fn run_machine_test( // reporting interval is 2 s, so two of them cannot be satisfied by // frames the compositor produced before the first cycle. let mut after = String::new(); - let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(20)); - while std::time::Instant::now() < deadline && frames(&after) < 2 { + let deadline = qemu.now() + qemu.budget(Duration::from_secs(20)); + while qemu.now() < deadline && frames(&after) < 2 { after.push_str(&qemu.drain_serial(Duration::from_millis(250))); } if frames(&after) < 2 { @@ -16067,7 +16045,7 @@ fn the_others_halt_first(mut qemu: QemuInstance, arch: toyos_build::arch::Arch) let mut monitor = qemu::QmpMonitor::open(qemu.qmp_socket()); // A guard and never a verdict: a vCPU the host has not run yet has not // taken the stop, and this is how long it is waited for. - let give_up = Instant::now() + qemu::GUEST_QUIET; + let give_up = qemu.now() + qemu::GUEST_QUIET; loop { let stopped = qemu::stopped_cpus(&mut monitor, arch); // QEMU's CPU#n is the kernel's cpun: its MADT lists them in that order, @@ -16075,7 +16053,7 @@ fn the_others_halt_first(mut qemu: QemuInstance, arch: toyos_build::arch::Arch) if stopped.len() == cpus && stopped.iter().enumerate().all(|(cpu, &halted)| halted || cpu == fatal as usize) { break; } - if Instant::now() >= give_up { + if qemu.now() >= give_up { return Err(format!( "{STALLED} waiting for the other CPUs to halt after the fatal path on cpu{fatal} \ stopped them — QEMU shows each vCPU halted with interrupts masked as {stopped:?}\n{console}" @@ -16174,10 +16152,17 @@ impl Tally { if let Some(fastest) = fastest { say(format!( "host: fastest boot {fastest} ms against the reference {reference} ms — liveness \ - ceilings paid at {:.2}x width", + ceilings paid at {:.2}x", f64::from(num) / f64::from(den) )); } + if let Some((wall, had)) = common::steal::run_share() { + say(format!( + "host: the guests had {:.0}% of the {wall:.0?} their waits read across; the rest \ + was the host's load, which no ceiling counted", + had.as_secs_f64() * 100.0 / wall.as_secs_f64() + )); + } // The other half of the liveness correction is per guest, not host-wide: // a guest with more vCPUs than the host has cores waits `vcpus/cores` // longer again before its ceiling calls it wedged. Reported so a reader @@ -16617,7 +16602,6 @@ fn run_phase( return Vec::new(); } let width = width.clamp(1, tasks.len()); - qemu::set_width(width as u32); let queue = std::sync::Mutex::new(std::collections::VecDeque::from(tasks)); let mut all = Vec::new(); thread::scope(|scope| {