A guest test waits for a kernel record and for a program's line each, where it read one off a capture the other ended

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

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<String> = 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(&not_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(&not_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())?;

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();

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}"));