From 3f7081381417179f1068385876fe30dbc77a4826 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 11:56:18 +0200 Subject: [PATCH 1/2] A wait on a guest reads the guest's own clock, and an AP is waited for as long as a dead CPU is The 21-test guest suite is meant to become a required check on GitHub's shared Linux runners, so the host's speed and load may decide none of its verdicts. On main every wait the harness puts on a guest read the host's wall clock: the boot wait, `Liveness`'s silence and backstop (every `await_guest`), `drain_until`, `screendump_while`, `run_test_paced`'s ceiling and the fatal-halt test's wait for QMP to show the other vCPUs halted. A loaded host stretches a TCG guest's work by however long QEMU's threads sat runnable and unserved, and a wall-clock wait reads that stretch as a hang. `tests/common/steal.rs` is the guest's clock, carried from #658 (`wt/toyos-loadfree`, `f1ad5d1ed`): the wall clock less what the host withheld from the guest's QEMU. 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 gets the wall's time, so a stopped guest is still called stopped on time. The clock never runs faster than the wall. Two corrections to #658's reading: - macOS: `ri_runnable_time` counts a thread running as well as waiting to. Measured on this host: one spinner alone for 500 ms ran 500.05 ms and was runnable 503.24 ms; 28 on 14 cores ran 6.93 s and were runnable 14.00 s. #658 read the whole of it as the wait, so a busy guest on a quiet host had half the wall. The wait is now what it holds past the run. - Linux: `/proc//task/*/schedstat` is read per tid, and a span counts each thread's growth since the last reading. A thread that exits now loses only its last span, where #658's sum lost the thread's whole life and read the span as no demand. `WIDTH` and `set_width` go: the width was a stand-in for contention, and contention is now the clock's to take out, so keeping both double-counts it. `host_scale` times boots on the guest's clock, so it measures the host's speed and not its load. The boot wait is 20 s of the guest's clock, the number a run of one guest always had. The suite's summary says what share of the wall its guests had. `time::AP_START` becomes `DEAF_CPU`'s 5 s, up from 100 ms. Its expiry boots the machine one CPU short for good, and a vCPU its host has not run yet is slow, not dead. Linux waits 5000 ms for the same echo on arm64 (`arch/arm64/kernel/smp.c`, `__cpu_up`). `virt_smp` was booted 7 of 8 on a loaded host for this (`636r2-virt.log`), so `issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md` goes. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-scheduled-for-100-ms-is-booted-without.md | 30 --- kernel/src/time.rs | 6 +- tests/checks.rs | 18 ++ tests/checks/qemu.rs | 2 +- tests/checks/steal.rs | 162 ++++++++++++++ tests/common/mod.rs | 1 + tests/common/qemu.rs | 171 +++++++------- tests/common/steal.rs | 211 ++++++++++++++++++ tests/toyos.rs | 19 +- 9 files changed, 486 insertions(+), 134 deletions(-) delete mode 100644 issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md create mode 100644 tests/checks/steal.rs create mode 100644 tests/common/steal.rs 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 a7643a60aa8..00000000000 --- a/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md +++ /dev/null @@ -1,30 +0,0 @@ ---- -status: open -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`, userland only, 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`). - -Owner: the orchestrator. - -**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` passes in a whole-suite run at a host load average above -the dev host's core count. diff --git a/kernel/src/time.rs b/kernel/src/time.rs index 092c1559222..a258103ad05 100644 --- a/kernel/src/time.rs +++ b/kernel/src/time.rs @@ -242,9 +242,11 @@ 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: +/// [`DEAF_CPU`]'s span, because a vCPU its host has not run yet is slow and not +/// dead. 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/tests/checks.rs b/tests/checks.rs index 05f9544e77d..0c9220aaa88 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,22 @@ mod checks { clock_checks::self_check() } + /// A guest's clock: the arithmetic, the host's accounting it reads, and a + /// wait's decision on a starved guest and on a gone one. + #[test] + fn steal_clock() -> Result<(), String> { + steal_checks::served_self_check()?; + steal_checks::reading_self_check()?; + steal_checks::wait_self_check() + } + + /// Not a check: `steal_clock`'s child, spawned by it and read from outside. + #[test] + #[ignore = "a load `steal_clock` spawns and reads"] + fn one_thread_spins() { + steal_checks::one_thread_spins() + } + /// 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/qemu.rs b/tests/checks/qemu.rs index 3c91ab032e6..d883b405809 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -32,7 +32,7 @@ pub fn host_scale_self_check() -> Result<(), String> { // Finite in the worst case the suite can reach: eight vCPUs on a single // core is 8x, not unbounded — so a genuine hang still reports in bounded // time. `budget_smp` composes this with `budget`'s own capped host_scale - // (<=8x) and the run's width, and on the `--jobs 1` runner width is 1. + // (<=8x). if oversub_ratio(8, 1) != (8, 1) { return Err(format!("the worst suite case must stay finite at 8x, got {:?}", oversub_ratio(8, 1))); } diff --git a/tests/checks/steal.rs b/tests/checks/steal.rs new file mode 100644 index 00000000000..ff1d72f4a5d --- /dev/null +++ b/tests/checks/steal.rs @@ -0,0 +1,162 @@ +use std::io::{BufRead, BufReader}; +use std::process::{Command, Stdio}; +use std::sync::atomic::{AtomicBool, Ordering}; +use std::sync::{mpsc, Arc, Barrier}; +use std::time::Instant; + +use super::*; +use common::qemu::Liveness; +use common::steal::{demand, served, spent, Clock}; + +/// What [`one_thread_spins`] says once its spinner runs. +pub const SPINNING: &str = "steal: one thread spins until stdin closes"; + +/// The span each reading below is taken across. +const WINDOW: Duration = Duration::from_millis(400); + +/// [`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, held to the identity it has to satisfy whatever the +/// host's load: a thread runnable throughout a span either ran or waited for +/// all of it. Read from outside, on a child whose one runnable thread is a +/// spinner, since this process's other tests run beside it; and once the child +/// is reaped it has no accounting at all. +pub fn reading_self_check() -> Result<(), String> { + let exe = std::env::current_exe().map_err(|e| format!("this test's own binary: {e}"))?; + let mut child = Command::new(exe) + .args(["--ignored", "--exact", "checks::one_thread_spins", "--nocapture", "--test-threads=1"]) + .stdin(Stdio::piped()) + .stdout(Stdio::piped()) + .spawn() + .map_err(|e| format!("spawn a child that spins: {e}"))?; + let pid = child.id(); + let stdout = child.stdout.take().expect("piped"); + let (said, spinning) = mpsc::channel(); + let reader = thread::spawn(move || { + for line in BufReader::new(stdout).lines().map_while(Result::ok) { + if line.contains(SPINNING) { + let _ = said.send(()); + } + } + }); + let heard = spinning.recv_timeout(Duration::from_secs(30)); + let measured = heard.map_err(|e| format!("pid {pid} never said {SPINNING:?}: {e}")).and_then(|()| { + let before = demand(pid).ok_or(format!("pid {pid} has no accounting while it spins"))?; + let wall = Instant::now(); + thread::sleep(WINDOW); + let after = demand(pid).ok_or(format!("pid {pid} has no accounting while it spins"))?; + Ok((spent(&before, &after), wall.elapsed())) + }); + drop(child.stdin.take()); + let status = child.wait().map_err(|e| format!("reap pid {pid}: {e}"))?; + reader.join().map_err(|_| "the child's reader panicked")?; + let ((ran, waited), took) = measured?; + if !status.success() { + return Err(format!("the spinning child ended {status}")); + } + let slack = took / 4 + Duration::from_millis(20); + if ran + waited + slack < took || ran + waited > took + slack { + return Err(format!( + "one thread runnable for {took:?} ran {ran:?} and waited {waited:?}: the two are its \ + whole span, give or take {slack:?}" + )); + } + if let Some(said) = demand(pid) { + return Err(format!("pid {pid} is reaped and its accounting still answered {said:?}")); + } + eprintln!(" [steal] one thread runnable for {took:?} ran {ran:?} and waited {waited:?}"); + Ok(()) +} + +/// [`reading_self_check`]'s child: one thread spins until stdin closes. +pub fn one_thread_spins() { + let stop = Arc::new(AtomicBool::new(false)); + let spinner = { + let stop = Arc::clone(&stop); + thread::spawn(move || { + while !stop.load(Ordering::Relaxed) { + std::hint::spin_loop(); + } + }) + }; + println!("{SPINNING}"); + std::io::copy(&mut std::io::stdin(), &mut std::io::sink()).expect("read stdin to its end"); + stop.store(true, Ordering::Relaxed); + spinner.join().expect("the spinner panicked"); +} + +/// A wait's decision on the guest's clock, against the two guests it has to +/// tell apart: one the host starves keeps its wait past the wall's span of +/// silence, and one that is gone is called stopped at that span. +pub fn wait_self_check() -> Result<(), String> { + const QUIET: Duration = Duration::from_millis(250); + let total = Duration::from_secs(60); + + // Twice as many spinners as cores: each is served half the time at most, + // and a host busy with anything else serves them less. + let cores = thread::available_parallelism().map_err(|e| format!("this host's cores: {e}"))?; + let spinners = 2 * cores.get(); + let (stop, started) = (Arc::new(AtomicBool::new(false)), Arc::new(Barrier::new(spinners + 1))); + let threads: Vec<_> = (0..spinners) + .map(|_| { + let (stop, started) = (Arc::clone(&stop), Arc::clone(&started)); + thread::spawn(move || { + started.wait(); + while !stop.load(Ordering::Relaxed) { + std::hint::spin_loop(); + } + }) + }) + .collect(); + started.wait(); + let clock = Clock::of(std::process::id()); + let mut starved = Liveness::new(clock.clone(), QUIET, total); + let (wall, moment) = (Instant::now(), clock.now()); + thread::sleep(QUIET + QUIET / 2); + let (working, had, took) = (starved.working(""), clock.since(moment), wall.elapsed()); + stop.store(true, Ordering::Relaxed); + for spinner in threads { + spinner.join().map_err(|_| "a spinner panicked")?; + } + if !working { + return Err(format!( + "{spinners} spinners on {cores} cores had {had:?} of {took:?}, and the wait called \ + them stopped after {QUIET:?} of silence" + )); + } + + let exe = std::env::current_exe().map_err(|e| format!("this test's own binary: {e}"))?; + let mut gone = Command::new(exe) + .arg("--list") + .stdout(Stdio::null()) + .spawn() + .map_err(|e| format!("spawn a child that lists and leaves: {e}"))?; + let pid = gone.id(); + gone.wait().map_err(|e| format!("reap pid {pid}: {e}"))?; + let mut stopped = Liveness::new(Clock::of(pid), QUIET, total); + let wall = Instant::now(); + thread::sleep(QUIET + QUIET / 2); + if stopped.working("") { + return Err(format!("a guest that is gone was still working after {:?} of silence", wall.elapsed())); + } + eprintln!(" [steal] {spinners} spinners had {had:?} of {took:?} and their wait went on; a gone guest's ended"); + Ok(()) +} diff --git a/tests/common/mod.rs b/tests/common/mod.rs index d6c4b15489d..ab9b1b5f2fd 100644 --- a/tests/common/mod.rs +++ b/tests/common/mod.rs @@ -16,5 +16,6 @@ pub mod qemu; pub mod screen; pub mod serial; pub mod ssh; +pub mod steal; pub mod usb; pub mod volumes; diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 93952d7b541..86c9ab3a8e5 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -8,6 +8,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; @@ -159,51 +160,34 @@ pub fn boot_census() -> (u32, u32, Vec) { pub const DECLARED_KERNEL_BUILDS: [&str; 2] = toyos_build::build::TEST_SUITE_KERNEL_BUILDS; -/// How many guests the run 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. -static WIDTH: AtomicU32 = AtomicU32::new(1); - -pub fn set_width(width: u32) { - assert!(width >= 1, "a run boots at least one guest"); - WIDTH.store(width, Ordering::SeqCst); -} - -/// A liveness ceiling, stated for one guest and paid out for the run's width. +/// 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 width multiplies -/// it, as `wait_for_ready` multiplies the boot timeout. +/// asserting on the host's clock. Sharing the host is the clock's to take out, +/// so nothing here scales by how many guests share it. /// -/// 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. -/// -/// 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. 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 others; 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. @@ -223,12 +207,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 @@ -317,8 +299,8 @@ fn oversubscription(smp: u32) -> (u32, u32) { /// [`budget`] widened by a guest's own vCPU oversubscription. /// -/// The guest-agnostic [`budget`] scales by the run's width and boot-derived host -/// speed; this multiplies in `smp/cores` on top, so a wide-SMP guest that a +/// 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 /// every guest on the dev host. @@ -329,17 +311,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. Both spans are read on the guest's own [`steal::Clock`], so no +/// number in this type is a statement about the host. /// /// `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 @@ -348,33 +323,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, + total: Duration, + began: Moment, + last_growth: Moment, seen: usize, - give_up: Instant, } 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 silence on `clock` ends the wait, and so does `total` + /// however loud the guest is. + pub fn new(clock: steal::Clock, quiet_for: Duration, total: Duration) -> Self { + let now = clock.now(); + Self { clock, quiet_for, total, began: now, last_growth: now, seen: 0 } } /// 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.began < self.total && now - 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.since(self.began) >= self.total { "it never stopped talking and never got there" } else { "it went quiet" @@ -423,8 +400,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.clock(), GUEST_QUIET, GUEST_WEDGED) } /// A kernel line without its `[kernel cpu] ` stamp. @@ -529,8 +506,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 on the guest's clock (`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. @@ -604,7 +581,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); @@ -1051,6 +1028,8 @@ pub struct QemuInstance { smp: u32, /// The test binaries this boot put on ROOT, by the name `run` takes. carried: BTreeSet, + /// The time this guest has had, which every wait on it reads. + clock: steal::Clock, } /// Which of [`DECLARED_KERNEL_BUILDS`] this boot wants. @@ -1393,10 +1372,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 (began, ceiling) = (self.clock.now(), budget_smp(timeout, self.smp)); loop { let dump = self.screendump(); - if done(&dump) || Instant::now() >= deadline { + if done(&dump) || self.clock.since(began) >= ceiling { return dump; } thread::sleep(interval); @@ -1423,11 +1402,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. + /// 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) } @@ -1448,12 +1425,13 @@ impl QemuInstance { } fn drain_for(&mut self, dur: Duration, line: impl Fn(&str) -> bool) -> String { - let deadline = Instant::now() + dur; + let began = self.clock.now(); let mut out = String::new(); loop { - let Some(remaining) = deadline.checked_duration_since(Instant::now()) else { + let Some(remaining) = dur.checked_sub(self.clock.since(began)).filter(|left| !left.is_zero()) else { return out; }; + // Its expiry is the wall's, and the guest's clock is asked again. match self.rx.recv_timeout(remaining) { Ok(seen) => { out.push_str(&seen); @@ -1462,12 +1440,17 @@ impl QemuInstance { return out; } } - Err(RecvTimeoutError::Timeout) => return out, + Err(RecvTimeoutError::Timeout) => {} Err(RecvTimeoutError::Disconnected) => return out, } } } + /// This guest's own clock: every wait on it reads this, never the wall. + pub fn clock(&self) -> steal::Clock { + self.clock.clone() + } + /// The QMP socket this instance opened. Injection needs it, and it needs /// `BootOptions { qmp: true }`. pub fn qmp_socket(&self) -> &Path { @@ -1529,7 +1512,7 @@ impl QemuInstance { ); let timeout = budget_smp(timeout, self.smp); - let start = Instant::now(); + let start = self.clock.now(); let mut stdout = String::new(); let mut serial = String::new(); // Every line seen before this test announced itself. Kept, never @@ -1539,7 +1522,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 = start; 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 @@ -1552,9 +1535,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 @@ -1573,7 +1556,7 @@ impl QemuInstance { match self.rx.recv_timeout(Duration::from_millis(100)) { Ok(line) => { - last_line = Instant::now(); + last_line = self.clock.now(); lines += 1; step(self.sockets.qmp.as_deref(), &line); if dying.is_none() @@ -2157,6 +2140,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 = BufWriter::new(child.stdin.take().unwrap()); let stdout = child.stdout.take().unwrap(); @@ -2210,7 +2194,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 { @@ -2227,6 +2211,7 @@ fn spawn_and_wait_ready(mut qemu: Command, options: &BootOptions, files: Files) boot_log, smp: options.smp, carried, + clock, } } @@ -2266,18 +2251,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 run 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 - // run of a single guest. - // - // A wedge costs that much longer to report and nothing else. + // Twenty seconds of the guest's own clock, which is what a run of one guest + // gave it: 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 @@ -2292,12 +2272,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, @@ -2380,6 +2359,6 @@ fn wait_for_ready( } } } - record_boot(start.elapsed()); + record_boot(clock.since(start)); seen } diff --git a/tests/common/steal.rs b/tests/common/steal.rs new file mode 100644 index 00000000000..6de9c630faa --- /dev/null +++ b/tests/common/steal.rs @@ -0,0 +1,211 @@ +//! 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; this clock does not run +//! across that stretch. A guest that wanted nothing had nothing withheld, so an +//! idle guest's clock and a stopped one's are the wall's, and a guest that +//! stopped is called stopped on time however loaded the host is. + +use std::collections::BTreeMap; +use std::ops::Sub; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Arc, Mutex, PoisonError}; +use std::time::{Duration, Instant}; + +/// A point on one guest's [`Clock`]; two guests' moments are not comparable. +#[derive(Clone, Copy)] +pub struct Moment(Duration); + +impl Sub for Moment { + type Output = Duration; + + fn sub(self, earlier: Moment) -> Duration { + self.0.saturating_sub(earlier.0) + } +} + +/// 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")) +} + +/// Each of a process's threads' time on a CPU and runnable waiting for one, +/// over its life, by an id that names the same thread in every reading. +pub type Threads = BTreeMap; + +/// What `threads` ran and waited since `before`. A thread `before` lacks was +/// born inside the span; one `threads` lacks exited inside it, and only its +/// last span is lost. +pub fn spent(before: &Threads, threads: &Threads) -> (Duration, Duration) { + threads.iter().fold((Duration::ZERO, Duration::ZERO), |(ran, waited), (id, &(r, w))| { + let (r0, w0) = before.get(id).copied().unwrap_or_default(); + (ran + r.saturating_sub(r0), waited + w.saturating_sub(w0)) + }) +} + +/// 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, + threads: Threads, + had: Duration, +} + +/// The least wall time between two readings of a process's accounting: a +/// console flood reads the clock once a line. +const RESAMPLE: Duration = Duration::from_millis(5); + +/// Every guest's read spans this run, in nanoseconds: the wall clock, and what +/// of it the guest had. +static WALL_NS: AtomicU64 = AtomicU64::new(0); +static HAD_NS: AtomicU64 = AtomicU64::new(0); + +/// The wall clock this run's guests' waits read across, and what of it they +/// had: the host's load where it fell. `None` before any guest's clock has +/// been read. +pub fn run_share() -> Option<(Duration, Duration)> { + let wall = WALL_NS.load(Ordering::Relaxed); + (wall != 0).then(|| (Duration::from_nanos(wall), Duration::from_nanos(HAD_NS.load(Ordering::Relaxed)))) +} + +impl Clock { + /// The clock of process `pid`, at zero now. + pub fn of(pid: u32) -> Self { + let reading = Reading { pid, wall: Instant::now(), threads: demand(pid).unwrap_or_default(), 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(threads) => { + let (ran, waited) = spent(&reading.threads, &threads); + reading.threads = threads; + served(span, ran, waited) + } + None => span, + }; + reading.wall = wall; + reading.had += had; + WALL_NS.fetch_add(u64::try_from(span.as_nanos()).expect("a span fits u64 nanoseconds"), Ordering::Relaxed); + HAD_NS.fetch_add(u64::try_from(had.as_nanos()).expect("a span fits u64 nanoseconds"), Ordering::Relaxed); + Moment(reading.had) + } + + /// Time this guest has had since `earlier`. + pub fn since(&self, earlier: Moment) -> Duration { + self.now() - earlier + } +} + +/// Process `pid`'s threads ([`Threads`]); `None` once the process is gone. +/// +/// The task's totals, under one id: they keep what its exited threads ran. +/// `ri_runnable_time` counts a thread running as well as waiting to, so the +/// wait is what it holds past the run. +#[cfg(target_os = "macos")] +pub fn demand(pid: u32) -> Option { + // 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 ran = info.ri_user_time + info.ri_system_time; + let ticks = |count: u64| Duration::from_nanos(mach_nanos(count)); + Some(Threads::from([(0, (ticks(ran), ticks(info.ri_runnable_time.saturating_sub(ran))))])) +} + +/// 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") +} + +/// Each `/proc//task//schedstat`, by tid: nanoseconds on a CPU, then +/// nanoseconds waiting on a run queue. +#[cfg(target_os = "linux")] +pub fn demand(pid: u32) -> Option { + use std::io::ErrorKind::NotFound; + // Without it every thread's file is absent and a starved guest reads as one + // that wanted nothing. + assert!( + std::path::Path::new("/proc/self/schedstat").is_file(), + "this kernel keeps no per-task schedstat (CONFIG_SCHED_INFO), which a guest's clock reads" + ); + let tasks = match std::fs::read_dir(format!("/proc/{pid}/task")) { + Ok(tasks) => tasks, + Err(e) if e.kind() == NotFound => return None, + Err(e) => panic!("/proc/{pid}/task: {e}"), + }; + let mut threads = Threads::new(); + for task in tasks { + let task = task.unwrap_or_else(|e| panic!("/proc/{pid}/task: {e}")); + let tid = task.file_name().to_str().and_then(|t| t.parse::().ok()); + let tid = tid.unwrap_or_else(|| panic!("/proc/{pid}/task holds {:?}, which is no tid", task.file_name())); + let path = task.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()); + }; + threads.insert(tid, (Duration::from_nanos(on_cpu), Duration::from_nanos(queued))); + } + Some(threads) +} + +#[cfg(not(any(target_os = "macos", target_os = "linux")))] +pub fn demand(_: u32) -> Option { + unimplemented!("this host's scheduler accounting is not read here") +} diff --git a/tests/toyos.rs b/tests/toyos.rs index 13a0f210766..f5aee403447 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, BootOptions, QemuInstance, @@ -3232,7 +3232,8 @@ 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 clock = qemu.clock(); + let began = clock.now(); 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, @@ -3240,7 +3241,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 clock.since(began) >= qemu::GUEST_QUIET { 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}" @@ -3339,10 +3340,19 @@ 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) )); } + // How loaded the host was where the guests' waits fell, which the + // fastest boot, taken at the run's quietest moment, cannot say. + 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 @@ -3470,7 +3480,6 @@ fn run_tasks(tasks: Vec, width: usize, test_config: &Path) -> Vec 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 8b94f84389ee9d6479cde48ebcaec030406796c0 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 12:26:20 +0200 Subject: [PATCH 2/2] Review round 1: the guest clock and WIDTH's deletion go; AP_START stays The harness goes back to main's, byte for byte: `tests/common/steal.rs`, `tests/checks/steal.rs` and `steal_clock` are deleted, and every wait that read the guest's clock reads the wall again. `WIDTH`, `set_width`, `host_scale`'s wall-clock boots and the boot wait's `10 s x max(width, 2)` stand as main has them. The clock fixed no measured failure. With main's wall-clock waits, `WIDTH` and the 100 ms `AP_START` reverted in, the 21-test suite went 21/21 under 28 spinners on the 14-core dev host at a load average of 86 to 98 (`loadfree2-negctl-whole-LOAD.log`). Its Linux reading had never run, and its `unimplemented!` would have panicked every wait on any other host. Deleting `WIDTH` was justified only by the clock taking contention out; without the clock it is unmeasured, and #638 deletes it on its own terms. What stays is `time::AP_START` at `DEAF_CPU`'s 5 s, from 100 ms, and the deletion of the issue it closes. Linux arm64 waits 5000 ms for the same echo (`arch/arm64/kernel/smp.c`, `__cpu_up`). `virt_smp` booted 7 of 8 with "cpu7 mpidr=0x7 did not echo within 100ms" on a loaded host (`636r2-virt.log`). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- tests/checks.rs | 18 ---- tests/checks/qemu.rs | 2 +- tests/checks/steal.rs | 162 -------------------------------- tests/common/mod.rs | 1 - tests/common/qemu.rs | 171 +++++++++++++++++++--------------- tests/common/steal.rs | 211 ------------------------------------------ tests/toyos.rs | 19 +--- 7 files changed, 102 insertions(+), 482 deletions(-) delete mode 100644 tests/checks/steal.rs delete mode 100644 tests/common/steal.rs diff --git a/tests/checks.rs b/tests/checks.rs index 0c9220aaa88..05f9544e77d 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -19,8 +19,6 @@ mod checks { mod screen_checks; #[path = "serial.rs"] mod serial_checks; - #[path = "steal.rs"] - mod steal_checks; #[path = "usb.rs"] mod usb_checks; @@ -104,22 +102,6 @@ mod checks { clock_checks::self_check() } - /// A guest's clock: the arithmetic, the host's accounting it reads, and a - /// wait's decision on a starved guest and on a gone one. - #[test] - fn steal_clock() -> Result<(), String> { - steal_checks::served_self_check()?; - steal_checks::reading_self_check()?; - steal_checks::wait_self_check() - } - - /// Not a check: `steal_clock`'s child, spawned by it and read from outside. - #[test] - #[ignore = "a load `steal_clock` spawns and reads"] - fn one_thread_spins() { - steal_checks::one_thread_spins() - } - /// 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/qemu.rs b/tests/checks/qemu.rs index d883b405809..3c91ab032e6 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -32,7 +32,7 @@ pub fn host_scale_self_check() -> Result<(), String> { // Finite in the worst case the suite can reach: eight vCPUs on a single // core is 8x, not unbounded — so a genuine hang still reports in bounded // time. `budget_smp` composes this with `budget`'s own capped host_scale - // (<=8x). + // (<=8x) and the run's width, and on the `--jobs 1` runner width is 1. if oversub_ratio(8, 1) != (8, 1) { return Err(format!("the worst suite case must stay finite at 8x, got {:?}", oversub_ratio(8, 1))); } diff --git a/tests/checks/steal.rs b/tests/checks/steal.rs deleted file mode 100644 index ff1d72f4a5d..00000000000 --- a/tests/checks/steal.rs +++ /dev/null @@ -1,162 +0,0 @@ -use std::io::{BufRead, BufReader}; -use std::process::{Command, Stdio}; -use std::sync::atomic::{AtomicBool, Ordering}; -use std::sync::{mpsc, Arc, Barrier}; -use std::time::Instant; - -use super::*; -use common::qemu::Liveness; -use common::steal::{demand, served, spent, Clock}; - -/// What [`one_thread_spins`] says once its spinner runs. -pub const SPINNING: &str = "steal: one thread spins until stdin closes"; - -/// The span each reading below is taken across. -const WINDOW: Duration = Duration::from_millis(400); - -/// [`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, held to the identity it has to satisfy whatever the -/// host's load: a thread runnable throughout a span either ran or waited for -/// all of it. Read from outside, on a child whose one runnable thread is a -/// spinner, since this process's other tests run beside it; and once the child -/// is reaped it has no accounting at all. -pub fn reading_self_check() -> Result<(), String> { - let exe = std::env::current_exe().map_err(|e| format!("this test's own binary: {e}"))?; - let mut child = Command::new(exe) - .args(["--ignored", "--exact", "checks::one_thread_spins", "--nocapture", "--test-threads=1"]) - .stdin(Stdio::piped()) - .stdout(Stdio::piped()) - .spawn() - .map_err(|e| format!("spawn a child that spins: {e}"))?; - let pid = child.id(); - let stdout = child.stdout.take().expect("piped"); - let (said, spinning) = mpsc::channel(); - let reader = thread::spawn(move || { - for line in BufReader::new(stdout).lines().map_while(Result::ok) { - if line.contains(SPINNING) { - let _ = said.send(()); - } - } - }); - let heard = spinning.recv_timeout(Duration::from_secs(30)); - let measured = heard.map_err(|e| format!("pid {pid} never said {SPINNING:?}: {e}")).and_then(|()| { - let before = demand(pid).ok_or(format!("pid {pid} has no accounting while it spins"))?; - let wall = Instant::now(); - thread::sleep(WINDOW); - let after = demand(pid).ok_or(format!("pid {pid} has no accounting while it spins"))?; - Ok((spent(&before, &after), wall.elapsed())) - }); - drop(child.stdin.take()); - let status = child.wait().map_err(|e| format!("reap pid {pid}: {e}"))?; - reader.join().map_err(|_| "the child's reader panicked")?; - let ((ran, waited), took) = measured?; - if !status.success() { - return Err(format!("the spinning child ended {status}")); - } - let slack = took / 4 + Duration::from_millis(20); - if ran + waited + slack < took || ran + waited > took + slack { - return Err(format!( - "one thread runnable for {took:?} ran {ran:?} and waited {waited:?}: the two are its \ - whole span, give or take {slack:?}" - )); - } - if let Some(said) = demand(pid) { - return Err(format!("pid {pid} is reaped and its accounting still answered {said:?}")); - } - eprintln!(" [steal] one thread runnable for {took:?} ran {ran:?} and waited {waited:?}"); - Ok(()) -} - -/// [`reading_self_check`]'s child: one thread spins until stdin closes. -pub fn one_thread_spins() { - let stop = Arc::new(AtomicBool::new(false)); - let spinner = { - let stop = Arc::clone(&stop); - thread::spawn(move || { - while !stop.load(Ordering::Relaxed) { - std::hint::spin_loop(); - } - }) - }; - println!("{SPINNING}"); - std::io::copy(&mut std::io::stdin(), &mut std::io::sink()).expect("read stdin to its end"); - stop.store(true, Ordering::Relaxed); - spinner.join().expect("the spinner panicked"); -} - -/// A wait's decision on the guest's clock, against the two guests it has to -/// tell apart: one the host starves keeps its wait past the wall's span of -/// silence, and one that is gone is called stopped at that span. -pub fn wait_self_check() -> Result<(), String> { - const QUIET: Duration = Duration::from_millis(250); - let total = Duration::from_secs(60); - - // Twice as many spinners as cores: each is served half the time at most, - // and a host busy with anything else serves them less. - let cores = thread::available_parallelism().map_err(|e| format!("this host's cores: {e}"))?; - let spinners = 2 * cores.get(); - let (stop, started) = (Arc::new(AtomicBool::new(false)), Arc::new(Barrier::new(spinners + 1))); - let threads: Vec<_> = (0..spinners) - .map(|_| { - let (stop, started) = (Arc::clone(&stop), Arc::clone(&started)); - thread::spawn(move || { - started.wait(); - while !stop.load(Ordering::Relaxed) { - std::hint::spin_loop(); - } - }) - }) - .collect(); - started.wait(); - let clock = Clock::of(std::process::id()); - let mut starved = Liveness::new(clock.clone(), QUIET, total); - let (wall, moment) = (Instant::now(), clock.now()); - thread::sleep(QUIET + QUIET / 2); - let (working, had, took) = (starved.working(""), clock.since(moment), wall.elapsed()); - stop.store(true, Ordering::Relaxed); - for spinner in threads { - spinner.join().map_err(|_| "a spinner panicked")?; - } - if !working { - return Err(format!( - "{spinners} spinners on {cores} cores had {had:?} of {took:?}, and the wait called \ - them stopped after {QUIET:?} of silence" - )); - } - - let exe = std::env::current_exe().map_err(|e| format!("this test's own binary: {e}"))?; - let mut gone = Command::new(exe) - .arg("--list") - .stdout(Stdio::null()) - .spawn() - .map_err(|e| format!("spawn a child that lists and leaves: {e}"))?; - let pid = gone.id(); - gone.wait().map_err(|e| format!("reap pid {pid}: {e}"))?; - let mut stopped = Liveness::new(Clock::of(pid), QUIET, total); - let wall = Instant::now(); - thread::sleep(QUIET + QUIET / 2); - if stopped.working("") { - return Err(format!("a guest that is gone was still working after {:?} of silence", wall.elapsed())); - } - eprintln!(" [steal] {spinners} spinners had {had:?} of {took:?} and their wait went on; a gone guest's ended"); - Ok(()) -} diff --git a/tests/common/mod.rs b/tests/common/mod.rs index ab9b1b5f2fd..d6c4b15489d 100644 --- a/tests/common/mod.rs +++ b/tests/common/mod.rs @@ -16,6 +16,5 @@ pub mod qemu; pub mod screen; pub mod serial; pub mod ssh; -pub mod steal; pub mod usb; pub mod volumes; diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 86c9ab3a8e5..93952d7b541 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -8,7 +8,6 @@ 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; @@ -160,34 +159,51 @@ pub fn boot_census() -> (u32, u32, Vec) { pub const DECLARED_KERNEL_BUILDS: [&str; 2] = toyos_build::build::TEST_SUITE_KERNEL_BUILDS; -/// 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`]. +/// How many guests the run 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. +static WIDTH: AtomicU32 = AtomicU32::new(1); + +pub fn set_width(width: u32) { + assert!(width >= 1, "a run boots at least one guest"); + WIDTH.store(width, Ordering::SeqCst); +} + +/// A liveness ceiling, stated for one guest and paid out for the run's width. /// /// 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. Sharing the host is the clock's to take out, -/// so nothing here scales by how many guests share it. +/// 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 width multiplies +/// it, as `wait_for_ready` multiplies the boot timeout. /// -/// 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. Callers that hold a guest want that one, so its -/// ceiling reflects the vCPUs it actually asked for. +/// 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. +/// +/// 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. pub fn budget(one_guest: Duration) -> Duration { let (num, den) = host_scale(); - one_guest * num / den + one_guest * WIDTH.load(Ordering::SeqCst) * num / den } -/// The fastest boot-to-ready this run has seen, in milliseconds of the booting -/// guest's own clock. +/// The fastest boot-to-ready this run has seen, in milliseconds. /// /// 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 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 a boot +/// taken with three other guests up measures the others; 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. @@ -207,10 +223,12 @@ 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. /// -/// 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. +/// [`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. /// /// **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 @@ -299,8 +317,8 @@ fn oversubscription(smp: u32) -> (u32, u32) { /// [`budget`] widened by a guest's own vCPU oversubscription. /// -/// The guest-agnostic [`budget`] scales by boot-derived host speed; this -/// multiplies in `smp/cores` on top, so a wide-SMP guest that a +/// The guest-agnostic [`budget`] scales by the run's width and 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 /// every guest on the dev host. @@ -311,10 +329,17 @@ pub fn budget_smp(one_guest: Duration, smp: u32) -> Duration { /// A liveness guard that watches the guest instead of the host's clock. /// -/// 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. Both spans are read on the guest's own [`steal::Clock`], so no -/// number in this type is a statement about the host. +/// [`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. /// /// `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 @@ -323,35 +348,33 @@ 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, - total: Duration, - began: Moment, - last_growth: Moment, + last_growth: Instant, seen: usize, + give_up: Instant, } impl Liveness { - /// `quiet_for` of silence on `clock` ends the wait, and so does `total` - /// however loud the guest is. - pub fn new(clock: steal::Clock, quiet_for: Duration, total: Duration) -> Self { - let now = clock.now(); - Self { clock, quiet_for, total, began: now, last_growth: now, seen: 0 } + /// `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 } } /// 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 = now; + self.last_growth = Instant::now(); } - now - self.began < self.total && now - self.last_growth < self.quiet_for + let now = Instant::now(); + now < self.give_up && now.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 self.clock.since(self.began) >= self.total { + if Instant::now() >= self.give_up { "it never stopped talking and never got there" } else { "it went quiet" @@ -400,8 +423,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(guest: &QemuInstance) -> Liveness { - Liveness::new(guest.clock(), GUEST_QUIET, GUEST_WEDGED) +pub fn guest_liveness() -> Liveness { + Liveness::new(GUEST_QUIET, GUEST_WEDGED) } /// A kernel line without its `[kernel cpu] ` stamp. @@ -506,8 +529,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 its -/// budget on the guest's clock (`budget_smp`-scaled, so it already carries #256's +/// **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 /// `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. @@ -581,7 +604,7 @@ pub fn await_guest( ) -> Result<(), String> { // Where this wait's own evidence starts. let from = log.len(); - let mut live = guest_liveness(qemu); + let mut live = guest_liveness(); while !done(log) && live.working(log) { let more = qemu.drain_serial(Duration::from_millis(200)); log.push_str(&more); @@ -1028,8 +1051,6 @@ pub struct QemuInstance { smp: u32, /// The test binaries this boot put on ROOT, by the name `run` takes. carried: BTreeSet, - /// The time this guest has had, which every wait on it reads. - clock: steal::Clock, } /// Which of [`DECLARED_KERNEL_BUILDS`] this boot wants. @@ -1372,10 +1393,10 @@ impl QemuInstance { interval: Duration, done: impl Fn(&super::screen::Ppm) -> bool, ) -> super::screen::Ppm { - let (began, ceiling) = (self.clock.now(), budget_smp(timeout, self.smp)); + let deadline = Instant::now() + budget_smp(timeout, self.smp); loop { let dump = self.screendump(); - if done(&dump) || self.clock.since(began) >= ceiling { + if done(&dump) || Instant::now() >= deadline { return dump; } thread::sleep(interval); @@ -1402,9 +1423,11 @@ impl QemuInstance { self.stdin.flush().expect("Failed to flush QEMU stdin"); } - /// 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. + /// 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. pub fn drain_serial(&mut self, dur: Duration) -> String { self.drain_for(dur, |_| false) } @@ -1425,13 +1448,12 @@ impl QemuInstance { } fn drain_for(&mut self, dur: Duration, line: impl Fn(&str) -> bool) -> String { - let began = self.clock.now(); + let deadline = Instant::now() + dur; let mut out = String::new(); loop { - let Some(remaining) = dur.checked_sub(self.clock.since(began)).filter(|left| !left.is_zero()) else { + let Some(remaining) = deadline.checked_duration_since(Instant::now()) else { return out; }; - // Its expiry is the wall's, and the guest's clock is asked again. match self.rx.recv_timeout(remaining) { Ok(seen) => { out.push_str(&seen); @@ -1440,17 +1462,12 @@ impl QemuInstance { return out; } } - Err(RecvTimeoutError::Timeout) => {} + Err(RecvTimeoutError::Timeout) => return out, Err(RecvTimeoutError::Disconnected) => return out, } } } - /// This guest's own clock: every wait on it reads this, never the wall. - pub fn clock(&self) -> steal::Clock { - self.clock.clone() - } - /// The QMP socket this instance opened. Injection needs it, and it needs /// `BootOptions { qmp: true }`. pub fn qmp_socket(&self) -> &Path { @@ -1512,7 +1529,7 @@ impl QemuInstance { ); let timeout = budget_smp(timeout, self.smp); - let start = self.clock.now(); + let start = Instant::now(); let mut stdout = String::new(); let mut serial = String::new(); // Every line seen before this test announced itself. Kept, never @@ -1522,7 +1539,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 = start; + let mut last_line = Instant::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 @@ -1535,9 +1552,9 @@ impl QemuInstance { loop { if let Some(error) = ceiling_verdict( dying.as_deref(), - self.clock.since(start), + start.elapsed(), timeout, - self.clock.since(last_line), + last_line.elapsed(), lines, ) { // The window in the order the guest wrote it: `before` holds @@ -1556,7 +1573,7 @@ impl QemuInstance { match self.rx.recv_timeout(Duration::from_millis(100)) { Ok(line) => { - last_line = self.clock.now(); + last_line = Instant::now(); lines += 1; step(self.sockets.qmp.as_deref(), &line); if dying.is_none() @@ -2140,7 +2157,6 @@ 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 = BufWriter::new(child.stdin.take().unwrap()); let stdout = child.stdout.take().unwrap(); @@ -2194,7 +2210,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, &clock) + wait_for_ready(&mut child, &rx, options, &uart_log) }; QemuInstance { @@ -2211,7 +2227,6 @@ fn spawn_and_wait_ready(mut qemu: Command, options: &BootOptions, files: Files) boot_log, smp: options.smp, carried, - clock, } } @@ -2251,13 +2266,18 @@ 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; - // Twenty seconds of the guest's own clock, which is what a run of one guest - // gave it: sharing the host is the clock's to take out. + // Ten seconds per guest this run 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 + // run of a single guest. + // + // A wedge costs that much longer to report and nothing else. // // 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 @@ -2272,11 +2292,12 @@ 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(20) * num / den * onum / oden; - let start = clock.now(); + let boot_timeout = + Duration::from_secs(10) * WIDTH.load(Ordering::SeqCst).max(2) * num / den * onum / oden; + let start = Instant::now(); let mut seen = String::new(); loop { - if !no_timeout && clock.since(start) > boot_timeout { + if !no_timeout && start.elapsed() > 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, @@ -2359,6 +2380,6 @@ fn wait_for_ready( } } } - record_boot(clock.since(start)); + record_boot(start.elapsed()); seen } diff --git a/tests/common/steal.rs b/tests/common/steal.rs deleted file mode 100644 index 6de9c630faa..00000000000 --- a/tests/common/steal.rs +++ /dev/null @@ -1,211 +0,0 @@ -//! 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; this clock does not run -//! across that stretch. A guest that wanted nothing had nothing withheld, so an -//! idle guest's clock and a stopped one's are the wall's, and a guest that -//! stopped is called stopped on time however loaded the host is. - -use std::collections::BTreeMap; -use std::ops::Sub; -use std::sync::atomic::{AtomicU64, Ordering}; -use std::sync::{Arc, Mutex, PoisonError}; -use std::time::{Duration, Instant}; - -/// A point on one guest's [`Clock`]; two guests' moments are not comparable. -#[derive(Clone, Copy)] -pub struct Moment(Duration); - -impl Sub for Moment { - type Output = Duration; - - fn sub(self, earlier: Moment) -> Duration { - self.0.saturating_sub(earlier.0) - } -} - -/// 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")) -} - -/// Each of a process's threads' time on a CPU and runnable waiting for one, -/// over its life, by an id that names the same thread in every reading. -pub type Threads = BTreeMap; - -/// What `threads` ran and waited since `before`. A thread `before` lacks was -/// born inside the span; one `threads` lacks exited inside it, and only its -/// last span is lost. -pub fn spent(before: &Threads, threads: &Threads) -> (Duration, Duration) { - threads.iter().fold((Duration::ZERO, Duration::ZERO), |(ran, waited), (id, &(r, w))| { - let (r0, w0) = before.get(id).copied().unwrap_or_default(); - (ran + r.saturating_sub(r0), waited + w.saturating_sub(w0)) - }) -} - -/// 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, - threads: Threads, - had: Duration, -} - -/// The least wall time between two readings of a process's accounting: a -/// console flood reads the clock once a line. -const RESAMPLE: Duration = Duration::from_millis(5); - -/// Every guest's read spans this run, in nanoseconds: the wall clock, and what -/// of it the guest had. -static WALL_NS: AtomicU64 = AtomicU64::new(0); -static HAD_NS: AtomicU64 = AtomicU64::new(0); - -/// The wall clock this run's guests' waits read across, and what of it they -/// had: the host's load where it fell. `None` before any guest's clock has -/// been read. -pub fn run_share() -> Option<(Duration, Duration)> { - let wall = WALL_NS.load(Ordering::Relaxed); - (wall != 0).then(|| (Duration::from_nanos(wall), Duration::from_nanos(HAD_NS.load(Ordering::Relaxed)))) -} - -impl Clock { - /// The clock of process `pid`, at zero now. - pub fn of(pid: u32) -> Self { - let reading = Reading { pid, wall: Instant::now(), threads: demand(pid).unwrap_or_default(), 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(threads) => { - let (ran, waited) = spent(&reading.threads, &threads); - reading.threads = threads; - served(span, ran, waited) - } - None => span, - }; - reading.wall = wall; - reading.had += had; - WALL_NS.fetch_add(u64::try_from(span.as_nanos()).expect("a span fits u64 nanoseconds"), Ordering::Relaxed); - HAD_NS.fetch_add(u64::try_from(had.as_nanos()).expect("a span fits u64 nanoseconds"), Ordering::Relaxed); - Moment(reading.had) - } - - /// Time this guest has had since `earlier`. - pub fn since(&self, earlier: Moment) -> Duration { - self.now() - earlier - } -} - -/// Process `pid`'s threads ([`Threads`]); `None` once the process is gone. -/// -/// The task's totals, under one id: they keep what its exited threads ran. -/// `ri_runnable_time` counts a thread running as well as waiting to, so the -/// wait is what it holds past the run. -#[cfg(target_os = "macos")] -pub fn demand(pid: u32) -> Option { - // 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 ran = info.ri_user_time + info.ri_system_time; - let ticks = |count: u64| Duration::from_nanos(mach_nanos(count)); - Some(Threads::from([(0, (ticks(ran), ticks(info.ri_runnable_time.saturating_sub(ran))))])) -} - -/// 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") -} - -/// Each `/proc//task//schedstat`, by tid: nanoseconds on a CPU, then -/// nanoseconds waiting on a run queue. -#[cfg(target_os = "linux")] -pub fn demand(pid: u32) -> Option { - use std::io::ErrorKind::NotFound; - // Without it every thread's file is absent and a starved guest reads as one - // that wanted nothing. - assert!( - std::path::Path::new("/proc/self/schedstat").is_file(), - "this kernel keeps no per-task schedstat (CONFIG_SCHED_INFO), which a guest's clock reads" - ); - let tasks = match std::fs::read_dir(format!("/proc/{pid}/task")) { - Ok(tasks) => tasks, - Err(e) if e.kind() == NotFound => return None, - Err(e) => panic!("/proc/{pid}/task: {e}"), - }; - let mut threads = Threads::new(); - for task in tasks { - let task = task.unwrap_or_else(|e| panic!("/proc/{pid}/task: {e}")); - let tid = task.file_name().to_str().and_then(|t| t.parse::().ok()); - let tid = tid.unwrap_or_else(|| panic!("/proc/{pid}/task holds {:?}, which is no tid", task.file_name())); - let path = task.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()); - }; - threads.insert(tid, (Duration::from_nanos(on_cpu), Duration::from_nanos(queued))); - } - Some(threads) -} - -#[cfg(not(any(target_os = "macos", target_os = "linux")))] -pub fn demand(_: u32) -> Option { - unimplemented!("this host's scheduler accounting is not read here") -} diff --git a/tests/toyos.rs b/tests/toyos.rs index f5aee403447..13a0f210766 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; +use std::time::{Duration, Instant}; use common::qemu::{ self, await_guest, await_marker, BootOptions, QemuInstance, @@ -3232,8 +3232,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 clock = qemu.clock(); - let began = clock.now(); + let give_up = Instant::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, @@ -3241,7 +3240,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 clock.since(began) >= qemu::GUEST_QUIET { + if Instant::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}" @@ -3340,19 +3339,10 @@ 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", + ceilings paid at {:.2}x width", f64::from(num) / f64::from(den) )); } - // How loaded the host was where the guests' waits fell, which the - // fastest boot, taken at the run's quietest moment, cannot say. - 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 @@ -3480,6 +3470,7 @@ fn run_tasks(tasks: Vec, width: usize, test_config: &Path) -> Vec 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| {