From e641eae4259afe39a6f44fd06c2371d898c4e262 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 04:19:59 +0200 Subject: [PATCH 1/7] Redlist: twelve reds on main, each disabled with the issue that owns it The orchestrator stops re-running reds on a quiet host. Every red below is on main's code, so each is disabled now, and its issue says what it is and what ends it. Defects already on main: - process_stats: a connection park charged 0 ns to ipc and to pipe, at process_stats.rs:280 on wt/toyos-loaderlines 6e0d7da82 (fastest boot 480 ms) and at :263 on wt/toyos-proclife1 60ec86df3. Neither branch touches the test or the charge. The existing issue takes both sightings and becomes expected-red. - lan_dhcp_lease: the test awaits the lease and asserts netd's ready line after it, but the capture ends at test-runner's ===READY===, which can come first (wt/toyos-tight 59940c452, ceilings at 1.00x). - root_candidate_malformed: wait_for_ready reads a 16550 ready marker off QEMU's log file while the loader is still writing the line, and the test got "Slot A: REFUSED, its root is" (same run). - redirty_mid_flush: the guest went silent after spawning its child (wt/toyos-proclife 6e9d6a4df). The branch's own kernel change is two retired-syscall lines; the test passed at the branch's previous head and in every other kept whole-suite log. Verdicts the host's speed decided: - update_boots_the_new_kernel, update_falls_back_from_a_dying_kernel, update_floor_is_the_images_own, update_refusals_boot_the_other_slot: 15 s of silence across the firmware reset reads as a stall at load average 84, on #648's run and again on #642's. - guest_dies_with_its_harness: the owner's boot is judged at an unscaled 20 s on the host's clock. - syscall_window_nmi_controls: the spinner stops after ten seconds of the guest's clock and the storm waits for a million syscalls; starved, it made 950000. - virt_smp: an AP has 100 ms to echo, and a starved vCPU did not. src/redlist.rs's whole-name test probed `_controls` against None; with syscall_window_nmi and syscall_window_nmi_controls both disabled that probe finds the second row, so it now asserts only that the probe does not find the row it extends. The old assertion reds on this table (checked: EXIT=101), the new one passes. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-reads-a-starved-guest-as-a-stopped-one.md | 37 ++++++++++++++++ ...550-file-can-end-the-boot-wait-mid-line.md | 25 +++++++++++ ...serts-a-line-its-wait-does-not-wait-for.md | 25 +++++++++++ ...ess-stats-exits-101-beside-other-guests.md | 18 +++++++- ...-scheduled-for-100-ms-is-booted-without.md | 28 ++++++++++++ ...sh-went-silent-after-spawning-its-child.md | 35 +++++++++++++++ ...mes-its-victim-by-the-guests-wall-clock.md | 26 +++++++++++ src/redlist.rs | 43 ++++++++++++++++++- 8 files changed, 235 insertions(+), 2 deletions(-) create mode 100644 issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md create mode 100644 issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md create mode 100644 issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md create mode 100644 issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md create mode 100644 issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md create mode 100644 issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md diff --git a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md new file mode 100644 index 00000000000..9b0937972b7 --- /dev/null +++ b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md @@ -0,0 +1,37 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# A harness wait reads a starved guest as a stopped one + +Every wait the harness puts on a guest is measured on the host's wall clock. +On a loaded host a TCG guest's QEMU sits runnable and unserved, so a guest that +is slow reads as one that stopped, and the host's load decides the verdict: + +- `update_boots_the_new_kernel`, `update_falls_back_from_a_dying_kernel`, + `update_floor_is_the_images_own` and `update_refusals_boot_the_other_slot` + STALLED in the same run (`648-648-whole.log`, `wt/toyos-proclife1` + `60ec86df3`, load average 84 on 14 cores): "the console and the 16550 both + went quiet for 15 s", each just after the loader's "this pass resets the + machine". `await_machine` (`tests/common/update.rs`) ends on 15 s of silence + alone, and the firmware between that reset and the loader's next line is + silent. The same run's `boot_from_power_on` read "power-on to loader 17387 + ms", against 5021 ms on a quiet host. `update_boots_the_new_kernel` STALLED + the same way on `wt/toyos-proclife` `6e9d6a4df` (`642r2-642-whole.log`). +- `guest_dies_with_its_harness` (same 648 run, 21 s): "Boot timed out waiting + for ===READY===; the console carried: nothing at all". The owner process has + measured no boot, so its `wait_for_ready` ceiling is the unscaled 20 s, and + its 16550 had reached "ROOT: read into memory" — a guest still working. + +The opposite error has the same cause. `budget` multiplies a test's ceiling by +the phase width and by `host_scale`, two stand-ins for the host's load, so a +guest that stops at once is waited on for 37 times its budget: +`redirty_mid_flush` (`642r2-642-whole.log`) said nothing after its first second +and was called stalled at "4474s of guard expired": its 120 s × 12 wide × a +`host_scale` of 3.1 (4474 / 1440), the fastest boot the run had seen when the +test began. + +**Exit**: every wait on a guest reads time the guest had, with the host's +steal taken out, and no ceiling scales by the host's load; then these rows go. 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/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/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md b/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md new file mode 100644 index 00000000000..c086e661240 --- /dev/null +++ b/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md @@ -0,0 +1,28 @@ +--- +status: expected-red +kind: defect +opened: 2026-10-01 +--- + +# An AP its host has not scheduled for 100 ms is booted without + +`virt_smp` red in `636r2-virt.log` (`wt/toyos-rulesbatch` `8f142ba9e`, TCG, +`VirtEl2`, a loaded host, "liveness ceilings paid at 1.93x"): + +``` +[kernel 0.236 cpu0] SMP: cpu6 mpidr=0x6 online +[kernel 0.368 cpu0] SMP: cpu7 mpidr=0x7 did not echo within 100ms (the machine boots with the CPUs that came up before the first that did not); the rest stay off +[kernel 0.372 cpu0] SMP: 7 of 8 MADT CPUs online +``` + +`time::AP_START` gives an AP 100 ms between `CPU_ON` (or the SIPIs) and its +echo, and its expiry boots the machine without that CPU for good. On metal an +AP that is alive answers in microseconds; under any hypervisor a vCPU its host +has not scheduled answers late, and 100 ms of steal reads as a dead CPU. Linux +waits 5 s for the same echo on arm64 (`arch/arm64/kernel/smp.c`, `__cpu_up`: +`wait_for_completion_timeout(&cpu_running, msecs_to_jiffies(5000))`) and 10 s +in its generic bring-up (`kernel/cpu.c`, `cpuhp_wait_for_sync_state`). + +**Exit**: the bound is one on a dead CPU — the span this kernel already holds a +live CPU to (`time::DEAF_CPU`) — and `virt_smp` is green on a loaded host; 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/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md b/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md new file mode 100644 index 00000000000..ddf8866a517 --- /dev/null +++ b/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md @@ -0,0 +1,26 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# The syscall-window storm times its victim by the guest's wall clock + +`syscall_window_nmi_controls` red at 446 s in `648-648-whole.log` +(`wt/toyos-proclife1` `60ec86df3`, load average 84 on 14 cores): "the capture +has no `syscall-window-nmi: held cpu=` line and no `syscall-window-nmi: held +nobody` line". The storm never fired. It fires once one CPU has counted a +million syscalls (`nmi_gate::SPINNING_SYSCALLS`), and the spinner stops after +ten seconds of the guest's clock: under TCG that is the host's, and the +starved spinner said `950000 syscalls` (`syscalls: pid=9 total=950009 ... +cpu=9997ms`) — the dev host's quiet rate is a million in about 190 ms. + +The storm's own waits on its victim are the same mistake at 100 ms each: +`HOLD_ACK_NS` for the held CPU's acknowledgement, `HELD_DELIVERY_NS` for the +aimed NMI to be taken, and `HOLD_ACK_NS` again for the released CPU's next +syscall. A vCPU the host has not scheduled for 100 ms answers none of them, +and the control's held arrival is then not the one the hold arranged. + +**Exit**: the spinner spins until the storm is over, and every wait the storm +puts on its victim is a bound on a dead CPU and not on a starved one; then the +row goes. diff --git a/src/redlist.rs b/src/redlist.rs index c08804b93d1..9c4025fafd3 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -30,6 +30,10 @@ pub const DISABLED: &[Disabled] = &[ issue: "issues/build/the-console-input-path-can-stop-after-a-ps2-overflow.md", }, Disabled { test: "desktop_window_child", issue: "issues/kernel/desktop-window-child-freeze.md" }, + Disabled { + test: "guest_dies_with_its_harness", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "handle_basic", issue: "issues/kernel/deferred-release-outlives-its-syscall.md" }, Disabled { test: "handle_kill_policy", @@ -41,6 +45,10 @@ pub const DISABLED: &[Disabled] = &[ issue: "issues/hardware/i8042-mouse-ends-four-packets-short-with-a-clean-exit.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 +61,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 +74,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", @@ -85,6 +102,26 @@ pub const DISABLED: &[Disabled] = &[ test: "syscall_window_nmi", issue: "issues/kernel/syscall-window-nmi-shortfalls-on-a-contended-host.md", }, + Disabled { + test: "syscall_window_nmi_controls", + issue: "issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md", + }, + Disabled { + test: "update_boots_the_new_kernel", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, + Disabled { + test: "update_falls_back_from_a_dying_kernel", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, + Disabled { + test: "update_floor_is_the_images_own", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, + Disabled { + test: "update_refusals_boot_the_other_slot", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "usb_transport_break", issue: "issues/kernel/a-held-disk-waits-for-a-pass-no-cpu-takes-when-every-cpu-is-in-a-call-on-it.md", @@ -93,6 +130,10 @@ pub const DISABLED: &[Disabled] = &[ test: "user_copy_races_munmap", issue: "issues/kernel/copy-meets-a-remap-holds-a-cpu-the-thread-it-waits-on-may-be-queued-behind.md", }, + Disabled { + test: "virt_smp", + issue: "issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md", + }, ]; /// The row of `rows` that disables `test`, matched by the whole name. @@ -257,7 +298,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); } From 330c76a10e7c3cd4ff2038418a4fdb35792f76ad Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 04:46:51 +0200 Subject: [PATCH 2/7] The host's load decides no verdict: every wait on a guest reads the guest's own clock, and the kernel's waits on another CPU are bounds on a dead one Seven reds were the host's speed, not the guest's behaviour. Each timing assumption is removed where it lives. The harness. Every wait on a guest measured the host's wall clock, so a TCG guest whose QEMU sat runnable and unserved read as one that stopped (the update tests' 15 s of silence across a firmware reset; the owner's boot in guest_dies_with_its_harness killed at 20 s with its loader still printing). The opposite error had the same cause: `budget` multiplied a ceiling by the phase width and by a fastest-boot `host_scale` taken early in a loaded run, so redirty_mid_flush's stopped guest was waited on for 4474 s against its 120 s budget. - tests/common/steal.rs is a guest's own clock: the wall clock less the host's steal, read from QEMU's process accounting (macOS proc_pid_rusage's run and runnable times; Linux's per-thread schedstat). Demand under one thread's worth loses the moments it waited; demand over it has the share the host served. A guest that wants nothing, idle or stopped, has the wall's time, so a stopped guest is called stopped on time however loaded the host is. - Every wait on a guest reads it: the boot wait, run_test's ceiling, the drains, Liveness, the screendump waits, await_exit, the update tests' wait, the QMP event waits (now bounded on the clock with a 200 ms read poll), the segment's frame wait, and the tests' own deadline loops. - WIDTH, set_width and round_trip go: sharing the host is the clock's to take out, and the width was a stand-in for it. The boot ceiling is the twenty seconds a phase of one guest gave it. `host_scale` reads boots on the guest's clock, so it measures the host's speed and not its load. The kernel. `time::AP_START` gave an AP 100 ms to echo, and a vCPU its host had not scheduled for that long booted the machine one CPU short (virt_smp, cpu7 of 8). It is now DEAF_CPU's span, the bound this kernel already holds a live CPU to; Linux waits 5 s for the same echo on arm64 (`__cpu_up`) and 10 s in its generic bring-up (`cpuhp_wait_for_sync_state`). The NMI storm. syscall_window_nmi_controls' spinner stopped after ten seconds of the guest's clock while the storm waits for a million syscalls on one CPU; starved, it made 950000 and the storm never fired. The spinner now spins until the harness ends its boot, and the storm's three waits on its victim (`HOLD_ACK_NS` twice, `HELD_DELIVERY_NS`) are DEAF_CPU's span rather than 100 ms; the hold's budget of turns grows to 2^31 to outlast it at the 3 ns-a-turn estimate its assertion states. The seven rows #654 disabled for these, and their three issues, go: update_boots_the_new_kernel, update_falls_back_from_a_dying_kernel, update_floor_is_the_images_own, update_refusals_boot_the_other_slot, guest_dies_with_its_harness, syscall_window_nmi_controls, virt_smp. -icount is not taken: it is TCG's alone, so the HVF and KVM guests keep the kernel's exposure to steal and only TCG's is masked; QEMU refuses MTTCG with it ("No MTTCG when icount is enabled", accel/tcg/tcg-all.c), and round-robin switches vCPUs on a 100 ms kick of the virtual clock (TCG_KICK_PERIOD), which ISB-based spin loops on AArch64 do not yield before. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-reads-a-starved-guest-as-a-stopped-one.md | 37 -- ...-scheduled-for-100-ms-is-booted-without.md | 28 -- ...mes-its-victim-by-the-guests-wall-clock.md | 26 -- kernel/src/arch/x86_64/nmi_gate.rs | 10 +- kernel/src/time.rs | 7 +- src/redlist.rs | 28 -- tests/checks.rs | 11 + tests/checks/steal.rs | 77 ++++ tests/common/devices.rs | 2 +- tests/common/faults.rs | 17 +- tests/common/logstream.rs | 6 +- tests/common/mod.rs | 2 + tests/common/origin.rs | 13 +- tests/common/pkg.rs | 4 +- tests/common/power.rs | 34 +- tests/common/qemu.rs | 362 +++++++++--------- tests/common/segment.rs | 22 +- tests/common/steal.rs | 184 +++++++++ tests/common/update.rs | 14 +- tests/common/usb.rs | 16 +- tests/common/volumes.rs | 4 +- .../src/bin/nmi_window_spin.rs | 23 +- tests/toyos.rs | 107 ++---- 23 files changed, 578 insertions(+), 456 deletions(-) delete mode 100644 issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md delete mode 100644 issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md delete mode 100644 issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md create mode 100644 tests/checks/steal.rs create mode 100644 tests/common/steal.rs diff --git a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md deleted file mode 100644 index 9b0937972b7..00000000000 --- a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md +++ /dev/null @@ -1,37 +0,0 @@ ---- -status: expected-red -kind: tooling -opened: 2026-10-01 ---- - -# A harness wait reads a starved guest as a stopped one - -Every wait the harness puts on a guest is measured on the host's wall clock. -On a loaded host a TCG guest's QEMU sits runnable and unserved, so a guest that -is slow reads as one that stopped, and the host's load decides the verdict: - -- `update_boots_the_new_kernel`, `update_falls_back_from_a_dying_kernel`, - `update_floor_is_the_images_own` and `update_refusals_boot_the_other_slot` - STALLED in the same run (`648-648-whole.log`, `wt/toyos-proclife1` - `60ec86df3`, load average 84 on 14 cores): "the console and the 16550 both - went quiet for 15 s", each just after the loader's "this pass resets the - machine". `await_machine` (`tests/common/update.rs`) ends on 15 s of silence - alone, and the firmware between that reset and the loader's next line is - silent. The same run's `boot_from_power_on` read "power-on to loader 17387 - ms", against 5021 ms on a quiet host. `update_boots_the_new_kernel` STALLED - the same way on `wt/toyos-proclife` `6e9d6a4df` (`642r2-642-whole.log`). -- `guest_dies_with_its_harness` (same 648 run, 21 s): "Boot timed out waiting - for ===READY===; the console carried: nothing at all". The owner process has - measured no boot, so its `wait_for_ready` ceiling is the unscaled 20 s, and - its 16550 had reached "ROOT: read into memory" — a guest still working. - -The opposite error has the same cause. `budget` multiplies a test's ceiling by -the phase width and by `host_scale`, two stand-ins for the host's load, so a -guest that stops at once is waited on for 37 times its budget: -`redirty_mid_flush` (`642r2-642-whole.log`) said nothing after its first second -and was called stalled at "4474s of guard expired": its 120 s × 12 wide × a -`host_scale` of 3.1 (4474 / 1440), the fastest boot the run had seen when the -test began. - -**Exit**: every wait on a guest reads time the guest had, with the host's -steal taken out, and no ceiling scales by the host's load; then these rows go. diff --git a/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md b/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md deleted file mode 100644 index c086e661240..00000000000 --- a/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md +++ /dev/null @@ -1,28 +0,0 @@ ---- -status: expected-red -kind: defect -opened: 2026-10-01 ---- - -# An AP its host has not scheduled for 100 ms is booted without - -`virt_smp` red in `636r2-virt.log` (`wt/toyos-rulesbatch` `8f142ba9e`, TCG, -`VirtEl2`, a loaded host, "liveness ceilings paid at 1.93x"): - -``` -[kernel 0.236 cpu0] SMP: cpu6 mpidr=0x6 online -[kernel 0.368 cpu0] SMP: cpu7 mpidr=0x7 did not echo within 100ms (the machine boots with the CPUs that came up before the first that did not); the rest stay off -[kernel 0.372 cpu0] SMP: 7 of 8 MADT CPUs online -``` - -`time::AP_START` gives an AP 100 ms between `CPU_ON` (or the SIPIs) and its -echo, and its expiry boots the machine without that CPU for good. On metal an -AP that is alive answers in microseconds; under any hypervisor a vCPU its host -has not scheduled answers late, and 100 ms of steal reads as a dead CPU. Linux -waits 5 s for the same echo on arm64 (`arch/arm64/kernel/smp.c`, `__cpu_up`: -`wait_for_completion_timeout(&cpu_running, msecs_to_jiffies(5000))`) and 10 s -in its generic bring-up (`kernel/cpu.c`, `cpuhp_wait_for_sync_state`). - -**Exit**: the bound is one on a dead CPU — the span this kernel already holds a -live CPU to (`time::DEAF_CPU`) — and `virt_smp` is green on a loaded host; then -the row goes. diff --git a/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md b/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md deleted file mode 100644 index ddf8866a517..00000000000 --- a/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md +++ /dev/null @@ -1,26 +0,0 @@ ---- -status: expected-red -kind: tooling -opened: 2026-10-01 ---- - -# The syscall-window storm times its victim by the guest's wall clock - -`syscall_window_nmi_controls` red at 446 s in `648-648-whole.log` -(`wt/toyos-proclife1` `60ec86df3`, load average 84 on 14 cores): "the capture -has no `syscall-window-nmi: held cpu=` line and no `syscall-window-nmi: held -nobody` line". The storm never fired. It fires once one CPU has counted a -million syscalls (`nmi_gate::SPINNING_SYSCALLS`), and the spinner stops after -ten seconds of the guest's clock: under TCG that is the host's, and the -starved spinner said `950000 syscalls` (`syscalls: pid=9 total=950009 ... -cpu=9997ms`) — the dev host's quiet rate is a million in about 190 ms. - -The storm's own waits on its victim are the same mistake at 100 ms each: -`HOLD_ACK_NS` for the held CPU's acknowledgement, `HELD_DELIVERY_NS` for the -aimed NMI to be taken, and `HOLD_ACK_NS` again for the released CPU's next -syscall. A vCPU the host has not scheduled for 100 ms answers none of them, -and the control's held arrival is then not the one the hold arranged. - -**Exit**: the spinner spins until the storm is over, and every wait the storm -puts on its victim is a bound on a dead CPU and not on a starved one; 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 9c4025fafd3..485f277d180 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -30,10 +30,6 @@ pub const DISABLED: &[Disabled] = &[ issue: "issues/build/the-console-input-path-can-stop-after-a-ps2-overflow.md", }, Disabled { test: "desktop_window_child", issue: "issues/kernel/desktop-window-child-freeze.md" }, - Disabled { - test: "guest_dies_with_its_harness", - issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", - }, Disabled { test: "handle_basic", issue: "issues/kernel/deferred-release-outlives-its-syscall.md" }, Disabled { test: "handle_kill_policy", @@ -102,26 +98,6 @@ pub const DISABLED: &[Disabled] = &[ test: "syscall_window_nmi", issue: "issues/kernel/syscall-window-nmi-shortfalls-on-a-contended-host.md", }, - Disabled { - test: "syscall_window_nmi_controls", - issue: "issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md", - }, - Disabled { - test: "update_boots_the_new_kernel", - issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", - }, - Disabled { - test: "update_falls_back_from_a_dying_kernel", - issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", - }, - Disabled { - test: "update_floor_is_the_images_own", - issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", - }, - Disabled { - test: "update_refusals_boot_the_other_slot", - issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", - }, Disabled { test: "usb_transport_break", issue: "issues/kernel/a-held-disk-waits-for-a-pass-no-cpu-takes-when-every-cpu-is-in-a-call-on-it.md", @@ -130,10 +106,6 @@ pub const DISABLED: &[Disabled] = &[ test: "user_copy_races_munmap", issue: "issues/kernel/copy-meets-a-remap-holds-a-cpu-the-thread-it-waits-on-may-be-queued-behind.md", }, - Disabled { - test: "virt_smp", - issue: "issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md", - }, ]; /// The row of `rows` that disables `test`, matched by the whole name. 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..fc61ce1f7b7 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..e28572bca95 --- /dev/null +++ b/tests/common/steal.rs @@ -0,0 +1,184 @@ +//! 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::{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); + +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; + 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; + 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..70d9eb43e87 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,7 +16152,7 @@ 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) )); } @@ -16617,7 +16595,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| { From dc153d6da9adb5be33c70f3f20013b5335d6cd78 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 05:18:05 +0200 Subject: [PATCH 3/7] Redlist: iommu_virtio_platform and loader_watchdog_arms, from a libc-only branch's run Both went red in 650-libcllvm-whole.log on wt/toyos-libcllvm, whose diff is userland/libc alone, at load average 66-74. - iommu_virtio_platform is a defect on main. It reads netd's claim line and netd's feature negotiation off a boot log that ends at test-runner's ===READY===, and netd starts before test-runner but speaks after it. The same race reds in two wordings on 634r2, 637r2 and 641f-r3, each on a branch that does not touch it. #639 carries a fix (d773a4306). - loader_watchdog_arms timed out its boot at 132 s of wall clock, which is 10 s x 12 wide x host_scale. The console stood at "BdsDxe: starting Boot0001". Its 50-odd other runs in the kept logs passed in 6-34 s. It goes under the harness-wait issue, which now carries this sighting and 650's two update STALLs. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-reads-a-starved-guest-as-a-stopped-one.md | 8 +++++ ...es-off-a-boot-log-that-ends-before-them.md | 31 +++++++++++++++++++ src/redlist.rs | 8 +++++ 3 files changed, 47 insertions(+) create mode 100644 issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md diff --git a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md index 9b0937972b7..3b10e2922b1 100644 --- a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md +++ b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md @@ -24,6 +24,14 @@ is slow reads as one that stopped, and the host's load decides the verdict: for ===READY===; the console carried: nothing at all". The owner process has measured no boot, so its `wait_for_ready` ceiling is the unscaled 20 s, and its 16550 had reached "ROOT: read into memory" — a guest still working. +- `650-libcllvm-whole.log` (`wt/toyos-libcllvm`, libc only, load average + 66–74, image builds in the same run): `update_refusals_boot_the_other_slot` + and `update_boots_the_new_kernel` STALLED as above, and `loader_watchdog_arms` + timed out its boot at 132 s of wall clock — 10 s × 12 wide × `host_scale` — + with the console at "BdsDxe: starting Boot0001". Its 50-odd other runs in + the kept logs passed in 6–34 s. Whether that guest was starved or the loader + stalled before its first line is what a wait on the guest's own time + separates. The opposite error has the same cause. `budget` multiplies a test's ceiling by the phase width and by `host_scale`, two stand-ins for the host's load, so a 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/src/redlist.rs b/src/redlist.rs index 9c4025fafd3..5e2254c7084 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -44,11 +44,19 @@ 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: "loader_watchdog_arms", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.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", From 262dd97680ec45eaf45ec2304bcd073b9a1ddba4 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 05:18:59 +0200 Subject: [PATCH 4/7] power: watch_the_bound hands its guest to QmpShutdown without a second borrow Clippy's needless_borrow, red in the host gate's clippy step at 330c76a10: the guest is already a reference there. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- tests/common/power.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/common/power.rs b/tests/common/power.rs index fc61ce1f7b7..34fa7834008 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -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, budget), budget) + (qemu::QmpShutdown::open(qemu, budget), budget) } /// QEMU's own `guest-reset` on `watch`, and the serial the guest wrote after From 703d9703eb87d0852535acb4dc05e53d0b8b27a4 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 05:41:51 +0200 Subject: [PATCH 5/7] Redlist: three more from the libc-only run, each on main's code 650-libcllvm-whole.log, wt/toyos-libcllvm, whose diff is userland/libc alone; load average 66-87, with the run reporting ceilings at 1.01x. - metal_sim_window_drag and usb_boot_stick_pulled timed out their boots at 21 and 22 s in the serial tail, the 20 s a phase of one guest gets. Each had the loader still printing its segments. They go under the harness-wait issue, which now also says why the run's 1.01x could not see the load. - blockd_serves_partitions: the bench passed and its process exited at 35.978 s, then no ===TEST_END=== came for 3559 s, while the kernel kept logging with every CPU idle. Either test-runner's wait on the job missed the exit's post, or logd stopped forwarding. The new issue says which evidence the next sighting needs, and names #655's poller shape as the logd reading. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-reads-a-starved-guest-as-a-stopped-one.md | 7 +++- ...ob-that-exited-was-never-reported-ended.md | 37 +++++++++++++++++++ src/redlist.rs | 12 ++++++ 3 files changed, 55 insertions(+), 1 deletion(-) create mode 100644 issues/kernel/a-job-that-exited-was-never-reported-ended.md diff --git a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md index 3b10e2922b1..ef5ab906c40 100644 --- a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md +++ b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md @@ -31,7 +31,12 @@ is slow reads as one that stopped, and the host's load decides the verdict: with the console at "BdsDxe: starting Boot0001". Its 50-odd other runs in the kept logs passed in 6–34 s. Whether that guest was starved or the loader stalled before its first line is what a wait on the guest's own time - separates. + separates. In the serial tail of the same run, `metal_sim_window_drag` and + `usb_boot_stick_pulled` timed out their boots at 21 and 22 s — the 20 s a + phase of one guest gets — with the loader still printing its segments. The + run reported "fastest boot 1331 ms against the reference 1320 ms — liveness + ceilings paid at 1.01x" at a load average of 66–87: the fastest boot is + taken at the run's quietest moment, so `host_scale` cannot see the load. The opposite error has the same cause. `budget` multiplies a test's ceiling by the phase width and by `host_scale`, two stand-ins for the host's load, so a 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/src/redlist.rs b/src/redlist.rs index 5e2254c7084..86b2b496c8f 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", @@ -61,6 +65,10 @@ pub const DISABLED: &[Disabled] = &[ test: "log_ring_keeps_the_owners_slots", issue: "issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md", }, + Disabled { + test: "metal_sim_window_drag", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "netd_refused_accept", issue: "issues/hardware/netd-refused-accept-hung-waiting-for-a-wake-that-never-came.md", @@ -130,6 +138,10 @@ pub const DISABLED: &[Disabled] = &[ test: "update_refusals_boot_the_other_slot", issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", }, + Disabled { + test: "usb_boot_stick_pulled", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "usb_transport_break", issue: "issues/kernel/a-held-disk-waits-for-a-pass-no-cpu-takes-when-every-cpu-is-in-a-call-on-it.md", From 1478bd45c9f5ee67f5da2b34e9fa45451d0aca58 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 05:44:30 +0200 Subject: [PATCH 6/7] The run says how much of the host its guests had, and a Linux kernel without schedstat is refused #650's run called its ceilings "1.01x" at a load average of 66-87. Its gauge is the fastest boot, taken at the run's quietest moment, so it sees the host's speed and never its load. Every guest's clock now adds its read spans to a run-wide tally, and the summary says what share of its waits' wall clock the guests had. That is the load, measured where it fell. On Linux the clock reads each thread's /proc schedstat. A kernel built without CONFIG_SCHED_INFO has no such file, so a starved guest would read as one that wanted nothing. demand() now refuses such a kernel by name. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- tests/common/steal.rs | 23 +++++++++++++++++++++++ tests/toyos.rs | 7 +++++++ 2 files changed, 30 insertions(+) diff --git a/tests/common/steal.rs b/tests/common/steal.rs index e28572bca95..a5f38e4d3c4 100644 --- a/tests/common/steal.rs +++ b/tests/common/steal.rs @@ -11,6 +11,7 @@ //! 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}; @@ -66,6 +67,20 @@ struct Reading { /// 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 { @@ -93,6 +108,8 @@ impl Clock { }; 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) } @@ -153,6 +170,12 @@ fn mach_nanos(count: u64) -> u64 { #[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, diff --git a/tests/toyos.rs b/tests/toyos.rs index 70d9eb43e87..b24b3bb3ac8 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -16156,6 +16156,13 @@ impl Tally { 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 From f1ad5d1eda66fb970b2ef2b75f394c2a4c8281c7 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 05:57:31 +0200 Subject: [PATCH 7/7] issues: an idle guest and a hung one print the same sched line blockd_serves_partitions' guest printed "ready=0 ... parked=4" every ten seconds for an hour. The coordinator asked that such a guest be ended within seconds. The line cannot carry that verdict: a guest waiting out a timer prints the same line. The issue records what would carry it, a count of the parks with a deadline, and what it would end early. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...nd-a-hung-one-print-the-same-sched-line.md | 26 +++++++++++++++++++ 1 file changed, 26 insertions(+) create mode 100644 issues/diagnostics/an-idle-guest-and-a-hung-one-print-the-same-sched-line.md 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.