diff --git a/issues/kernel/a-counters-read-under-host-load-can-go-silent-for-15-s.md b/issues/kernel/a-counters-read-under-host-load-can-go-silent-for-15-s.md new file mode 100644 index 00000000000..9fe7bf58773 --- /dev/null +++ b/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. diff --git a/tests/toyos.rs b/tests/toyos.rs index 7fac3b67117..e2a82598dae 100644 --- a/tests/toyos.rs +++ b/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 { +/// 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 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 { 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()