From c424f96d32bca736b5c558414fa57e89301f31a4 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 00:06:45 +0200 Subject: [PATCH 1/3] machine_shutdown_short_stop waits for the server's armed line before it reads it The test waited for the kernel's record of the sleep type and then asserted acpiserver's armed line on the capture that wait ended. The server says the armed line first, but a program's line reaches the console when logkeeper has read the program's ring and queued it, and the kernel's record does not go that way: a capture that ends at the record need not hold the line. Seen red once, beside machine_shutdown and acpi_power_button in one filtered run on a host at load 51 (1 min), with the kernel's record stamped 15.521 s and no program's line stamped after 15.175 s; green alone at load 45. It now waits for the armed line itself, as acpi_power_button does, and then for the record, each under await_marker's own guard, so a server that never arms is a stall named for what it waited on. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- tests/common/power.rs | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/tests/common/power.rs b/tests/common/power.rs index 7ba2ad8060e..43de9bf0dc0 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -92,10 +92,14 @@ pub fn machine_shutdown_short_stop(test_config: &Path) -> Result<(), String> { let boot = serial::Serial::boot(&qemu); boot.must_be_clean()?; let mut console = boot.text().to_string(); + // A wait each: the server's line reaches the console through `logkeeper` + // and the kernel's record does not, so a capture that ends at either need + // not hold the other. + qemu::await_marker(&mut qemu, &mut console, ACPI_ARMED, "the ACPI server arming")?; qemu::await_marker(&mut qemu, &mut console, Q35_S5_SUPPLIED, "the ACPI server to hand the kernel \\_S5")?; - let armed = serial::Serial::named("boot", console.clone()); - armed.must_say(ACPI_ARMED)?; - armed.must_say("acpi: the firmware handed this machine over in ACPI mode, so nothing is written")?; + // The kernel's own record, committed before the one just waited for. + serial::Serial::named("boot", console.clone()) + .must_say("acpi: the firmware handed this machine over in ACPI mode, so nothing is written")?; let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET)); writeln!(qemu.stdin_mut(), "run test_rs_stop_short").expect("write to QEMU stdin"); From 0c0a348e151c491d787141324524f0a5abeddc58 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 01:58:07 +0200 Subject: [PATCH 2/3] A kernel record and a program's line are each waited for, wherever one was read off a capture the other ended A kernel record goes on the console as klogd drains the kernel's ring, and a program's line once logkeeper has queued it; klogd takes at most CHUNK of each per hold of the wire, so neither kind is held back for the other and a capture that ends at one need not hold the other. The short stop was the one site seen red. The review of that fix named two more of the same shape, and a sweep of every wait in tests/common and tests/toyos.rs found three: - acpi_power_button: the kernel's ACPI-mode record, read off the capture the server's armed line ended. - virt_reboot_refused_without_psci: the kernel's refusal, read off the capture test-runner's end of the job ended. - virt_smp, virt_el1_smp: each CPU's "joining scheduler", said after the machine is released, read off the capture the first job's end ended. - virt_job (seven tests): the kernel's record of logkeeper's spawn, which bootlog::one_clock owes, read off the capture the job's end ended. - iommu_virtio_platform: the kernel's records of the claim (the BAR moved and MSI-X armed, or the two refusals), read off the capture the daemons' lines ended. Each now waits on its own marker under await_guest's existing guard. A record the kernel makes before klogd starts is not waited for: kernel_main drains it inline, before any program exists. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- tests/common/iommu.rs | 27 +++++++++++++++++++++------ tests/common/power.rs | 15 +++++++++------ tests/toyos.rs | 25 +++++++++++++++++-------- 3 files changed, 47 insertions(+), 20 deletions(-) diff --git a/tests/common/iommu.rs b/tests/common/iommu.rs index 3dac6ab3973..f2bac2cebb8 100644 --- a/tests/common/iommu.rs +++ b/tests/common/iommu.rs @@ -64,11 +64,19 @@ pub fn iommu_virtio_platform(test_config: &Path) -> Result<(), String> { // that runs it. A daemon's line is waited for on the stream: the boot // log ends at test-runner's `===READY===`, its first act, and nothing // orders that against what the programs the supervisor started before it print. + // And the kernel's records of a claim with them: those reach the + // console by the kernel's own road, which nothing orders against a + // program's line either. let mut qemu = QemuInstance::boot_with_options(&netcase(), &[], &[], options); - let said: &[&str] = if behind_unit { - &[CLAIM_BOUNDED, NETSTACK_NEGOTIATED] + let said: Vec = if behind_unit { + vec![CLAIM_BOUNDED.to_string(), NETSTACK_NEGOTIATED.to_string(), bar_moved(), msix_armed()] } else { - &[DISKSERVER_REFUSED, FILESERVER_WITHOUT_DATA] + vec![ + DISKSERVER_REFUSED.to_string(), + FILESERVER_WITHOUT_DATA.to_string(), + not_handed_over(CLAIMED_AT, NOT_REMAPPED), + not_handed_over(NVME_AT, NOT_REMAPPED), + ] }; let mut text = qemu.boot_log().to_string(); qemu::await_guest(&mut qemu, &mut text, &format!("{name}: {said:?}"), |t| { @@ -174,6 +182,14 @@ const FILESERVER_WITHOUT_DATA: &str = /// the one its diskserver row claims. const NVME_AT: &str = "00:02.0"; +/// Why a machine with no unit hands no function over, in the kernel's words. +const NOT_REMAPPED: &str = "its interrupts would not be remapped on this machine"; + +/// The kernel's record of a claim on the function at `at` refused for `why`. +fn not_handed_over(at: &str, why: &str) -> String { + format!("pcidev: PCI {at} NOT HANDED OVER — {why}") +} + /// **A machine with no unit hands no function to a process**, and says so /// three times over. /// @@ -188,10 +204,9 @@ const NVME_AT: &str = "00:02.0"; /// NVMe controller is refused the same, and DATA with it by name: a disk that /// is there and cannot be used is never answered with memory. fn no_unit_is_no_claim(log: &Serial) -> Result<(), String> { - const NOT_REMAPPED: &str = "its interrupts would not be remapped on this machine"; // netstack's own exit is the third saying, and is not read here. refused_claim(log, NETSTACK_CLAIMS, NOT_REMAPPED, &[NVME_AT])?; - log.must_say(&format!("pcidev: PCI {NVME_AT} NOT HANDED OVER — {NOT_REMAPPED}"))?; + log.must_say(¬_handed_over(NVME_AT, NOT_REMAPPED))?; log.must_say("supervisor: diskserver: pci:1b36:0010 is on this machine and could not be handed over")?; log.must_say(DISKSERVER_REFUSED)?; log.must_say(FILESERVER_WITHOUT_DATA)?; @@ -315,7 +330,7 @@ fn refused_claim(log: &Serial, claims: &str, why: &str, beside: &[&str]) -> Resu // By the reason true of the path that raised it, on the line that names the // function: a refusal whose reason belongs to another path is worse than no // line at all. - log.must_say(&format!("pcidev: PCI {CLAIMED_AT} NOT HANDED OVER — {why}"))?; + log.must_say(¬_handed_over(CLAIMED_AT, why))?; log.must_not_say(&format!("[{claims}] handed over"))?; log.must_not_say(&msix_armed())?; log.must_not_say(&msi_armed())?; diff --git a/tests/common/power.rs b/tests/common/power.rs index 43de9bf0dc0..5728053528c 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -17,6 +17,11 @@ pub const SHUTTING_DOWN: &str = "Shutting down."; /// `\_S5` names, which is the one its ICH9 powers off on. const Q35_S5_SUPPLIED: &str = "power: S5 is PM1a 0x604 with SLP_TYPa=0,"; +/// What the kernel logs at the `acpi` claim on a machine its firmware handed +/// over in ACPI mode (`kernel/src/arch/x86_64/acpi_mode.rs`), as OVMF does +/// q35: the enable and its wait are the T14's to exercise (`acpi_mode`). +const HANDED_OVER_IN_ACPI_MODE: &str = "acpi: the firmware handed this machine over in ACPI mode, so nothing is written"; + /// Wait for the boot's `last` word on a guest asked to end, then for QEMU to /// stop for `reason` and exit; `console` gains everything said on the way. /// @@ -98,8 +103,7 @@ pub fn machine_shutdown_short_stop(test_config: &Path) -> Result<(), String> { qemu::await_marker(&mut qemu, &mut console, ACPI_ARMED, "the ACPI server arming")?; qemu::await_marker(&mut qemu, &mut console, Q35_S5_SUPPLIED, "the ACPI server to hand the kernel \\_S5")?; // The kernel's own record, committed before the one just waited for. - serial::Serial::named("boot", console.clone()) - .must_say("acpi: the firmware handed this machine over in ACPI mode, so nothing is written")?; + serial::Serial::named("boot", console.clone()).must_say(HANDED_OVER_IN_ACPI_MODE)?; let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET)); writeln!(qemu.stdin_mut(), "run test_rs_stop_short").expect("write to QEMU stdin"); @@ -618,11 +622,10 @@ pub fn acpi_power_button(test_config: &Path) -> Result<(), String> { let boot = serial::Serial::boot(&qemu); boot.must_be_clean()?; let mut console = boot.text().to_string(); + // A wait each, as in `machine_shutdown_short_stop`: the server's line and + // the kernel's record reach the console by different roads. qemu::await_marker(&mut qemu, &mut console, ACPI_ARMED, "the ACPI server arming")?; - let mode = serial::Serial::named("boot", console.clone()); - // OVMF hands q35 over in ACPI mode, so the mint writes nothing: the - // enable and its wait are the T14's to exercise (`acpi_mode`). - mode.must_say("acpi: the firmware handed this machine over in ACPI mode, so nothing is written")?; + qemu::await_marker(&mut qemu, &mut console, HANDED_OVER_IN_ACPI_MODE, "the kernel's record of the mode it was handed over in")?; let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET)); stop.power_button(); diff --git a/tests/toyos.rs b/tests/toyos.rs index 95cb23ad433..45454c46fc3 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1669,6 +1669,9 @@ fn virt_job(profile: qemu::Profile, job: &str, said: &str) -> Result<(), String> ); let mut serial = virt_console(&qemu); judge_virt_job(&mut qemu, &mut serial, job, said)?; + // The kernel's record `one_clock` reads beside the supervisor's line: it + // reaches the PL011 by the kernel's road, and the job's end by `logkeeper`'s. + await_marker(&mut qemu, &mut serial, bootlog::LOGKEEPER_SPAWN, "the kernel's record of logkeeper's spawn")?; // The one console that carries the loader's, the kernel's and a program's // lines on a CPU that states its counter's rate: the T14's metal rows // judge the same on x86-64, and no machine of this architecture has one. @@ -1960,13 +1963,18 @@ fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String let mut want = vec![format!("SMP: {VIRT_CPUS} of {VIRT_CPUS} MADT CPUs online")]; for cpu in 1..VIRT_CPUS { want.push(format!("SMP: cpu{cpu} mpidr={cpu:#x} online")); - want.push(format!("CPU {cpu}: joining scheduler")); } for want in want { if !serial.contains(&want) { return Err(format!("{want:?} not on the PL011\nserial:\n{serial}")); } } + // Waited for: a CPU says this once the machine is released, so it reaches + // the PL011 by the kernel's road beside the job's end on `logkeeper`'s. + for cpu in 1..VIRT_CPUS { + let joined = format!("CPU {cpu}: joining scheduler"); + await_marker(&mut qemu, &mut serial, &joined, &format!("cpu{cpu} to join the scheduler"))?; + } let entered = format!("as declared; entered at EL{el}"); for cpu in 0..VIRT_CPUS { if !serial.lines().any(|l| record_cpu(l) == Some(cpu) && l.contains(&entered)) { @@ -2196,13 +2204,14 @@ fn virt_reboot_refused_without_psci(profile: qemu::Profile) -> Result<(), String ..Default::default() }, ); - let mut rest = String::new(); - await_marker(&mut qemu, &mut rest, "===TEST_END reboot ", "the job reboot to end")?; - let console = format!("{}\n{rest}", qemu.boot_log()); - for said in [REBOOT_REFUSED, "===TEST_END reboot exit=1==="] { - if !console.contains(said) { - return Err(format!("{said:?} not on the PL011\n{console}")); - } + let mut console = virt_console(&qemu); + // A wait each: the job's end is test-runner's line and the refusal the + // kernel's record, and the two reach the PL011 by different roads. + await_marker(&mut qemu, &mut console, "===TEST_END reboot ", "the job reboot to end")?; + await_marker(&mut qemu, &mut console, REBOOT_REFUSED, "the kernel's refusal of the reboot") + .map_err(|why| format!("{why}\n{console}"))?; + if !console.contains("===TEST_END reboot exit=1===") { + return Err(format!("the job reboot did not end with exit 1\n{console}")); } if console.contains(bootlog::REBOOTING) { return Err(format!("a machine with no reset began one\n{console}")); From f9006e888758638e62b5b79b94bfcad65f716a04 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 02:29:23 +0200 Subject: [PATCH 3/3] The counters read's silence is recorded a second time, on virt_smp `virt_smp` stalled once in this branch's round-3 guest run, in `judge_virt_job`'s wait for `test_rs_counters_read` to end, a wait this branch does not touch. The defect is `main`'s and already has its file; the file gains this occurrence: the line, the host's load, the wait that ended it, what differs from the first silent boot, what the run shows and what it does not. Each number was read off that run's log, which is not kept in the tree. No register capture exists for this one either, so the exit is no closer. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- ...-under-host-load-can-go-silent-for-15-s.md | 39 ++++++++++++++++++- 1 file changed, 37 insertions(+), 2 deletions(-) diff --git a/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md b/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md index ebc005a0361..04508750a14 100644 --- a/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md +++ b/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md @@ -8,10 +8,10 @@ opened: 2026-10-04 `test_rs_counters_read` in `tests/virtsmpcase` normally ends about 0.2 s of guest clock after `unmap_touch` does (median 0.17-0.20 s over 570 guests, max -1.46 s). Under host load it sometimes takes seconds, and once it went silent +1.46 s). Under host load it sometimes takes seconds, and twice it went silent long enough for the harness's 15 s quiet bound to call the guest stalled. -The silent one: `virt_el1_smp`, 8 vCPUs under TCG, on a 14-core host at +The first silent one: `virt_el1_smp`, 8 vCPUs under TCG, on a 14-core host at 1-minute load 38-53 while the primary checkout was building the stage-2 compiler; the branch `wt/toyos-counterstall` at `bc5f36c7b`, whose harness keeps every line the guest said. `test_rs_counters_read` started at 4.031, @@ -23,6 +23,41 @@ the console stopped. No register capture of that guest exists. One in 30 guests of that loop; none in the 1724 guests that followed on the same host at load 15-60. +The second silent one: `virt_smp` (EL2, started through SMC), the first on +that profile, on `wt/toyos-shortstop` at `0c0a348e1`, whose diff touches no +line of the wait and none the guest runs. + +- **The line.** `FAIL virt_smp: STALLED: waiting for the job + test_rs_counters_read to end — it went quiet`. +- **The load.** 14 tests 12 wide on the 14-core host, 1-minute load 30.40 when + the run began and 50.09 when it ended, from other worktrees' builds; + liveness ceilings paid at 4.98x; workers 1440 s building against 1072 s + testing. +- **The wait.** `judge_virt_job`'s `await_marker` on + `===TEST_END test_rs_counters_read `, ended by `GUEST_QUIET`, which is 15 s + of wall clock and is not paid out for host speed or guest width as + `GUEST_WEDGED` is. +- **What differs from the first.** The silence begins straight after the + job's first spawn record, with no thread's exit on the console: the guest's + last three lines are `===TEST_END unmap_touch exit=0===` and + `===TEST_START test_rs_counters_read===` at 13.724 and the kernel's + `spawn: /system/bin/test_rs_counters_read pid=13` at 13.737, and nothing + reached the harness in the 15 s of wall clock after them. +- **What is known.** `virt_el1_smp`, the same case booted one second later + beside it, did the same step in about one second of wall clock (the job's + spawn at guest 14.757, its end at 15.908) and had exited eleven seconds + before the verdict; the run's twelve other tests had ended earlier still, + so for the last eleven seconds of the silence no other guest of that run + was alive. `virt_smp` alone at load 52.19 passed in 9 s, the job ending + 0.4 s of guest clock after its start, and in the same group of 14 at load + 24.75 it passed: one silent boot in the five of that case at that commit. +- **What is not known.** Whether the guest was running, spinning or not being + scheduled by the host, and whether it was the guest or its console that + stopped. No register capture of it exists either, so it adds a count and a + second profile and brings the exit no closer. The fork compiler miscompiles, + for AArch64, an inclusive range that ends at its integer type's maximum; + whether that reaches this job's code has not been examined. + The slow ones, with registers: a probe that captured `info registers -a` over QMP whenever the read had not ended 3 s after `unmap_touch` (`debug-slow.patch` in https://github.com/ToyOSOrg/ToyOS/pull/719#issuecomment-5978643928, which