virt_smp's second job wait goes on from the capture its first wait drained

issues/kernel/a-counters-read-under-host-load-can-go-silent-for-15-s.md

@@ -0,0 +1,44 @@
+---
+status: open
+kind: defect
+opened: 2026-10-04
+---
+
+# A counters read under host load can go silent for 15 s on an 8-CPU `virt` guest
+
+`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
+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
+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,
+spawned at 4.044, two of its threads exited (4.174 and 4.576), and then the
+console carried nothing until the harness gave up 15 s later. No CPU printed
+`sched: cpu=` again, though each last printed one at 2.17-2.22 s and prints
+again on its first idle trip 10 s on (`scheduler::log_health`): no CPU went
+idle, or 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 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
+also carries `debug-regs.patch`, the capture of a stalled one) caught one (span
+3.68 s, `virt_el1_smp`, load 38) in 174 guests. Every CPU was at EL1 with
+DAIF masked; four (cpu0, 3, 5, 7) were in `Lock::lock`'s ticket spin on
+`counters::ANSWERED`'s waiter list (x19 its address in the shipping kernel's
+symbols), two at the kick handler's `ICC_EOIR1_EL1` write, one inside the
+post. 500 ms later all were back in `driver::pass`, and the read finished.
+Earlier slow reads without registers spanned 7, 15 and 26 s.
+
+Waking a round's readers once, from the answer that completes it, instead of
+once per answering CPU (`762a524f0`, reverted in the next commit) changed
+neither the kicks taken during the read (median 116/122/118, fix/base/fix)
+nor its span, so the waiter-list contention is not shown to be the cause.
+
+Exit: the cause of the silence is named from a capture of a silent guest
+(registers over QMP before anything else touches it), and fixed with the
+evidence, or shown to be the host stopping the guest.

tests/toyos.rs

@@ -1505,7 +1505,8 @@ fn virt_job(profile: qemu::Profile, job: &str, said: &str) -> Result<(), String>
             ..Default::default()
         },
     );
-    judge_virt_job(&mut qemu, job, said).map(drop)
+    let mut serial = virt_console(&qemu);
+    judge_virt_job(&mut qemu, &mut serial, job, said)
 }
 
 /// A `mask-windows` boot's windows: `common::irqcensus::windows`'s verdict,
@@ -1524,14 +1525,19 @@ fn mask_windows(capture: &str, cpus: u32) -> Result<(), String> {
     Ok(())
 }
 
+/// Everything the PL011 has carried on `qemu`'s boot: the capture each
+/// [`judge_virt_job`] after the first goes on from, since a drain reads past
+/// the marker it waited for.
+fn virt_console(qemu: &QemuInstance) -> String {
+    format!("{}\n", qemu.boot_log())
+}
+
 /// Wait for `job`'s end on a guest booted with it, and judge it: it ends with
-/// exit 0, having said `said`. Answers everything the PL011 carried.
-fn judge_virt_job(qemu: &mut QemuInstance, job: &str, said: &str) -> Result<String, String> {
+/// exit 0, having said `said`. `serial` is everything the PL011 has carried,
+/// and takes what this drains.
+fn judge_virt_job(qemu: &mut QemuInstance, serial: &mut String, job: &str, said: &str) -> Result<(), String> {
     let end = format!("===TEST_END {job} ");
-    let mut rest = String::new();
-    let waited = await_marker(qemu, &mut rest, &end, &format!("the job {job} to end"));
-    let serial = format!("{}\n{rest}", qemu.boot_log());
-    if let Err(why) = waited {
+    if let Err(why) = await_marker(qemu, serial, &end, &format!("the job {job} to end")) {
         return Err(format!("{why}\nserial:\n{serial}"));
     }
     let ended = serial
@@ -1545,7 +1551,7 @@ fn judge_virt_job(qemu: &mut QemuInstance, job: &str, said: &str) -> Result<Stri
     if !ended.contains(&format!("===TEST_END {job} exit=0===")) {
         return Err(format!("{ended}\nserial:\n{serial}"));
     }
-    Ok(serial)
+    Ok(())
 }
 
 /// What `unmap_touch` says once every read of a page just unmapped,
@@ -1567,7 +1573,8 @@ fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> {
         kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL,
         ..Default::default()
     });
-    let mut serial = judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?;
+    let mut serial = virt_console(&qemu);
+    judge_virt_job(&mut qemu, &mut serial, "unmap_touch", UNMAP_TOUCH_SAID)?;
     // To the boot's last word, said after every census and its windows: the drain that took the job's end can stop between the two.
     await_marker(&mut qemu, &mut serial, power::SHUTTING_DOWN, "the boot's last word")?;
     mask_windows(&serial, VIRT_CPUS)
@@ -1610,7 +1617,8 @@ fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String
     // Before the job list can reach its `shutdown`: QMP delivers no event
     // emitted before its client connected.
     let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET));
-    let serial = judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?;
+    let mut serial = virt_console(&qemu);
+    judge_virt_job(&mut qemu, &mut serial, "unmap_touch", UNMAP_TOUCH_SAID)?;
     let psci = serial.lines().find(|l| l.contains("PSCI: ")).unwrap_or_default();
     if !psci.contains(&format!(" through {conduit}")) {
         return Err(format!("PSCI is not said to be reached through {conduit}: {psci:?}\nserial:\n{serial}"));
@@ -1632,9 +1640,9 @@ fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String
         }
     }
     eprintln!("  [virt] {VIRT_CPUS} CPUs entered at EL{el}, started through {conduit}, and scheduling");
-    let counted = judge_virt_job(&mut qemu, "test_rs_counters_read", COUNTERS_READ_SAID)?;
+    judge_virt_job(&mut qemu, &mut serial, "test_rs_counters_read", COUNTERS_READ_SAID)?;
     let (console, calls) =
-        ended_through_psci(&mut qemu, &mut stop, counted, power::SHUTTING_DOWN, "guest-shutdown", &trace, |_| Vec::new())?;
+        ended_through_psci(&mut qemu, &mut stop, serial, power::SHUTTING_DOWN, "guest-shutdown", &trace, |_| Vec::new())?;
     let record = console
         .lines()
         .find_map(toyos_quiesce::Record::parse)
@@ -1733,7 +1741,8 @@ fn virt_failed_ap_leaves_no_hole(profile: qemu::Profile) -> Result<(), String> {
     const CPUS: u32 = 4;
     let mut qemu =
         boot_virt_smp(BootOptions { profile, smp: CPUS, kernel_params: &["smp-skip-ap"], ..Default::default() });
-    let serial = judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?;
+    let mut serial = virt_console(&qemu);
+    judge_virt_job(&mut qemu, &mut serial, "unmap_touch", UNMAP_TOUCH_SAID)?;
     // The premise, not just a small machine: cpu1 came up and cpu2 did not.
     for premise in ["SMP: cpu1 mpidr=0x1 online", "SMP: cpu2 mpidr=0x2 did not echo within"] {
         if !serial.contains(premise) {
@@ -1810,7 +1819,8 @@ fn virt_off_names_the_cpus_left_on(profile: qemu::Profile) -> Result<(), String>
         ..Default::default()
     });
     let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET));
-    let serial = judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?;
+    let mut serial = virt_console(&qemu);
+    judge_virt_job(&mut qemu, &mut serial, "unmap_touch", UNMAP_TOUCH_SAID)?;
     let spared = |calls: &[(u64, u64)]| -> Vec<u64> {
         let last = calls.iter().find(|&&(function, _)| function == PSCI_SYSTEM_OFF).map(|&(_, cpu)| cpu);
         (u64::from(VIRT_CPUS) - 2..u64::from(VIRT_CPUS)).filter(|&cpu| Some(cpu) != last).collect()