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 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 7ba2ad8060e..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. /// @@ -92,10 +97,13 @@ 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(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"); @@ -614,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}"));