From df33b21b4b2e13fc4a32ad8d40e35a2b887543e5 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 17:06:34 +0200 Subject: [PATCH 1/2] virt_mask_windows judges the whole console, to QEMU's exit The red `issues/kernel/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md` recorded was the capture, not the kernel. `judge_virt_job` answers what `await_marker` drained, and `await_guest` drains in 200 ms slices: the capture runs past `===TEST_END unmap_touch` to the end of the slice that carried it, which can land inside the `SYS_SHUTDOWN` report the job list's `shutdown` prints next, between a CPU's `irq:` line and its `windows:` line. Captured at origin/main 2f6c8a4ba with the judged capture printed on a red: `cargo test --test toyos-build -- --nocapture virt_mask_windows`, six at once, red on the 12th run (load averages 42 to 59 on the 14-core host): census lines per cpu {0: 10, ..., 6: 10, 7: 9} and windows lines per cpu {0: 10, ..., 5: 10, 6: 9, 7: 9} The capture ended on `irq: cpu6` of the shutdown report. The same boot's whole console, echoed line by line, holds 10 census and 10 windows lines for every CPU, cpu6's windows line straight after its census, and ends on `Shutting down.`: the kernel paired every line. The next 60 runs at load 36 to 53 were green, so the slice's end landing inside a report is rare (1 in 72 here). A marker is no report boundary either: `klogd` alternates 8 records and 8 queued lines per hold of the wire, so a program's line can go out between two records of a report committed before it. So the capture is the console to its close: after the job's end the test waits for the boot's last word, then for QEMU to exit, and judges everything said. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...ses-and-eight-windows-lines-for-one-cpu.md | 41 ------------------- tests/common/qemu.rs | 4 ++ tests/toyos.rs | 9 +++- 3 files changed, 11 insertions(+), 43 deletions(-) delete mode 100644 issues/kernel/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md diff --git a/issues/kernel/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md b/issues/kernel/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md deleted file mode 100644 index db4911a6be6..00000000000 --- a/issues/kernel/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md +++ /dev/null @@ -1,41 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-03 ---- - -# `virt_mask_windows` read nine census lines and eight windows lines for one CPU - -`virt_mask_windows` (`tests/toyos.rs`) judges the capture `judge_virt_job` -answers, which ends where `===TEST_END unmap_touch` arrived, with -`irqcensus::windows`: every `irq: cpu` census line has its CPU's windows line -beside it. - -## Measured - -A whole guest suite at `bf28c1e38`, whose `virt_mask_windows`, kernel and -`tests/common/irqcensus.rs` are `origin/main`'s at `c59e09ed6`: -`cargo test --test toyos-build`, 12 wide on the 14-core dev host at load -average 43 to 59, exited 1 with this one red in 66.8 s: - -``` -FAIL virt_mask_windows: census lines per cpu {0: 9, 1: 9, 2: 9, 3: 9, 4: 9, 5: 9, 6: 9, 7: 9} and windows lines per cpu {0: 9, 1: 9, 2: 9, 3: 9, 4: 9, 5: 9, 6: 9, 7: 8}: a census went out without its windows, or windows without their census - FAIL virt_mask_windows (10s) -``` - -The whole run before it and the one after it, same tree and same command, -passed it in 8 s and 7 s. The PL011 capture of the red was not kept: the run's -`target/red-run-serial` holds the x86-64 guests' 16550 logs only. - -Two candidates, neither measured: the capture ends at the marker with cpu7's -last windows line still behind it, or the kernel printed a census without its -windows. - -## Owner - -The windows instrument's author (`issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md`). - -## What would close it - -The cause, from a capture of a red: either the judge reads a capture that ends -on a whole report, or the kernel's report is shown to pair its two lines. diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 0b7917e87d4..d8e54a911cd 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -538,6 +538,10 @@ pub fn ceiling_verdict( /// Collect console output until `done` reads true of the whole capture, or the /// guest stops making progress. /// +/// The capture runs past the line that made `done` true to the end of that +/// line's drain, which can fall inside anything the guest says in more than +/// one line. +/// /// The shape [`QemuInstance::drain_serial`] cannot have: its caller passes a /// number of seconds, and a number of seconds is a claim about the host. Here /// the wait ends when the guest goes quiet or wedges, so a guest with a twelfth diff --git a/tests/toyos.rs b/tests/toyos.rs index 7ccdc6930f9..9bcfe9453d4 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1426,7 +1426,8 @@ const VIRT_CPUS: u32 = 8; /// The windows on AArch64: `tests/virtsmpcase` on [`VIRT_CPUS`] CPUs of a /// `mask-windows` kernel, whose every hook checks the state it finds, judged -/// once the case's job `unmap_touch` has ended. +/// on the whole console once the case's job `unmap_touch` has ended and its +/// job list has powered the machine off. fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { let mut qemu = boot_virt_smp(BootOptions { profile, @@ -1434,7 +1435,11 @@ fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL, ..Default::default() }); - mask_windows(&judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?, VIRT_CPUS) + let mut serial = judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?; + // To QEMU's exit, because the drain that took the job's end can stop between a census and its windows. + await_marker(&mut qemu, &mut serial, power::SHUTTING_DOWN, "the boot's last word")?; + serial.push_str(&qemu.await_exit(qemu.budget(qemu::GUEST_QUIET))?); + mask_windows(&serial, VIRT_CPUS) } /// Boot `tests/virtsmpcase` as `options` say. From 56b21d59afc17acf648ed1c6a90802ff7ee91c30 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 17:27:25 +0200 Subject: [PATCH 2/2] virt_mask_windows judges the console to the boot's last word The kernel's quiesce stops userland, then logs every CPU's census and windows, then the boot's last word, all from one CPU and in one record order. So once await_marker has seen `Shutting down.`, the capture already holds the whole shutdown report, and waiting on to QEMU's exit added nothing the judge reads. The await_exit is gone. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- tests/toyos.rs | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/tests/toyos.rs b/tests/toyos.rs index 9bcfe9453d4..35e8f50a82f 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1426,8 +1426,8 @@ const VIRT_CPUS: u32 = 8; /// The windows on AArch64: `tests/virtsmpcase` on [`VIRT_CPUS`] CPUs of a /// `mask-windows` kernel, whose every hook checks the state it finds, judged -/// on the whole console once the case's job `unmap_touch` has ended and its -/// job list has powered the machine off. +/// on the whole console once the case's job `unmap_touch` has ended and the +/// boot has said its last word. fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { let mut qemu = boot_virt_smp(BootOptions { profile, @@ -1436,9 +1436,8 @@ fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { ..Default::default() }); let mut serial = judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?; - // To QEMU's exit, because the drain that took the job's end can stop between a census and its windows. + // 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")?; - serial.push_str(&qemu.await_exit(qemu.budget(qemu::GUEST_QUIET))?); mask_windows(&serial, VIRT_CPUS) }