From 0e148b1b8f0038deb457681782e8bb4eb318cc3e Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 23:42:27 +0200 Subject: [PATCH 01/13] Stage 6 step 2: the longest interrupts-off and preemption-off windows, per CPU, beside the census MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `mask-windows` is a kernel build that reads the counter at every masking transition and every preempt-count crossing of zero, and prints, beside each CPU's IRQ census line, the longest interrupts-off and preemption-off window that CPU closed since the report before (`windows: cpuN irqs_off_ns=… preempt_off_ns=…`). Fed by each architecture's masking primitives and entries: `IrqGuard`, `enable_interrupts`/`disable_interrupts` and the halt on both; on x86-64 the syscall entry, every gate stub (device, TLB, timer in both rings, spurious, unclaimed) and the exception dispatch; on AArch64 the vector dispatch. A return to user mode opens interrupts at `exit_to_user`'s end, which every such return runs last. The preempt count's accessors feed its crossings on both arches, and the x86-64 stubs that raise it inline feed theirs from their Rust halves. A context switch runs inside an `IrqGuard` in this build, so no saved context carries interrupts open through `context_switch`'s flags restore, the one transition no hook can follow. A scheduler pass ends a preemption-off window and starts the next, and the idle halt inside a pass is no window: without both the number is the time since the CPU last returned to user mode, idle time included. Every hook checks the state it finds: a transition no hook saw panics at the next hook on that CPU, and every entry is held to what the hardware says it interrupted (a maskable interrupt only with interrupts open; an exception's frame carries the flag). The load `issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md` names is `test_rs_ring_park_herd`: 256 threads parked in `submit` on one ring, and the main thread completing into it 64 times, each once the roster shows all 256 parked again. `mask_windows` (x86-64, four CPUs) and `virt_mask_windows` (AArch64) boot `boot-actuators,mask-windows,test-actuators` with `windows-staged`, which spins 1 ms inside the first process exit, where both windows are open; a later report of that CPU must carry both at least that long. The `mask_windows` metal row boots the shipping kernel plus `mask-windows` on the T14 and records the boot's longest windows and the herd's. The harness lets a named build that carries the actuators arm one. roster.rs holds 1024 entries and refuses a machine with more, since the herd's 257 threads would not fit its 256. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- kernel/Cargo.toml | 6 + kernel/src/actuator.rs | 5 + kernel/src/arch/aarch64/cpu.rs | 10 + kernel/src/arch/aarch64/hw.rs | 10 + kernel/src/arch/aarch64/mod.rs | 9 + kernel/src/arch/aarch64/percpu.rs | 8 + kernel/src/arch/aarch64/trap.rs | 15 +- kernel/src/arch/x86_64/cpu.rs | 12 +- kernel/src/arch/x86_64/hw.rs | 8 + kernel/src/arch/x86_64/idt/device_irq.rs | 28 ++ kernel/src/arch/x86_64/idt/mod.rs | 33 ++- kernel/src/arch/x86_64/idt/spurious.rs | 5 + kernel/src/arch/x86_64/idt/timer.rs | 15 ++ kernel/src/arch/x86_64/idt/tlb.rs | 14 + kernel/src/arch/x86_64/idt/unclaimed.rs | 5 + kernel/src/arch/x86_64/mod.rs | 9 + kernel/src/arch/x86_64/percpu.rs | 8 + kernel/src/arch/x86_64/syscall.rs | 9 + kernel/src/hw.rs | 4 + kernel/src/irq_census.rs | 3 + kernel/src/main.rs | 2 + kernel/src/process.rs | 7 + kernel/src/sched/driver.rs | 6 + kernel/src/scheduler.rs | 4 + kernel/src/windows.rs | 249 ++++++++++++++++++ src/build.rs | 18 +- src/clippy.rs | 18 +- tests/common/irqcensus.rs | 110 +++++++- tests/common/qemu.rs | 24 +- .../src/bin/ring_park_herd.rs | 114 ++++++++ tests/toyos-rust-tests/src/roster.rs | 6 +- tests/toyos.rs | 135 ++++++++++ 32 files changed, 891 insertions(+), 18 deletions(-) create mode 100644 kernel/src/windows.rs create mode 100644 tests/toyos-rust-tests/src/bin/ring_park_herd.rs diff --git a/kernel/Cargo.toml b/kernel/Cargo.toml index 5beca3f086b..d1abb016585 100644 --- a/kernel/Cargo.toml +++ b/kernel/Cargo.toml @@ -129,6 +129,12 @@ debug-wait = [] # Not a boot parameter, and the one that could not be: it forwards to a # dependency's cargo feature, which no runtime value can reach. sched-check = ["toyos-sched/check"] +# The longest interrupts-off and preemption-off window each CPU closed since the +# last report, printed beside the IRQ census (`src/windows.rs`). Its own build +# because it reads the counter at every masking transition and every preempt +# count crossing zero, on every entry and exit: a kernel being measured for +# anything else must not carry it. +mask-windows = [] # The stray-write tripwire on the per-CPU `CpuSched` record: a shadow copy of its # bytes, taken when the driver's exclusive region is left and compared when it is # next entered, so a word that changed while nothing was allowed to change it is diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 89cc9f2dc42..42fee8cee73 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -260,6 +260,11 @@ actuators! { /// handler posted it there. handler_post = "handler-post"; + /// Spin a known span inside the first process exit, where both of + /// `mask-windows`' windows are open, and say how long; judged by + /// `mask_windows`. + windows_staged = "windows-staged"; + /// Starve the four xHCI bring-up register waits in `init_one`. xhci_deaf_controller = "xhci-deaf-controller"; diff --git a/kernel/src/arch/aarch64/cpu.rs b/kernel/src/arch/aarch64/cpu.rs index 31e5fceb94a..b87c5044638 100644 --- a/kernel/src/arch/aarch64/cpu.rs +++ b/kernel/src/arch/aarch64/cpu.rs @@ -67,14 +67,24 @@ pub unsafe fn write_thread_pointer(tp: u64) { /// Unmask interrupts on this CPU: `DAIF.I` and `DAIF.F`. pub fn enable_interrupts() { + #[cfg(feature = "mask-windows")] + if !interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: writes two `DAIF` bits; a compiler barrier, so no access moves across it. unsafe { asm!("msr daifclr, #3", options(nostack)) }; } /// Mask interrupts on this CPU. pub fn disable_interrupts() { + #[cfg(feature = "mask-windows")] + let were_open = interrupts_enabled(); // SAFETY: writes two `DAIF` bits; a compiler barrier, so no access moves across it. unsafe { asm!("msr daifset, #3", options(nostack)) }; + #[cfg(feature = "mask-windows")] + if were_open { + crate::windows::irqs_masked(); + } } /// Whether this CPU takes interrupts: `DAIF.I` clear. diff --git a/kernel/src/arch/aarch64/hw.rs b/kernel/src/arch/aarch64/hw.rs index cb74189d885..fc3fd38c0ec 100644 --- a/kernel/src/arch/aarch64/hw.rs +++ b/kernel/src/arch/aarch64/hw.rs @@ -13,6 +13,12 @@ use crate::sched::payload::{KernelCtx, KernelPayload}; /// `WFI` whatever `DAIF` says (Arm ARM K.a, D1.6.2), so a wake that lands /// between the decision and the wait is taken right after it, not slept through. pub fn halt() { + // Before the `WFI`: what it waits for is taken the moment it unmasks, so + // the wait is no window. + #[cfg(feature = "mask-windows")] + if !cpu::interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: waits for an interrupt and unmasks `I` and `F`; touches no memory. unsafe { core::arch::asm!("wfi", "msr daifclr, #3", "isb", options(nomem, nostack)) }; } @@ -64,6 +70,10 @@ impl Hw for KernelHw { unsafe fn switch(&self, token: RunToken) { let save = token.save_ptr(); let restore = token.restore_ptr(); + // Every context is saved masked, so `context_switch`'s `msr daif` + // never unmasks; the resumed context's own guard puts back what it had. + #[cfg(feature = "mask-windows")] + let _masked = crate::arch::IrqGuard::close(); // SAFETY: `save`/`restore` are live Box-backed contexts from // `SchedPass::finish`, freed only by a later pass. unsafe { diff --git a/kernel/src/arch/aarch64/mod.rs b/kernel/src/arch/aarch64/mod.rs index 8df6a4c33f2..95cf894027f 100644 --- a/kernel/src/arch/aarch64/mod.rs +++ b/kernel/src/arch/aarch64/mod.rs @@ -71,6 +71,10 @@ impl IrqGuard { unsafe { core::arch::asm!("mrs {saved}, daif", "msr daifset, #3", saved = out(reg) daif); } + #[cfg(feature = "mask-windows")] + if trap::frame_interrupts_enabled(daif) { + crate::windows::irqs_masked(); + } Self { daif, _not_send_sync: core::marker::PhantomData } } @@ -89,6 +93,11 @@ impl IrqGuard { impl Drop for IrqGuard { fn drop(&mut self) { + // Only where the restore opens them: an `unclosed` guard never masked. + #[cfg(feature = "mask-windows")] + if trap::frame_interrupts_enabled(self.daif) && !cpu::interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: the word `close` read out of `DAIF` on this CPU (the guard is // `!Send`), restored whole. unsafe { diff --git a/kernel/src/arch/aarch64/percpu.rs b/kernel/src/arch/aarch64/percpu.rs index 3963d2a9564..69e18eb7506 100644 --- a/kernel/src/arch/aarch64/percpu.rs +++ b/kernel/src/arch/aarch64/percpu.rs @@ -279,17 +279,25 @@ pub fn preempt_count() -> u32 { #[inline] pub fn set_preempt_count(value: u32) { + #[cfg(feature = "mask-windows")] + let old = preempt_count(); this().preempt_count.store(value, Relaxed); + #[cfg(feature = "mask-windows")] + crate::windows::preempt_set(old, value); } /// One increment, atomic against an interrupt on this CPU. #[inline] pub fn preempt_count_up() { this().preempt_count.fetch_add(1, Relaxed); + #[cfg(feature = "mask-windows")] + crate::windows::preempt_raised(); } #[inline] pub fn preempt_count_down() { + #[cfg(feature = "mask-windows")] + crate::windows::preempt_lowering(); this().preempt_count.fetch_sub(1, Relaxed); } diff --git a/kernel/src/arch/aarch64/trap.rs b/kernel/src/arch/aarch64/trap.rs index d85e2ca15a8..fe849db4e57 100644 --- a/kernel/src/arch/aarch64/trap.rs +++ b/kernel/src/arch/aarch64/trap.rs @@ -91,13 +91,26 @@ fn class_name(esr: u64) -> &'static str { /// The Rust half of every vector entry. Returns to the entry, which restores /// the frame and returns from the exception; everything fatal diverges. extern "C" fn dispatch(frame: &mut Frame, entry: u64) { + // Each returning entry found interrupts open, an IRQ because only then is + // one taken and EL0 because it never masks them, and taking it masked + // them; `exit_to_user` opens them for EL0, and the `ERET` for EL1. match entry { - EL1_IRQ => irq(false), + EL1_IRQ => { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); + irq(false); + #[cfg(feature = "mask-windows")] + crate::windows::irqs_unmasking(); + } EL0_SYNC => { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); el0_sync(frame); crate::scheduler::exit_to_user(); } EL0_IRQ => { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); irq(true); crate::scheduler::exit_to_user(); } diff --git a/kernel/src/arch/x86_64/cpu.rs b/kernel/src/arch/x86_64/cpu.rs index 2353b0f5868..b40333f3bc3 100644 --- a/kernel/src/arch/x86_64/cpu.rs +++ b/kernel/src/arch/x86_64/cpu.rs @@ -259,6 +259,10 @@ pub unsafe fn ltr(selector: u16) { /// `sti`; not a drop-in for a caller whose `cli`/`sti` also needs the compiler barrier a bare `asm!` carries. #[inline] pub fn enable_interrupts() { + #[cfg(feature = "mask-windows")] + if !interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: one RFLAGS bit, no memory, matching the options declared above. unsafe { asm!("sti", options(nomem, nostack)); @@ -271,7 +275,7 @@ pub fn enable_interrupts() { /// or `cli` runs, so nothing may branch on it to decide whether to mask; what it /// is for is a site that has to *say* which state it inherited, which is a fact /// about its caller rather than about the instruction after it. -#[cfg(feature = "boot-actuators")] +#[cfg(any(feature = "boot-actuators", feature = "mask-windows"))] pub fn interrupts_enabled() -> bool { let rflags: u64; // SAFETY: balanced push/pop leaves rsp unchanged; the pair uses the stack, so no nomem. @@ -284,10 +288,16 @@ pub fn interrupts_enabled() -> bool { /// `cli`, with [`enable_interrupts`]'s caveat about the missing barrier. #[inline] pub fn disable_interrupts() { + #[cfg(feature = "mask-windows")] + let were_open = interrupts_enabled(); // SAFETY: enable_interrupts's argument; masking interrupts is a latency bug, not a soundness one. unsafe { asm!("cli", options(nomem, nostack)); } + #[cfg(feature = "mask-windows")] + if were_open { + crate::windows::irqs_masked(); + } } /// The kernel's own FS base, not `rd/wrfsbase` (`control_regs::CR4_FORBIDDEN`). diff --git a/kernel/src/arch/x86_64/hw.rs b/kernel/src/arch/x86_64/hw.rs index 7f224e72f18..a296670b313 100644 --- a/kernel/src/arch/x86_64/hw.rs +++ b/kernel/src/arch/x86_64/hw.rs @@ -13,6 +13,10 @@ use crate::sched::payload::{KernelCtx, KernelPayload}; /// `sti; hlt`, the atomic enable-and-wait pair: a wake landing between the two is not lost. pub fn halt() { + #[cfg(feature = "mask-windows")] + if !cpu::interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: enables interrupts and waits for one; touches no memory. unsafe { asm!("sti; hlt", options(nomem, nostack)); } } @@ -280,6 +284,10 @@ impl Hw for KernelHw { unsafe fn switch(&self, token: RunToken) { let save = token.save_ptr(); let restore = token.restore_ptr(); + // Every context is saved masked, so `context_switch`'s `popfq` never + // moves `IF`; the resumed context's own guard puts back what it had. + #[cfg(feature = "mask-windows")] + let _masked = crate::arch::IrqGuard::close(); // SAFETY: `save`/`restore` are live Box-backed contexts from `SchedPass::finish`, freed only by a later pass; `incoming.thread_pointer` is this kernel's own canonical value for the thread being installed. unsafe { (*save).thread_pointer = cpu::read_fs_base(); diff --git a/kernel/src/arch/x86_64/idt/device_irq.rs b/kernel/src/arch/x86_64/idt/device_irq.rs index b3b1fa07742..d3b355e102c 100644 --- a/kernel/src/arch/x86_64/idt/device_irq.rs +++ b/kernel/src/arch/x86_64/idt/device_irq.rs @@ -28,8 +28,14 @@ macro_rules! device_irq_entry { // Ring 0 entry has unknown rsp alignment; align via the rbp save. "mov rbp, rsp", "and rsp, -16", + #[cfg(feature = "mask-windows")] + "call {windows_entered}", // No user-state save around this call: kernel code is soft-float and never touches it. "call {handler}", + #[cfg(feature = "mask-windows")] + "mov rdi, [rbp + 88]", + #[cfg(feature = "mask-windows")] + "call {windows_leaving}", "mov rsp, rbp", "lock sub dword ptr gs:[{preempt_count}], 1", "test dword ptr [rsp + 88], 3", // CS = 10 GPRs + RIP above @@ -53,9 +59,31 @@ macro_rules! device_irq_entry { handler = sym $handler, exit_to_user = sym crate::arch::idt::kernel_exit_to_user_check, preempt_count = const $crate::arch::percpu::OFF_PREEMPT_COUNT, + #[cfg(feature = "mask-windows")] + windows_entered = sym super::device_irq::windows_entered, + #[cfg(feature = "mask-windows")] + windows_leaving = sym super::device_irq::windows_leaving, ); } }; } pub(crate) use device_irq_entry; + +/// The gate masked interrupts, which a maskable vector finds open (SDM Vol. 3A +/// §6.8.1), and the stub raised the preempt count by one. +#[cfg(feature = "mask-windows")] +pub(super) extern "sysv64" fn windows_entered() { + crate::windows::irqs_masked(); + crate::windows::preempt_raised(); +} + +/// The stub lowers the count next, with the frame's `cs`; its `iretq` opens +/// interrupts on a return to Ring 0, and `exit_to_user` on one to Ring 3. +#[cfg(feature = "mask-windows")] +pub(super) extern "sysv64" fn windows_leaving(cs: u64) { + crate::windows::preempt_lowering(); + if cs & 3 == 0 { + crate::windows::irqs_unmasking(); + } +} diff --git a/kernel/src/arch/x86_64/idt/mod.rs b/kernel/src/arch/x86_64/idt/mod.rs index be72d3d92c9..e6016116e79 100644 --- a/kernel/src/arch/x86_64/idt/mod.rs +++ b/kernel/src/arch/x86_64/idt/mod.rs @@ -369,11 +369,42 @@ extern "sysv64" fn trap_dispatch(frame: *mut TrapFrame) { Vector::DoubleFault => exceptions::double_fault_handler(frame), Vector::MachineCheck => exceptions::machine_check_handler(frame), Vector::PageFault => { + #[cfg(feature = "mask-windows")] + windows_entered(frame); cpu::enable_interrupts(); exceptions::page_fault_handler(frame); cpu::disable_interrupts(); + #[cfg(feature = "mask-windows")] + windows_leaving(frame); } - _ => exceptions::exception_handler(frame), + _ => { + #[cfg(feature = "mask-windows")] + windows_entered(frame); + exceptions::exception_handler(frame) + } + } +} + +/// The gate masked interrupts if the frame says they were open, and a window +/// is already open if it says they were not; `common_entry` raised the preempt +/// count by one. +#[cfg(feature = "mask-windows")] +fn windows_entered(frame: &TrapFrame) { + if frame_interrupts_enabled(frame.rflags) { + crate::windows::irqs_masked(); + } else { + crate::windows::irqs_found_masked(); + } + crate::windows::preempt_raised(); +} + +/// `common_entry` lowers the count next; its `iretq` opens interrupts on a +/// return to Ring 0 that had them, and `exit_to_user` on one to Ring 3. +#[cfg(feature = "mask-windows")] +fn windows_leaving(frame: &TrapFrame) { + crate::windows::preempt_lowering(); + if frame.cs & 3 == 0 && frame_interrupts_enabled(frame.rflags) { + crate::windows::irqs_unmasking(); } } diff --git a/kernel/src/arch/x86_64/idt/spurious.rs b/kernel/src/arch/x86_64/idt/spurious.rs index 06fdd73d23a..7c066325620 100644 --- a/kernel/src/arch/x86_64/idt/spurious.rs +++ b/kernel/src/arch/x86_64/idt/spurious.rs @@ -51,11 +51,16 @@ pub(super) extern "sysv64" fn spurious_entry() { } /// Counts one delivery and acknowledges it if the ISR bit shows it needed one. +/// Its `iretq` returns to either ring with interrupts open, as the vector found them. extern "sysv64" fn took() { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); crate::arch::percpu::irq_took!(Spurious); if apic::in_service(SPURIOUS_VECTOR) { apic::eoi(); } + #[cfg(feature = "mask-windows")] + crate::windows::irqs_unmasking(); } /// Raises the spurious vector on this CPU and verifies the handler ran and diff --git a/kernel/src/arch/x86_64/idt/timer.rs b/kernel/src/arch/x86_64/idt/timer.rs index 574e4a68713..1ce8cb24fba 100644 --- a/kernel/src/arch/x86_64/idt/timer.rs +++ b/kernel/src/arch/x86_64/idt/timer.rs @@ -76,7 +76,10 @@ pub(super) extern "sysv64" fn timer_entry() { "pop rcx", "pop rax", "iretq", + #[cfg(not(feature = "mask-windows"))] deadline = sym crate::deadline::poll, + #[cfg(feature = "mask-windows")] + deadline = sym ring0_tick, handler = sym timer_handler, exit_to_user = sym crate::arch::idt::kernel_exit_to_user_check, armed_ticks = const crate::arch::percpu::OFF_LAST_ARMED_TICKS, @@ -89,7 +92,19 @@ pub(super) extern "sysv64" fn timer_entry() { ); } +/// The Ring 0 branch's Rust half under `mask-windows`: it interrupted a CPU +/// with interrupts open, and its `iretq` opens them again. +#[cfg(feature = "mask-windows")] +extern "sysv64" fn ring0_tick() { + crate::windows::irqs_masked(); + crate::deadline::poll(); + crate::windows::irqs_unmasking(); +} + extern "sysv64" fn timer_handler() { + // From Ring 3, so interrupts were open; `exit_to_user` opens them again. + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); crate::arch::percpu::irq_took!(Timer); // Before anything that can take a lock: a CPU running userland is the other // half of the coverage the Ring 0 branch above gives a CPU holding one. diff --git a/kernel/src/arch/x86_64/idt/tlb.rs b/kernel/src/arch/x86_64/idt/tlb.rs index fa5a147aa24..17551416d73 100644 --- a/kernel/src/arch/x86_64/idt/tlb.rs +++ b/kernel/src/arch/x86_64/idt/tlb.rs @@ -18,12 +18,22 @@ pub(super) extern "sysv64" fn tlb_flush_entry() { "lock add dword ptr gs:[{preempt_count}], 1", "mov rbp, rsp", "and rsp, -16", + #[cfg(feature = "mask-windows")] + "call {windows_entered}", "call {flush}", "mov rsp, rbp", "mov ecx, 0x80B", "xor eax, eax", "xor edx, edx", "wrmsr", + #[cfg(feature = "mask-windows")] + "mov rdi, [rsp + 88]", + #[cfg(feature = "mask-windows")] + "and rsp, -16", + #[cfg(feature = "mask-windows")] + "call {windows_leaving}", + #[cfg(feature = "mask-windows")] + "mov rsp, rbp", "lock sub dword ptr gs:[{preempt_count}], 1", // Only this branch can context-switch; user state is saved and restored around it alone. "test dword ptr [rsp + 88], 3", @@ -47,6 +57,10 @@ pub(super) extern "sysv64" fn tlb_flush_entry() { flush = sym flush, exit_to_user = sym crate::arch::idt::kernel_exit_to_user_check, preempt_count = const crate::arch::percpu::OFF_PREEMPT_COUNT, + #[cfg(feature = "mask-windows")] + windows_entered = sym super::device_irq::windows_entered, + #[cfg(feature = "mask-windows")] + windows_leaving = sym super::device_irq::windows_leaving, ); } diff --git a/kernel/src/arch/x86_64/idt/unclaimed.rs b/kernel/src/arch/x86_64/idt/unclaimed.rs index 9ca9f4b6dcf..49c47f60ebb 100644 --- a/kernel/src/arch/x86_64/idt/unclaimed.rs +++ b/kernel/src/arch/x86_64/idt/unclaimed.rs @@ -56,7 +56,10 @@ pub(super) extern "sysv64" fn unclaimed_entry() { } /// Counts the delivery, remembers the vector, and EOIs only if the ISR needs one. +/// Its `iretq` returns to either ring with interrupts open, as the vector found them. extern "sysv64" fn took() { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); crate::arch::percpu::irq_took!(Unclaimed); match apic::in_service_highest() { Some(vector) => { @@ -67,6 +70,8 @@ extern "sysv64" fn took() { NO_ISR.fetch_add(1, Ordering::Relaxed); } } + #[cfg(feature = "mask-windows")] + crate::windows::irqs_unmasking(); } /// Whether `vector` has been taken through this gate. diff --git a/kernel/src/arch/x86_64/mod.rs b/kernel/src/arch/x86_64/mod.rs index 1e565f53f79..f5368770a36 100644 --- a/kernel/src/arch/x86_64/mod.rs +++ b/kernel/src/arch/x86_64/mod.rs @@ -72,6 +72,10 @@ impl IrqGuard { unsafe { core::arch::asm!("pushfq", "pop {saved}", "cli", saved = out(reg) rflags); } + #[cfg(feature = "mask-windows")] + if idt::frame_interrupts_enabled(rflags) { + crate::windows::irqs_masked(); + } Self { rflags, _not_send_sync: core::marker::PhantomData } } @@ -90,6 +94,11 @@ impl IrqGuard { impl Drop for IrqGuard { fn drop(&mut self) { + // Only where the restore opens them: an `unclosed` guard never masked. + #[cfg(feature = "mask-windows")] + if idt::frame_interrupts_enabled(self.rflags) && !cpu::interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: the word `close` read out of RFLAGS on this CPU (the guard is // `!Send`), restored whole. unsafe { diff --git a/kernel/src/arch/x86_64/percpu.rs b/kernel/src/arch/x86_64/percpu.rs index f4ba2446624..34084fa5846 100644 --- a/kernel/src/arch/x86_64/percpu.rs +++ b/kernel/src/arch/x86_64/percpu.rs @@ -771,18 +771,26 @@ pub fn preempt_count() -> u32 { #[inline] pub fn set_preempt_count(value: u32) { + #[cfg(feature = "mask-windows")] + let old = preempt_count(); gs::write_u32::(value); + #[cfg(feature = "mask-windows")] + crate::windows::preempt_set(old, value); } /// One increment, atomic against an interrupt on this CPU. #[inline] pub fn preempt_count_up() { gs::lock_inc_u32::(); + #[cfg(feature = "mask-windows")] + crate::windows::preempt_raised(); } /// One decrement, atomic against an interrupt on this CPU. #[inline] pub fn preempt_count_down() { + #[cfg(feature = "mask-windows")] + crate::windows::preempt_lowering(); gs::lock_dec_u32::(); } diff --git a/kernel/src/arch/x86_64/syscall.rs b/kernel/src/arch/x86_64/syscall.rs index 46d448f9202..e7be09402f1 100644 --- a/kernel/src/arch/x86_64/syscall.rs +++ b/kernel/src/arch/x86_64/syscall.rs @@ -173,11 +173,20 @@ extern "sysv64" fn syscall_entry() { /// The syscall bracket: the entry's diagnostic stores stay readable only while [`percpu::in_syscall`] is true. extern "sysv64" fn syscall_handler(num: u64, a1: u64, a2: u64, _: u64, a3: u64, a4: u64) -> u64 { + // `IA32_FMASK` masked interrupts, and the entry raised the preempt count by one. + #[cfg(feature = "mask-windows")] + { + crate::windows::irqs_masked(); + crate::windows::preempt_raised(); + } #[cfg(feature = "df-witness")] cpu::df_witness("syscall_handler"); percpu::enter_syscall(); let out = syscall_dispatch(num, a1, a2, a3, a4); percpu::leave_syscall(); + // The entry lowers it by one next; `exit_to_user` opens interrupts. + #[cfg(feature = "mask-windows")] + crate::windows::preempt_lowering(); out } diff --git a/kernel/src/hw.rs b/kernel/src/hw.rs index 041eaeb2fd4..fcf902e10c8 100644 --- a/kernel/src/hw.rs +++ b/kernel/src/hw.rs @@ -78,7 +78,11 @@ impl Machine for KernelHw { if crate::actuator::diag_tick() { irqchip::arm_within(DIAG_TICK_NS); } + #[cfg(feature = "mask-windows")] + crate::windows::halting(); self.halt(); + #[cfg(feature = "mask-windows")] + crate::windows::woken(); // **A CPU that is executing has a one-shot armed, and this is where // that becomes true again.** `TimerPlan::Stop` left this one at zero // before the halt above and only a pass reaching `apply_timer` arms diff --git a/kernel/src/irq_census.rs b/kernel/src/irq_census.rs index 6187df24d8f..be637d91d3b 100644 --- a/kernel/src/irq_census.rs +++ b/kernel/src/irq_census.rs @@ -133,6 +133,7 @@ pub fn taken_here() -> u64 { } /// Logs one `irq: cpuN total=… =…` line per online CPU; counts are cumulative since boot. +/// A `mask-windows` kernel follows each with that CPU's `windows:` line. /// Allocates nothing, takes no lock, touches no device. pub fn log_census() { for cpu in 0..crate::smp::cpu_count() { @@ -142,5 +143,7 @@ pub fn log_census() { counts[TOTAL], Fields(&counts[TOTAL + 1..]) ); + #[cfg(feature = "mask-windows")] + crate::windows::log_cpu(cpu); } } diff --git a/kernel/src/main.rs b/kernel/src/main.rs index e91c58580f8..fecac0d51bb 100644 --- a/kernel/src/main.rs +++ b/kernel/src/main.rs @@ -72,6 +72,8 @@ mod hw; mod iommu; mod preempt; mod irq_census; +#[cfg(feature = "mask-windows")] +mod windows; mod irq_ring; mod trace; mod time; diff --git a/kernel/src/process.rs b/kernel/src/process.rs index c7ebfbdc078..d3527d7cdd2 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -958,6 +958,13 @@ fn teardown_resources( data.peak_memory / (1024 * 1024), data.alloc_count, data.free_count); } + #[cfg(feature = "boot-actuators")] + if crate::actuator::windows_staged() { + #[cfg(feature = "mask-windows")] + crate::windows::stage_once(); + #[cfg(not(feature = "mask-windows"))] + panic!("windows-staged: armed on a kernel without `mask-windows`, which has no window to hold to it"); + } // Machine-wide, cumulative counters, printed here (not at shutdown) because process exit is the one recurring moment every boot reaches. crate::irq_census::log_census(); // After the irq lines: the tlb conservation check reads deliveries first, issues second. diff --git a/kernel/src/sched/driver.rs b/kernel/src/sched/driver.rs index 1c4cdf8f562..d7a3b65edfd 100644 --- a/kernel/src/sched/driver.rs +++ b/kernel/src/sched/driver.rs @@ -529,6 +529,8 @@ pub fn pass(dispose: Dispose) { }; disposed.finish() }); + #[cfg(feature = "mask-windows")] + crate::windows::scheduled(); charge_cpu_time(now); with_cpu(|cpu| { if let Some(current) = cpu.running() { @@ -600,6 +602,8 @@ pub fn pass_block(ticket: Ticket, deadline: Option) { Commit::Killed => (pass.dispose_none().finish(), false), } }); + #[cfg(feature = "mask-windows")] + crate::windows::scheduled(); charge_cpu_time(now); with_cpu(|cpu| { if let Some(current) = cpu.running() { @@ -675,6 +679,8 @@ fn drain_irqs(entered: super::dump::Entered) { /// Leave the current stack for this CPU's idle stack and never come back. pub fn enter_idle_loop() -> ! { + #[cfg(feature = "mask-windows")] + crate::windows::start_here(); percpu::set_current_tid(None); percpu::set_current_pid(None); // SAFETY: `set_kernel_stack` requires the caller be the CPU its GS base belongs to — true here, on that CPU, after its base was set. diff --git a/kernel/src/scheduler.rs b/kernel/src/scheduler.rs index 2dbdcee7230..c33e584a861 100644 --- a/kernel/src/scheduler.rs +++ b/kernel/src/scheduler.rs @@ -414,6 +414,10 @@ pub fn exit_to_user() { if crate::actuator::dump_in_blocking_pass() { crate::sched::dump::staged::note_return_to_user(); } + // Every caller's next unmask is the return to user mode, or a + // kernel thread's first. + #[cfg(feature = "mask-windows")] + crate::windows::irqs_unmasking(); return; } assert!(!in_schedule_self(), "exit-to-user inside a scheduler pass"); diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs new file mode 100644 index 00000000000..e673897e09a --- /dev/null +++ b/kernel/src/windows.rs @@ -0,0 +1,249 @@ +//! The longest interrupts-off and the longest preemption-off window each CPU +//! closed since the last report, printed beside the IRQ census as +//! `windows: cpuN irqs_off_ns=… preempt_off_ns=…` (`mask-windows` builds only). +//! +//! **An interrupts-off window** opens where this CPU stops taking maskable +//! interrupts and closes where it takes them again. Each architecture feeds +//! [`irqs_masked`] and [`irqs_unmasking`] from every instruction that changes +//! that: its masking primitives, the halt, every entry (a gate, `SYSCALL` or an +//! exception masks) and every return (`scheduler::exit_to_user`'s end for a +//! return to user mode, the entry's own hook for a return to the kernel). A +//! context switch changes nothing: this build switches inside an +//! `IrqGuard`, so every saved context holds interrupts masked. An NMI is not +//! a window: nothing masks it, and it runs no hook. +//! +//! **A preemption-off window** opens where this CPU's preempt count leaves +//! zero and closes where it returns there. A scheduler pass ends it and starts +//! the next, because a pass is where a waiting thread gets the CPU, and the +//! idle halt inside a pass is no window, since a wake ends it. +//! [`preempt_raised`] follows every raise by one and [`preempt_lowering`] +//! precedes every lowering by one; each acts only on a crossing of zero. +//! +//! **Every hook checks the state it finds against the transition it +//! reports**, so a transition no hook saw panics at the next hook on that CPU, +//! and every entry is held to what the CPU says it interrupted: a maskable +//! interrupt is delivered only with interrupts open, and an exception's frame +//! carries the flag. The hooks that change `IF` run with +//! interrupts masked; a preempt hook may run with them open, since an +//! interrupt cannot move the count across zero between it and the count it +//! follows or precedes. A CPU is tracked from [`start_here`], where it joins +//! the scheduler. +//! +//! A window is reported by the report after it closes, so one still open when +//! a report is made belongs to the next. + +use core::sync::atomic::{AtomicU64, Ordering::Relaxed}; + +use crate::arch::{cpu, percpu}; +use crate::sched::MAX_CPUS; + +/// A CPU that has not yet joined the scheduler: every hook is a no-op on it. +const UNTRACKED: u64 = u64::MAX; + +/// One CPU's windows, written by that CPU alone; the report takes the longest +/// ones from another. The counter is never zero once firmware has run, so a +/// stamp of zero is no open window. +#[repr(align(64))] +struct Cpu { + /// [`UNTRACKED`], 0 while interrupts are open, else the counter at which they were masked. + irqs_off: AtomicU64, + /// 0 while the preempt count is zero, else the counter at which it left zero or a pass last ran. + preempt_off: AtomicU64, + irqs_longest: AtomicU64, + preempt_longest: AtomicU64, +} + +static CPUS: [Cpu; MAX_CPUS] = [const { + Cpu { + irqs_off: AtomicU64::new(UNTRACKED), + preempt_off: AtomicU64::new(0), + irqs_longest: AtomicU64::new(0), + preempt_longest: AtomicU64::new(0), + } +}; MAX_CPUS]; + +/// This CPU's windows once it is tracked; before the per-CPU block exists +/// there is no CPU to ask. +fn tracked() -> Option<&'static Cpu> { + if !crate::log::PERCPU_READY.load(Relaxed) { + return None; + } + let here = &CPUS[percpu::cpu_id() as usize]; + (here.irqs_off.load(Relaxed) != UNTRACKED).then_some(here) +} + +fn record(longest: &AtomicU64, since: u64, now: u64) { + let span = now.saturating_sub(since); + if span > longest.load(Relaxed) { + longest.fetch_max(span, Relaxed); + } +} + +/// A transition no hook saw. This CPU stops being tracked first, so the panic's +/// own masking finds nothing to check. +#[cold] +#[inline(never)] +fn unseen(what: &str) -> ! { + let cpu = percpu::cpu_id(); + CPUS[cpu as usize].irqs_off.store(UNTRACKED, Relaxed); + panic!("mask-windows: cpu{cpu} {what}"); +} + +/// Interrupts were open and this CPU has just masked them. +pub fn irqs_masked() { + let Some(here) = tracked() else { return }; + if here.irqs_off.load(Relaxed) != 0 { + unseen("masked interrupts with a window open: an unmask reached no hook"); + } + here.irqs_off.store(cpu::counter(), Relaxed); +} + +/// This CPU joins the scheduler, and its windows are tracked from here, open +/// as it stands. +pub fn start_here() { + let here = &CPUS[percpu::cpu_id() as usize]; + // Masked from here whatever it stood with; the guard's drop opens them + // again, through its hook, if it found them open. + let _masked = crate::arch::IrqGuard::close(); + let now = cpu::counter(); + here.preempt_off.store(if crate::preempt::count() == 0 { 0 } else { now }, Relaxed); + here.irqs_off.store(now, Relaxed); +} + +/// An exception's frame says it interrupted this CPU with interrupts masked. +pub fn irqs_found_masked() { + let Some(here) = tracked() else { return }; + if here.irqs_off.load(Relaxed) == 0 { + unseen("took an exception with interrupts masked and no window open: a mask reached no hook"); + } +} + +/// Interrupts are masked and this CPU is about to open them. +pub fn irqs_unmasking() { + let Some(here) = tracked() else { return }; + let since = here.irqs_off.load(Relaxed); + if since == 0 { + unseen("opened interrupts with no window open: a mask reached no hook"); + } + record(&here.irqs_longest, since, cpu::counter()); + here.irqs_off.store(0, Relaxed); +} + +/// The preempt count has just been raised by one. +pub fn preempt_raised() { + let Some(here) = tracked() else { return }; + if crate::preempt::count() != 1 { + return; + } + if here.preempt_off.load(Relaxed) != 0 { + unseen("raised the preempt count off zero with a window open: a lowering reached no hook"); + } + here.preempt_off.store(cpu::counter(), Relaxed); +} + +/// The preempt count is about to be lowered by one. +pub fn preempt_lowering() { + let Some(here) = tracked() else { return }; + if crate::preempt::count() != 1 { + return; + } + let since = here.preempt_off.load(Relaxed); + if since == 0 { + unseen("lowered the preempt count to zero with no window open: a raise reached no hook"); + } + record(&here.preempt_longest, since, cpu::counter()); + here.preempt_off.store(0, Relaxed); +} + +/// The preempt count was just set from `old` to `new` whole. +pub fn preempt_set(old: u32, new: u32) { + let Some(here) = tracked() else { return }; + let since = here.preempt_off.load(Relaxed); + match (old, new) { + (0, 0) => {} + (0, _) => { + if since != 0 { + unseen("set the preempt count off zero with a window open: a lowering reached no hook"); + } + here.preempt_off.store(cpu::counter(), Relaxed); + } + (_, 0) => { + if since == 0 { + unseen("set the preempt count to zero with no window open: a raise reached no hook"); + } + record(&here.preempt_longest, since, cpu::counter()); + here.preempt_off.store(0, Relaxed); + } + _ => {} + } +} + +/// A scheduler pass has decided what runs here: the window it ran in ends, +/// and the next starts, since the count is still raised. +pub fn scheduled() { + let Some(here) = tracked() else { return }; + let since = here.preempt_off.load(Relaxed); + if since == 0 { + unseen("ran a pass with no preemption-off window open: a raise reached no hook"); + } + let now = cpu::counter(); + record(&here.preempt_longest, since, now); + here.preempt_off.store(now, Relaxed); +} + +/// This CPU halts inside a pass, waiting for whatever runs next. The wait is +/// no window, so the one open ends here and the next opens at [`woken`]; an +/// interrupt taken meanwhile raises the count past one, which acts on nothing. +pub fn halting() { + let Some(here) = tracked() else { return }; + let since = here.preempt_off.load(Relaxed); + if since == 0 { + unseen("halted inside a pass with no preemption-off window open: a raise reached no hook"); + } + record(&here.preempt_longest, since, cpu::counter()); + here.preempt_off.store(0, Relaxed); +} + +/// The halt [`halting`] began has ended, still inside its pass. +pub fn woken() { + let Some(here) = tracked() else { return }; + if here.preempt_off.load(Relaxed) != 0 { + unseen("woke from a halt with a preemption-off window open: a raise reached no hook"); + } + here.preempt_off.store(cpu::counter(), Relaxed); +} + +/// `cpu`'s line, taking its longest windows so the next report starts from none. +pub fn log_cpu(cpu: u32) { + let Some(of) = CPUS.get(cpu as usize) else { return }; + let irqs = crate::clock::nanos_of_ticks(of.irqs_longest.swap(0, Relaxed)); + let preempt = crate::clock::nanos_of_ticks(of.preempt_longest.swap(0, Relaxed)); + crate::log!("windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}"); +} + +/// What `windows-staged` spins for. +#[cfg(feature = "boot-actuators")] +const STAGED_NS: u64 = 1_000_000; + +/// `windows-staged`: at the first process exit, spin for [`STAGED_NS`] inside +/// the exit syscall, where both windows are open, and say how long, so a later +/// report of this CPU must carry both windows at least that long. +#[cfg(feature = "boot-actuators")] +pub fn stage_once() { + use core::sync::atomic::AtomicBool; + static STAGED: AtomicBool = AtomicBool::new(false); + if STAGED.swap(true, Relaxed) { + return; + } + let ticks = crate::clock::counter_ticks(STAGED_NS); + assert!(ticks > 0, "windows-staged: the clock has no period to spin by"); + let from = cpu::counter(); + while cpu::counter().saturating_sub(from) < ticks { + core::hint::spin_loop(); + } + crate::log!( + "windows: staged cpu{} {}ns", + percpu::cpu_id(), + crate::clock::nanos_of_ticks(ticks) + ); +} diff --git a/src/build.rs b/src/build.rs index 15d9f5386ea..3578a161d50 100644 --- a/src/build.rs +++ b/src/build.rs @@ -1370,8 +1370,18 @@ fn declared_kernel_features(root: &Path) -> Vec { pub const TEST_KERNEL: &[&str] = &["boot-actuators", "test-actuators"]; /// Kernel builds the ordinary test suite is allowed to make. -pub const TEST_SUITE_KERNEL_BUILDS: [&str; 5] = - ["", "boot-actuators,test-actuators", "fpu-save-nothing", "sched-check", "user-writable-gsbase"]; +pub const TEST_SUITE_KERNEL_BUILDS: [&str; 6] = [ + "", + "boot-actuators,test-actuators", + "fpu-save-nothing", + "sched-check", + "user-writable-gsbase", + "boot-actuators,mask-windows,test-actuators", +]; + +/// The windows' instrument over the test kernel, for [`SCHED_CHECK_KERNEL`]'s +/// reason: one spelling, so one build. +pub const MASK_WINDOWS_KERNEL: &[&str] = &["boot-actuators", "mask-windows", "test-actuators"]; /// The scheduler core's own asserts, compiled in: `toyos-sched/check`. /// @@ -2712,6 +2722,10 @@ mod tests { "lock-acquire-off", "log-commit-release-off", "loom", + // The longest interrupts-off and preemption-off windows: a + // counter read on every masking transition and entry, so its + // own build and never one being measured for anything else. + "mask-windows", // `heap-lockspin`'s other arm: the same visit to the pass path, // for the same span, without the allocator's lock. "pass-spin", diff --git a/src/clippy.rs b/src/clippy.rs index 29a8f34f5b5..6e16dc6df39 100644 --- a/src/clippy.rs +++ b/src/clippy.rs @@ -39,13 +39,17 @@ struct Shape { const INSTRUMENTS: &str = "debug-wait,sched-check,sched-tripwire,heap-tripwire,heap-sweep,\ pass-spin,stack-witness,switch-witness,switch-witness-mutate-frame,\ switch-witness-mutate-rsp,df-witness,df-witness-mutate,\ - entry-df-unclean,fpu-save-nothing,user-writable-gsbase"; + entry-df-unclean,fpu-save-nothing,user-writable-gsbase,mask-windows"; /// [`INSTRUMENTS`] less the direction-flag three, which are x86-64's alone. const AARCH64_INSTRUMENTS: &str = "debug-wait,sched-check,sched-tripwire,heap-tripwire,heap-sweep,\ pass-spin,stack-witness,switch-witness,\ switch-witness-mutate-frame,switch-witness-mutate-rsp,\ - fpu-save-nothing,user-writable-gsbase"; + fpu-save-nothing,user-writable-gsbase,mask-windows"; + +/// `build::MASK_WINDOWS_KERNEL`, the one build whose arms need both the +/// windows and the actuators. +const MASK_WINDOWS_KERNEL: &str = "boot-actuators,mask-windows,test-actuators"; const UNCONTROLLED: &[&str] = &["toyos-pcid/counting-allocator", "toyos-sched/tripwire"]; @@ -96,6 +100,11 @@ const SHAPES: &[Shape] = &[ before: &["--target", Arch::X86_64.kernel(), "--features", INSTRUMENTS], after: &["$ADOPTED", "-D", "warnings"], }, + Shape { + dir: "kernel", + before: &["--target", Arch::X86_64.kernel(), "--features", MASK_WINDOWS_KERNEL], + after: &["$ADOPTED", "-D", "warnings"], + }, Shape { dir: "kernel", before: &["--target", Arch::X86_64.kernel(), "--features", "heap-band-notail,heap-lockspin"], @@ -126,6 +135,11 @@ const SHAPES: &[Shape] = &[ before: &["--target", Arch::Aarch64.kernel(), "--features", AARCH64_INSTRUMENTS], after: &["$ADOPTED", "-D", "warnings"], }, + Shape { + dir: "kernel", + before: &["--target", Arch::Aarch64.kernel(), "--features", MASK_WINDOWS_KERNEL], + after: &["$ADOPTED", "-D", "warnings"], + }, Shape { dir: "bootloader", before: &["--target", Arch::X86_64.loader()], diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index ee27653e911..aaac694b745 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -1,4 +1,5 @@ -//! The kernel's interrupt census, read back on the host. +//! The kernel's interrupt census, and the windows a `mask-windows` kernel +//! prints beside it, read back on the host. //! //! The guest prints `irq: cpuN total=… timer=… …` per online CPU whenever a //! process exits, on `SYS_SHUTDOWN` and on the blocked-task dump @@ -98,6 +99,113 @@ impl Census { } } +/// One CPU's longest interrupts-off and preemption-off windows since the report +/// before, out of the line a `mask-windows` kernel prints beside that CPU's +/// census (`kernel/src/windows.rs`). +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct Windows { + pub cpu: u32, + pub irqs_off_ns: u64, + pub preempt_off_ns: u64, +} + +impl Windows { + /// One line, or why it is not one; anything before `windows: cpu` is ignored. + pub fn parse(line: &str) -> Option> { + let rest = line.split("windows: cpu").nth(1)?; + let fields: Vec<&str> = rest.split_whitespace().collect(); + let value = |at: usize, name: &str| -> Result { + fields + .get(at) + .and_then(|f| f.strip_prefix(name)) + .and_then(|v| v.parse().ok()) + .ok_or_else(|| format!("no `{name}` field at {at} in {rest:?}")) + }; + let parsed = (|| { + if fields.len() != 3 { + return Err(format!("{} fields, want 3, in {rest:?}", fields.len())); + } + let cpu = fields[0].parse().map_err(|_| format!("unreadable cpu number in {rest:?}"))?; + Ok(Self { cpu, irqs_off_ns: value(1, "irqs_off_ns=")?, preempt_off_ns: value(2, "preempt_off_ns=")? }) + })(); + Some(parsed) + } +} + +/// The head of the line `windows-staged` says what it spun with, +/// `windows: staged cpuK ns`. +pub const STAGED: &str = "windows: staged cpu"; + +fn staged(line: &str) -> Option> { + let rest = line.split(STAGED).nth(1)?; + let parsed = rest + .trim() + .split_once(' ') + .and_then(|(cpu, ns)| Some((cpu.parse().ok()?, ns.strip_suffix("ns")?.parse().ok()?))) + .ok_or_else(|| format!("unreadable staged span in {rest:?}")); + Some(parsed) +} + +/// The judge of every `mask-windows` boot: each census line has its CPU's +/// windows line beside it, each CPU closed both kinds of window at some point +/// of the boot, and a span `windows-staged` spun is carried, in both windows, +/// by a later report of the CPU it spun on. Answers each CPU's longest windows +/// over the whole capture. +pub fn windows(capture: &str) -> Result, String> { + let mut censuses: BTreeMap = BTreeMap::new(); + let mut reports: Vec = Vec::new(); + // Where each staged span was said, as a position in `reports`. + let mut spun: Vec<(usize, u32, u64)> = Vec::new(); + for line in capture.lines() { + if let Some(census) = Census::parse(line) { + *censuses.entry(census.map_err(|why| format!("{why}\nline: {line}"))?.cpu).or_default() += 1; + } else if let Some(report) = Windows::parse(line) { + reports.push(report.map_err(|why| format!("{why}\nline: {line}"))?); + } else if let Some(said) = staged(line) { + let (cpu, ns) = said?; + spun.push((reports.len(), cpu, ns)); + } + } + if censuses.is_empty() { + return Err(format!("no `irq: cpu` census in the capture:\n{capture}")); + } + let mut beside: BTreeMap = BTreeMap::new(); + for report in &reports { + *beside.entry(report.cpu).or_default() += 1; + } + if beside != censuses { + return Err(format!( + "census lines per cpu {censuses:?} and windows lines per cpu {beside:?}: a census \ + went out without its windows, or windows without their census" + )); + } + let mut longest: BTreeMap = BTreeMap::new(); + for report in &reports { + let most = longest.entry(report.cpu).or_insert(Windows { irqs_off_ns: 0, preempt_off_ns: 0, ..*report }); + most.irqs_off_ns = most.irqs_off_ns.max(report.irqs_off_ns); + most.preempt_off_ns = most.preempt_off_ns.max(report.preempt_off_ns); + } + for most in longest.values() { + if most.irqs_off_ns == 0 || most.preempt_off_ns == 0 { + return Err(format!( + "cpu{} closed no window of one kind in the whole boot, and every CPU masks and \ + passes: {most:?}", + most.cpu + )); + } + } + for (at, cpu, ns) in spun { + let later: Vec<&Windows> = reports[at..].iter().filter(|r| r.cpu == cpu).collect(); + if !later.iter().any(|r| r.irqs_off_ns >= ns) || !later.iter().any(|r| r.preempt_off_ns >= ns) { + return Err(format!( + "cpu{cpu} spun {ns}ns with both windows open, and no later report of it carries \ + both that long: {later:?}" + )); + } + } + Ok(longest) +} + /// The newest census each CPU of each guest printed, keyed by the boot's own /// sequence number. /// diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 7feb27c1729..9dcb2c5d263 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -187,9 +187,12 @@ pub fn boot_census() -> (u32, u32, Vec) { /// were compiled by no CI run at all. `sched_check_build` is the test that asks. /// /// A fifth entry is that decision again, and it gets this paragraph's argument -/// made afresh. Interactive debug mode is separate: it builds -/// [`toyos_build::build::DEBUG_KERNEL_BUILD`] and returns before the suite. -pub const DECLARED_KERNEL_BUILDS: [&str; 5] = +/// made afresh. [`toyos_build::build::MASK_WINDOWS_KERNEL`] made it: its hooks +/// sit on every entry and masking primitive, where a parameter would be a +/// branch on the path they measure, and it carries the test kernel's actuators +/// so a staged span can hold it to one. Interactive debug mode is separate: it +/// builds [`toyos_build::build::DEBUG_KERNEL_BUILD`] and returns before the suite. +pub const DECLARED_KERNEL_BUILDS: [&str; 6] = toyos_build::build::TEST_SUITE_KERNEL_BUILDS; /// How many guests the phase now running may have up at once. @@ -2618,8 +2621,8 @@ fn refuse_a_staged_image_this_boot_did_not_ask_for(image: &Path, options: &BootO /// Which of [`DECLARED_KERNEL_BUILDS`] this boot wants. /// /// **A parameter never decides a build.** Every actuator lives in the one test -/// kernel, so asking for one selects that kernel and nothing more; the third -/// build is asked for by name and by one test. +/// kernel, so asking for one selects that kernel and nothing more; a build +/// asked for by name arms one only if it carries them all too. /// /// A boot handed a [`BootOptions::boot_image`] builds nothing at all, and this /// then answers what that image already carries: the two agree or the boot was @@ -2628,14 +2631,17 @@ fn kernel_of(options: &BootOptions) -> Vec<&'static str> { if options.kernel_params.is_empty() { return options.kernel_features.to_vec(); } + if options.kernel_features.is_empty() { + return toyos_build::build::TEST_KERNEL.to_vec(); + } assert!( - options.kernel_features.is_empty(), - "a boot asking to arm {:?} also asks for the kernel build {:?}; an actuator is a \ - parameter and the test kernel carries all of them", + options.kernel_features.contains(&"boot-actuators"), + "a boot asking to arm {:?} asks for the kernel build {:?}, which carries no actuator; \ + an actuator is a parameter and the test kernel carries all of them", options.kernel_params, options.kernel_features, ); - toyos_build::build::TEST_KERNEL.to_vec() + options.kernel_features.to_vec() } // Eight, because an image is its architecture as much as its files and its kernel. diff --git a/tests/toyos-rust-tests/src/bin/ring_park_herd.rs b/tests/toyos-rust-tests/src/bin/ring_park_herd.rs new file mode 100644 index 00000000000..1a609b84e2c --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/ring_park_herd.rs @@ -0,0 +1,114 @@ +//! **One process parks 256 threads in `submit` on one ring, and a sibling +//! thread completes into it.** +//! +//! A ring's own watch sits behind a lock that masks interrupts, so every +//! completion notifies all 256 registrations with interrupts masked, and each +//! woken thread re-registers under that lock and parks again: the load +//! `issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md` +//! names, which `mask_windows` reads the windows under. +//! +//! The sibling is this program's main thread. Each round it completes one +//! `OP_NOP` and takes the completion back, so the count the parked threads +//! wait for never reaches two, and it posts the next only once the kernel's +//! roster shows every one of them parked again. Two completions left standing +//! end the run. + +use std::sync::atomic::{AtomicU32, Ordering}; +use std::thread; + +use toyos::endow::{Endowments, SYSCAP_LABEL}; +use toyos::syscap::SysCap; +use toyos_abi::inbox::{RingHeader, Submission, COMPLETION_RING_OFF, OP_NOP, SUBMISSIONS_OFF, SUBMISSION_RING_OFF}; +use toyos_abi::syscall; +use toyos_abi::RawHandle; + +#[path = "../roster.rs"] +mod roster; + +const PARKED: usize = 256; + +/// Completions each parked thread is woken by and parks again after. +const ROUNDS: u64 = 64; + +/// The fewest the ring takes: the sibling never has more than two in it. +const DEPTH: u32 = 2; + +/// What every parked thread waits for, and what the sibling leaves only at the end. +const ENDING: u32 = 2; + +/// The ring's page, as `toyos::poller` reaches it: one atomic word or one +/// whole entry at a time, since the kernel writes it too. +struct Ring { + handle: RawHandle, + base: *mut u8, +} + +// SAFETY: the page stays mapped until the handle closes, after every thread is joined. +unsafe impl Sync for Ring {} + +impl Ring { + fn word(&self, ring_off: u64, field_off: usize) -> &AtomicU32 { + // SAFETY: inside the inbox page, 4-aligned; an atomic is sound over memory the kernel also writes. + unsafe { AtomicU32::from_ptr(self.base.add(ring_off as usize + field_off) as *mut u32) } + } + + /// One `OP_NOP`, handed to the kernel, which completes it at once. + fn complete_one(&self, token: u64) { + let tail = self.word(SUBMISSION_RING_OFF, core::mem::offset_of!(RingHeader, tail)); + let at = tail.load(Ordering::Relaxed); + let entry = Submission { op: OP_NOP, token, ..Submission::default() }; + // SAFETY: the slot `at` masks to is inside the page's submission array, which only this thread writes. + unsafe { + (self.base.add( + SUBMISSIONS_OFF as usize + (at & (DEPTH - 1)) as usize * core::mem::size_of::(), + ) as *mut Submission) + .write(entry); + } + tail.store(at.wrapping_add(1), Ordering::Release); + syscall::inbox_submit(self.handle, 1, 0, 0).expect("the sibling's submit"); + } + + /// Take the oldest completion back, so the count falls. + fn consume_one(&self) { + let head = self.word(COMPLETION_RING_OFF, core::mem::offset_of!(RingHeader, head)); + head.fetch_add(1, Ordering::Release); + } +} + +fn main() { + let cap: SysCap = Endowments::get() + .take(SYSCAP_LABEL) + .expect("test-runner endows every binary it spawns a system capability"); + // SAFETY: the page is read only through `Ring`, and the handle closes after every thread is joined. + let (handle, base) = unsafe { syscall::inbox_setup(DEPTH) }.expect("the ring"); + let ring = Ring { handle, base }; + + let parked_all = || { + roster::my_threads(&cap) + .iter() + .filter(|&&(is_thread, state)| is_thread && state == roster::BLOCKED) + .count() + == PARKED + }; + + thread::scope(|s| { + for _ in 0..PARKED { + s.spawn(|| { + let answered = syscall::inbox_submit(ring.handle, 0, ENDING, u64::MAX) + .expect("a parked thread's submit"); + assert!(answered >= ENDING, "a parked thread returned with {answered} completions"); + }); + } + roster::await_true(parked_all); + for round in 0..ROUNDS { + ring.complete_one(round); + ring.consume_one(); + roster::await_true(parked_all); + } + for token in 0..u64::from(ENDING) { + ring.complete_one(ROUNDS + token); + } + }); + syscall::close(handle); + println!("ring_park_herd: {PARKED} threads parked in submit on one ring, woken by {ROUNDS} completions"); +} diff --git a/tests/toyos-rust-tests/src/roster.rs b/tests/toyos-rust-tests/src/roster.rs index cbd5612e11d..4c59182836f 100644 --- a/tests/toyos-rust-tests/src/roster.rs +++ b/tests/toyos-rust-tests/src/roster.rs @@ -33,9 +33,13 @@ pub fn my_threads(cap: &SysCap) -> Vec<(bool, u8)> { pub fn threads_of(cap: &SysCap, pid: u32) -> Vec<(bool, u8)> { const HEADER: usize = toyos::system::SYSINFO_HEADER_SIZE; const ENTRY: usize = toyos::system::SYSINFO_ENTRY_SIZE; - let mut buf = vec![0u8; HEADER + ENTRY * 256]; + const ENTRIES: usize = 1024; + let mut buf = vec![0u8; HEADER + ENTRY * ENTRIES]; let n = cap.roster(&mut buf); assert!((HEADER..=buf.len()).contains(&n), "sysinfo answered {n}"); + // Past the buffer the roster is cut short, and a thread cut off is one never found. + let live = toyos_abi::syscall::SysinfoHeader::decode(buf[..HEADER].try_into().unwrap()).entries; + assert!(live as usize <= ENTRIES, "the machine has {live} threads and the roster holds {ENTRIES}"); (HEADER..) .step_by(ENTRY) .take_while(|pos| pos + ENTRY <= n) diff --git a/tests/toyos.rs b/tests/toyos.rs index f031b536ad4..573ff6ee695 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -162,6 +162,10 @@ const RUST_SKIP: &[&str] = &[ // is read off the clock around the syscall. The `tlb_shootdown_waits` // metal row runs it on the T14. "tlb_shootdown_waits", + // Its product is the windows a `mask-windows` kernel reports under it, and + // its 256 threads' stacks would crowd every member after it in one boot. + // `mask_windows` runs it. + "ring_park_herd", // **It reboots the machine**, so in the shared block it would end the boot // under whichever member came next; and its verdict is the order of the // console after that reset, which only its own boot holds. @@ -518,6 +522,9 @@ const SCREEN_TESTS: &[(&str, Sched, qemu::Profile)] = &[ ("virt_unmap_touch", Sched::Parallel, qemu::Profile::VirtEl2), ("virt_debug_refused", Sched::Parallel, qemu::Profile::VirtEl2), ("virt_readonly_copyout", Sched::Parallel, qemu::Profile::VirtEl2), + // `mask_windows`' judge over every AArch64 job: the windows each report + // carries and the staged span, counts and an order; no clock. + ("virt_mask_windows", Sched::Parallel, qemu::Profile::VirtEl2), ("virt_smp", Sched::Parallel, qemu::Profile::VirtEl2), ("virt_el1_smp", Sched::Parallel, qemu::Profile::VirtTcg), ("virt_failed_ap_leaves_no_hole", Sched::Parallel, qemu::Profile::VirtEl2), @@ -576,6 +583,11 @@ const MACHINE_TESTS: &[(&str, Sched)] = &[ // arithmetic over counters the guest printed, and there is no clock in any // of it. ("irq_census_conservation", Sched::Parallel), + // The longest interrupts-off and preemption-off windows, beside the + // census, under one process's 256 threads parked on one ring: a staged + // span is carried by a later report, and every hook's check held. Counts + // and an order of reports; no clock in the verdict. + ("mask_windows", Sched::Parallel), ("control_regs", Sched::Parallel), ("control_regs_negative", Sched::Parallel), // The boot facts the metal suite reads off a machine's own records: every @@ -1366,6 +1378,7 @@ const CARRIES: &[(&str, &[&str])] = &[ ("short_sleep_livelock", &["test_rs_abuse_short_sleep"]), ("heap_ceiling_bounds", &["test_rs_heap_ceiling"]), ("irq_census_conservation", &["test_rs_std_mmap"]), + ("mask_windows", &["test_rs_ring_park_herd"]), ("i8042_health", &["test_rs_i8042_keyboard"]), ("i8042_fadt_denial", &["test_rs_i8042_keyboard"]), ("i8042_kbd_echo", &["test_rs_i8042_keyboard"]), @@ -1573,6 +1586,12 @@ const METAL: &[(&str, metal::Metal)] = &[ judge: |b| irq_census(b[0].kernel().text()), }, ), + ( + // The windows on the machine that owes them: every CPU reported beside + // its census, and the boot's longest and the herd's own recorded. + "mask_windows", + metal::Metal::Runs { arms: WINDOWSCASE, judge: |b| windows_on_metal(b[0]) }, + ), ( // `log-close` is a runner builtin and prints its `survived=` evidence to // a console nothing is on. What crosses is the child it spawns only @@ -2077,6 +2096,13 @@ const TESTCASES_READDIR: &[metal::Arm] = const JOBCASE: &[metal::Arm] = &[metal::once("jobcase", "tests/jobcase", &[], &[])]; +/// The shipping kernel with the windows' instrument and nothing else, so what +/// it reads is that kernel under the herd. +const WINDOWSCASE: &[metal::Arm] = &[metal::Arm { + features: &["mask-windows"], + ..metal::once("windowscase", "tests/testcases", &[], &["test_rs_ring_park_herd"]) +}]; + /// A `logd` that leaves soundd's ring unread until the job says the tone played. const LOGSTALLCASE: &[metal::Arm] = &[metal::once("logstallcase", "tests/logstallcase", &[], &["test_rs_soundd_log_stall"])]; @@ -3573,6 +3599,30 @@ fn virt_job(profile: qemu::Profile, job: &str, said: &str) -> Result<(), String> judge_virt_job(qemu, job, said).map(drop) } +/// `mask_windows` on AArch64: every job of `tests/virtjobcase` run on a +/// `mask-windows` kernel with a span staged in the first exit, judged once the +/// last has ended. +fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { + let config = compile::repo_root().join("tests/virtjobcase/system.toml"); + let case = config.parent().expect("system.toml has a directory"); + let qemu = QemuInstance::boot_with_options( + case, + &[], + &[], + BootOptions { + profile, + smp: 1, + kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL, + kernel_params: &["windows-staged"], + ready_marker: "control registers: SCTLR_EL1=", + extra_root_files: vec![(format!("bin/test_rs_{VIRT_COPYOUT}"), virt_copyout(profile.arch()).to_vec())], + ..Default::default() + }, + ); + let serial = judge_virt_job(qemu, &format!("test_rs_{VIRT_COPYOUT}"), "a syscall writes only where its caller could store")?; + mask_windows(&serial, 1) +} + /// 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(mut qemu: QemuInstance, job: &str, said: &str) -> Result { @@ -5248,6 +5298,7 @@ fn run_screen_test( "virt_readonly_copyout" => { virt_job(profile, &format!("test_rs_{VIRT_COPYOUT}"), "a syscall writes only where its caller could store") } + "virt_mask_windows" => virt_mask_windows(profile), "virt_irq_storm" => { // The CPU floods itself with SGIs until the timer has fired a // thousand times through the flood, then waits for every SGI it @@ -12081,6 +12132,31 @@ fn run_machine_test( first.before, first.serial, second.before, second.serial )) } + "mask_windows" => { + // Four CPUs, and a first process whose exit the staged span is + // spun inside, so the herd's exit reports it: every hook runs + // under the herd, and a transition none saw panics the guest. + let options = BootOptions { + smp: 4, + kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL, + kernel_params: &["windows-staged"], + ..BootOptions::default() + }; + let mut qemu = + QemuInstance::boot_with_options(test_config, c_bins, rust_bins, options); + let boot = qemu.boot_log().to_string(); + let first = qemu.run_test("echo one", Duration::from_secs(30)); + let herd = qemu.run_test("test_rs_ring_park_herd", Duration::from_secs(120)); + if let Some(err) = &herd.error { + return Err(format!("the herd's guest stopped answering: {err}\nserial:\n{}", herd.serial)); + } + if !check_rust_result(&herd) { + return Err(format!("ring_park_herd failed:\n{}", herd.stdout)); + } + let capture = + format!("{boot}\n{}\n{}\n{}\n{}", first.before, first.serial, herd.before, herd.serial); + mask_windows(&capture, 4) + } "ioapic_topology" => { // Everything the I/O APIC driver says happens in Phase 2, long // before the virtio-console exists, so the 16550 file is where a @@ -14167,6 +14243,65 @@ fn parse_xhci_binds(log: &str) -> Vec { /// Both halves, because the kernel writes both registers whole: every bit named /// below must hold its named value, **and a bit named nowhere below may not be /// set at all**. Silence about a bit is a hole rather than a permission. +/// A `windows-staged` boot's windows: `common::irqcensus::windows`'s verdict, +/// with the staged span said and `cpus` CPUs reporting. +fn mask_windows(capture: &str, cpus: u32) -> Result<(), String> { + if !capture.contains(common::irqcensus::STAGED) { + return Err(format!("`windows-staged` said no span, so nothing was held to one:\n{capture}")); + } + let longest = common::irqcensus::windows(capture)?; + if longest.len() != cpus as usize { + return Err(format!("{} of {cpus} CPUs reported windows: {longest:?}", longest.len())); + } + for most in longest.values() { + eprintln!( + " [windows] cpu{} irqs_off_ns={} preempt_off_ns={}", + most.cpu, most.irqs_off_ns, most.preempt_off_ns + ); + } + Ok(()) +} + +/// The T14's windows: `common::irqcensus::windows`' verdict with every CPU +/// reporting, and the longest over the boot and in the herd's own report — the +/// one its exit printed, just before its exit record — recorded. +fn windows_on_metal(boot: &metal::Readback) -> Result<(), String> { + const HERD: &str = "test_rs_ring_park_herd"; + boot.job_passed(HERD)?; + let kernel = boot.kernel(); + let text = kernel.text(); + let longest = common::irqcensus::windows(text)?; + let cpus = boot.cpus()?; + if longest.len() != cpus as usize { + return Err(format!("{} of {cpus} CPUs reported windows: {longest:?}", longest.len())); + } + let exited = format!("{}{} pid=", toyos_build::bootlog::EXIT, toyos_build::bootlog::recorded_name(HERD)); + let mut latest = std::collections::BTreeMap::new(); + let mut herd = None; + for line in text.lines() { + if let Some(Ok(report)) = common::irqcensus::Windows::parse(line) { + latest.insert(report.cpu, report); + } else if line.contains(&exited) { + herd = Some(latest.clone()); + break; + } + } + let herd = herd.ok_or_else(|| format!("no `{exited}` record after a report:\n{text}"))?; + let most = |of: &mut dyn Iterator| { + of.fold((0, 0), |(i, p), w| (w.irqs_off_ns.max(i), w.preempt_off_ns.max(p))) + }; + let (irqs, preempt) = most(&mut longest.values()); + let (herd_irqs, herd_preempt) = most(&mut herd.values()); + eprintln!( + " [windows] boot irqs_off_ns={irqs} preempt_off_ns={preempt}; herd irqs_off_ns={herd_irqs} \ + preempt_off_ns={herd_preempt}" + ); + boot.measured("windows.windowscase.irqs_off_ns", irqs)?; + boot.measured("windows.windowscase.preempt_off_ns", preempt)?; + boot.measured("windows.windowscase.herd_irqs_off_ns", herd_irqs)?; + boot.measured("windows.windowscase.herd_preempt_off_ns", herd_preempt) +} + /// The interrupt census adds up, is monotonic, and every device delivery is /// still cpu0's. /// From 2f17b8038e081b430049d500328238e85fe1886b Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 23:44:29 +0200 Subject: [PATCH 02/13] mask_windows_verdict: the windows judge against captures no guest produces Positive control first, then seven refusals: no staged span, a staged span no later report carries, one carried only by a report before it, a census without its windows, a CPU that closed no window, one CPU of two, and a field missing. With the staged check reduced to "some later report exists" it reds: "a staged span no later report carries was accepted". Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- tests/checks.rs | 57 +++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 57 insertions(+) diff --git a/tests/checks.rs b/tests/checks.rs index 0bfca6e3cd7..d3f67bf2cee 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -343,6 +343,63 @@ mod checks { Ok(()) } + /// [`mask_windows`] against captures no guest has to produce: two CPUs, + /// two reports, and a span staged between them. + #[test] + fn mask_windows_verdict() -> Result<(), String> { + let census = |cpu: u32| { + format!( + "[kernel 0.1 cpu0] irq: cpu{cpu} total=0 timer=0 xhci=0 userdev=0 sound=0 i8042=0 \ + dmafault=0 hda=0 tlb=0 nmi=0 spurious=0 unclaimed=0\n" + ) + }; + let windows = |cpu: u32, irqs: u64, preempt: u64| { + format!("[kernel 0.1 cpu0] windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}\n") + }; + let staged = "[kernel 0.1 cpu1] windows: staged cpu1 1000000ns\n"; + let good = [ + census(0), windows(0, 5, 7), census(1), windows(1, 3, 4), + staged.to_string(), + census(0), windows(0, 2, 2), census(1), windows(1, 1_000_000, 1_200_000), + ] + .concat(); + let refused = |what: &str, capture: &str, says: &str| match mask_windows(capture, 2) { + Ok(()) => Err(format!("{what} was accepted")), + Err(e) if e.contains(says) => Ok(()), + Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")), + }; + + mask_windows(&good, 2).map_err(|e| format!("the good capture was refused: {e}"))?; + + refused("no staged span", &good.replace(staged, ""), "said no span")?; + refused( + "a staged span no later report carries", + &good.replace("irqs_off_ns=1000000", "irqs_off_ns=999999"), + "spun 1000000ns", + )?; + refused( + "a staged span carried only by a report before it", + &[ + census(0), windows(0, 5, 7), census(1), windows(1, 1_000_000, 1_200_000), + staged.to_string(), + census(0), windows(0, 2, 2), census(1), windows(1, 3, 4), + ] + .concat(), + "spun 1000000ns", + )?; + refused("a census without its windows", &good.replace(&windows(0, 2, 2), ""), "went out without")?; + refused( + "a CPU that closed no window", + &good.replace(&windows(0, 5, 7), &windows(0, 0, 7)).replace(&windows(0, 2, 2), &windows(0, 0, 2)), + "closed no window", + )?; + refused("one CPU of two", &[census(0), windows(0, 5, 7), staged.replace("cpu1", "cpu0"), census(0), windows(0, 1_000_000, 1_000_000)].concat(), "1 of 2")?; + refused("a field missing", &good.replace(" preempt_off_ns=7", ""), "fields")?; + + eprintln!(" [mask_windows] the verdict refuses 7 captures and accepts one"); + Ok(()) + } + /// What the declaration itself has to be, before any of it means anything. /// Which shared-boot binaries need `SYS_DEBUG`, asked of their source. /// From 865585cfbe013bab3e132a43c1bda79e0aca10c6 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 23:46:24 +0200 Subject: [PATCH 03/13] windows-staged spins 250 ms, past what an emulated guest closes on its own MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A 1 ms span is inside what a TCG guest's own windows can reach — the herd's completion alone walks 256 waiters — so with the spin removed a later report could still carry it and the negative control would stay green. 250 ms stands above that and far inside `time::DEAF_CPU`'s 5 s. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- kernel/src/windows.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index e673897e09a..293aa013f43 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -221,9 +221,11 @@ pub fn log_cpu(cpu: u32) { crate::log!("windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}"); } -/// What `windows-staged` spins for. +/// What `windows-staged` spins for: past any window an emulated guest closes +/// on its own, so a report carrying it carries the spin, and far inside +/// `time::DEAF_CPU`. #[cfg(feature = "boot-actuators")] -const STAGED_NS: u64 = 1_000_000; +const STAGED_NS: u64 = 250_000_000; /// `windows-staged`: at the first process exit, spin for [`STAGED_NS`] inside /// the exit syscall, where both windows are open, and say how long, so a later From 66530cf6beaefb9ccc565fcf9595235ae36ba74c Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 23:59:54 +0200 Subject: [PATCH 04/13] The windows' record is toyos-sched's, sans-IO, and its semantics are host tests `toyos_sched::windows::Windows` is one CPU's record: every transition takes the caller's counter reading (read only when the transition needs it) and answers `Unseen` for one that could not have followed the state it finds. The kernel's `windows.rs` is the glue: the per-CPU statics, the hooks each architecture calls, the report and `windows-staged`. What no guest can red now reds on the host: a pass ends the preemption-off window and starts the next, the idle halt inside a pass is no window, only a crossing of zero opens or closes one (and a raise past one reads no clock), the longest since the last take is what a take answers, and each transition nothing reported before is named. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- kernel/src/windows.rs | 219 ++++++---------------- toyos-sched/loom/src/lib.rs | 2 + toyos-sched/src/lib.rs | 1 + toyos-sched/src/windows.rs | 351 ++++++++++++++++++++++++++++++++++++ 4 files changed, 410 insertions(+), 163 deletions(-) create mode 100644 toyos-sched/src/windows.rs diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index 293aa013f43..aedf712e8b8 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -1,224 +1,117 @@ -//! The longest interrupts-off and the longest preemption-off window each CPU -//! closed since the last report, printed beside the IRQ census as +//! Each CPU's [`toyos_sched::windows::Windows`], fed where this CPU's +//! interrupts and preempt count change, and printed beside the IRQ census as //! `windows: cpuN irqs_off_ns=… preempt_off_ns=…` (`mask-windows` builds only). //! -//! **An interrupts-off window** opens where this CPU stops taking maskable -//! interrupts and closes where it takes them again. Each architecture feeds -//! [`irqs_masked`] and [`irqs_unmasking`] from every instruction that changes -//! that: its masking primitives, the halt, every entry (a gate, `SYSCALL` or an +//! Each architecture calls [`irqs_masked`] and [`irqs_unmasking`] from every +//! instruction that changes whether it takes a maskable interrupt: its +//! masking primitives, the halt, every entry (a gate, `SYSCALL` or an //! exception masks) and every return (`scheduler::exit_to_user`'s end for a -//! return to user mode, the entry's own hook for a return to the kernel). A -//! context switch changes nothing: this build switches inside an -//! `IrqGuard`, so every saved context holds interrupts masked. An NMI is not -//! a window: nothing masks it, and it runs no hook. +//! return to user mode, the entry's own hook for a return to the kernel). +//! Every entry is also held to what the hardware says it interrupted: a +//! maskable interrupt is delivered only with interrupts open, and an +//! exception's frame carries the flag. A context switch changes nothing: this +//! build switches inside an `IrqGuard`, so every saved context holds +//! interrupts masked. An NMI is not a window: nothing masks it, and it runs no +//! hook. [`preempt_raised`] and [`preempt_lowering`] follow the preempt count's +//! accessors and the entries that move it inline. //! -//! **A preemption-off window** opens where this CPU's preempt count leaves -//! zero and closes where it returns there. A scheduler pass ends it and starts -//! the next, because a pass is where a waiting thread gets the CPU, and the -//! idle halt inside a pass is no window, since a wake ends it. -//! [`preempt_raised`] follows every raise by one and [`preempt_lowering`] -//! precedes every lowering by one; each acts only on a crossing of zero. -//! -//! **Every hook checks the state it finds against the transition it -//! reports**, so a transition no hook saw panics at the next hook on that CPU, -//! and every entry is held to what the CPU says it interrupted: a maskable -//! interrupt is delivered only with interrupts open, and an exception's frame -//! carries the flag. The hooks that change `IF` run with -//! interrupts masked; a preempt hook may run with them open, since an -//! interrupt cannot move the count across zero between it and the count it -//! follows or precedes. A CPU is tracked from [`start_here`], where it joins -//! the scheduler. -//! -//! A window is reported by the report after it closes, so one still open when -//! a report is made belongs to the next. +//! The hooks that change `IF` run with interrupts masked; a preempt hook may +//! run with them open, since an interrupt cannot move the count across zero +//! between it and the count it follows or precedes. A transition the record +//! refuses panics, after the CPU stops being tracked so the panic's own +//! masking finds nothing to check. A CPU is tracked from [`start_here`], where +//! it joins the scheduler, and a window is reported by the report after it +//! closes. -use core::sync::atomic::{AtomicU64, Ordering::Relaxed}; +use core::sync::atomic::Ordering::Relaxed; + +use toyos_sched::windows::{Unseen, Windows}; use crate::arch::{cpu, percpu}; use crate::sched::MAX_CPUS; -/// A CPU that has not yet joined the scheduler: every hook is a no-op on it. -const UNTRACKED: u64 = u64::MAX; - -/// One CPU's windows, written by that CPU alone; the report takes the longest -/// ones from another. The counter is never zero once firmware has run, so a -/// stamp of zero is no open window. -#[repr(align(64))] -struct Cpu { - /// [`UNTRACKED`], 0 while interrupts are open, else the counter at which they were masked. - irqs_off: AtomicU64, - /// 0 while the preempt count is zero, else the counter at which it left zero or a pass last ran. - preempt_off: AtomicU64, - irqs_longest: AtomicU64, - preempt_longest: AtomicU64, -} - -static CPUS: [Cpu; MAX_CPUS] = [const { - Cpu { - irqs_off: AtomicU64::new(UNTRACKED), - preempt_off: AtomicU64::new(0), - irqs_longest: AtomicU64::new(0), - preempt_longest: AtomicU64::new(0), - } -}; MAX_CPUS]; +static CPUS: [Windows; MAX_CPUS] = [const { Windows::new() }; MAX_CPUS]; -/// This CPU's windows once it is tracked; before the per-CPU block exists -/// there is no CPU to ask. -fn tracked() -> Option<&'static Cpu> { +/// This CPU's record, once there is a per-CPU block to say which CPU this is. +fn on(transition: impl FnOnce(&Windows) -> Result<(), Unseen>) { if !crate::log::PERCPU_READY.load(Relaxed) { - return None; + return; } - let here = &CPUS[percpu::cpu_id() as usize]; - (here.irqs_off.load(Relaxed) != UNTRACKED).then_some(here) -} - -fn record(longest: &AtomicU64, since: u64, now: u64) { - let span = now.saturating_sub(since); - if span > longest.load(Relaxed) { - longest.fetch_max(span, Relaxed); + if let Err(unseen) = transition(&CPUS[percpu::cpu_id() as usize]) { + refuse(unseen); } } -/// A transition no hook saw. This CPU stops being tracked first, so the panic's -/// own masking finds nothing to check. #[cold] #[inline(never)] -fn unseen(what: &str) -> ! { +fn refuse(unseen: Unseen) -> ! { let cpu = percpu::cpu_id(); - CPUS[cpu as usize].irqs_off.store(UNTRACKED, Relaxed); - panic!("mask-windows: cpu{cpu} {what}"); -} - -/// Interrupts were open and this CPU has just masked them. -pub fn irqs_masked() { - let Some(here) = tracked() else { return }; - if here.irqs_off.load(Relaxed) != 0 { - unseen("masked interrupts with a window open: an unmask reached no hook"); - } - here.irqs_off.store(cpu::counter(), Relaxed); + CPUS[cpu as usize].stop(); + panic!("mask-windows: cpu{cpu} {unseen}"); } -/// This CPU joins the scheduler, and its windows are tracked from here, open -/// as it stands. +/// This CPU joins the scheduler, and is tracked from here. pub fn start_here() { - let here = &CPUS[percpu::cpu_id() as usize]; // Masked from here whatever it stood with; the guard's drop opens them // again, through its hook, if it found them open. let _masked = crate::arch::IrqGuard::close(); - let now = cpu::counter(); - here.preempt_off.store(if crate::preempt::count() == 0 { 0 } else { now }, Relaxed); - here.irqs_off.store(now, Relaxed); + CPUS[percpu::cpu_id() as usize].start(crate::preempt::count(), cpu::counter()); +} + +/// Interrupts were open and this CPU has just masked them. +pub fn irqs_masked() { + on(|w| w.masked(cpu::counter)); } /// An exception's frame says it interrupted this CPU with interrupts masked. pub fn irqs_found_masked() { - let Some(here) = tracked() else { return }; - if here.irqs_off.load(Relaxed) == 0 { - unseen("took an exception with interrupts masked and no window open: a mask reached no hook"); - } + on(Windows::found_masked); } /// Interrupts are masked and this CPU is about to open them. pub fn irqs_unmasking() { - let Some(here) = tracked() else { return }; - let since = here.irqs_off.load(Relaxed); - if since == 0 { - unseen("opened interrupts with no window open: a mask reached no hook"); - } - record(&here.irqs_longest, since, cpu::counter()); - here.irqs_off.store(0, Relaxed); + on(|w| w.unmasking(cpu::counter)); } /// The preempt count has just been raised by one. pub fn preempt_raised() { - let Some(here) = tracked() else { return }; - if crate::preempt::count() != 1 { - return; - } - if here.preempt_off.load(Relaxed) != 0 { - unseen("raised the preempt count off zero with a window open: a lowering reached no hook"); - } - here.preempt_off.store(cpu::counter(), Relaxed); + on(|w| w.raised(crate::preempt::count(), cpu::counter)); } /// The preempt count is about to be lowered by one. pub fn preempt_lowering() { - let Some(here) = tracked() else { return }; - if crate::preempt::count() != 1 { - return; - } - let since = here.preempt_off.load(Relaxed); - if since == 0 { - unseen("lowered the preempt count to zero with no window open: a raise reached no hook"); - } - record(&here.preempt_longest, since, cpu::counter()); - here.preempt_off.store(0, Relaxed); + on(|w| w.lowering(crate::preempt::count(), cpu::counter)); } /// The preempt count was just set from `old` to `new` whole. pub fn preempt_set(old: u32, new: u32) { - let Some(here) = tracked() else { return }; - let since = here.preempt_off.load(Relaxed); - match (old, new) { - (0, 0) => {} - (0, _) => { - if since != 0 { - unseen("set the preempt count off zero with a window open: a lowering reached no hook"); - } - here.preempt_off.store(cpu::counter(), Relaxed); - } - (_, 0) => { - if since == 0 { - unseen("set the preempt count to zero with no window open: a raise reached no hook"); - } - record(&here.preempt_longest, since, cpu::counter()); - here.preempt_off.store(0, Relaxed); - } - _ => {} - } + on(|w| w.set(old, new, cpu::counter)); } -/// A scheduler pass has decided what runs here: the window it ran in ends, -/// and the next starts, since the count is still raised. +/// A scheduler pass has decided what runs here. pub fn scheduled() { - let Some(here) = tracked() else { return }; - let since = here.preempt_off.load(Relaxed); - if since == 0 { - unseen("ran a pass with no preemption-off window open: a raise reached no hook"); - } - let now = cpu::counter(); - record(&here.preempt_longest, since, now); - here.preempt_off.store(now, Relaxed); + on(|w| w.scheduled(cpu::counter)); } -/// This CPU halts inside a pass, waiting for whatever runs next. The wait is -/// no window, so the one open ends here and the next opens at [`woken`]; an -/// interrupt taken meanwhile raises the count past one, which acts on nothing. +/// This CPU halts inside a pass. pub fn halting() { - let Some(here) = tracked() else { return }; - let since = here.preempt_off.load(Relaxed); - if since == 0 { - unseen("halted inside a pass with no preemption-off window open: a raise reached no hook"); - } - record(&here.preempt_longest, since, cpu::counter()); - here.preempt_off.store(0, Relaxed); + on(|w| w.halting(cpu::counter)); } -/// The halt [`halting`] began has ended, still inside its pass. +/// The halt has ended, still inside its pass. pub fn woken() { - let Some(here) = tracked() else { return }; - if here.preempt_off.load(Relaxed) != 0 { - unseen("woke from a halt with a preemption-off window open: a raise reached no hook"); - } - here.preempt_off.store(cpu::counter(), Relaxed); + on(|w| w.woken(cpu::counter)); } /// `cpu`'s line, taking its longest windows so the next report starts from none. pub fn log_cpu(cpu: u32) { let Some(of) = CPUS.get(cpu as usize) else { return }; - let irqs = crate::clock::nanos_of_ticks(of.irqs_longest.swap(0, Relaxed)); - let preempt = crate::clock::nanos_of_ticks(of.preempt_longest.swap(0, Relaxed)); - crate::log!("windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}"); + let (irqs, preempt) = of.take(); + crate::log!( + "windows: cpu{cpu} irqs_off_ns={} preempt_off_ns={}", + crate::clock::nanos_of_ticks(irqs), + crate::clock::nanos_of_ticks(preempt), + ); } /// What `windows-staged` spins for: past any window an emulated guest closes diff --git a/toyos-sched/loom/src/lib.rs b/toyos-sched/loom/src/lib.rs index d3b6762d873..82044dd7e76 100644 --- a/toyos-sched/loom/src/lib.rs +++ b/toyos-sched/loom/src/lib.rs @@ -49,5 +49,7 @@ pub mod task; pub mod timer; #[path = "../../src/watch.rs"] pub mod watch; +#[path = "../../src/windows.rs"] +pub mod windows; pub mod model; diff --git a/toyos-sched/src/lib.rs b/toyos-sched/src/lib.rs index 9f5032d2b87..ce70a84c921 100644 --- a/toyos-sched/src/lib.rs +++ b/toyos-sched/src/lib.rs @@ -28,3 +28,4 @@ pub mod sync; pub mod task; pub mod timer; pub mod watch; +pub mod windows; diff --git a/toyos-sched/src/windows.rs b/toyos-sched/src/windows.rs new file mode 100644 index 00000000000..cb273a31890 --- /dev/null +++ b/toyos-sched/src/windows.rs @@ -0,0 +1,351 @@ +//! One CPU's longest interrupts-off and preemption-off windows since its last +//! report: the record the kernel's `mask-windows` build keeps per CPU, feeds +//! at every transition, and prints beside the IRQ census. +//! +//! **An interrupts-off window** runs from the instant a CPU stops taking +//! maskable interrupts to the instant it takes them again: [`Windows::masked`] +//! follows the one and [`Windows::unmasking`] precedes the other. +//! +//! **A preemption-off window** runs while the CPU's preempt count is above +//! zero. A scheduler pass ends it and starts the next ([`Windows::scheduled`]), +//! because a pass is where a waiting thread gets the CPU, and the idle halt +//! inside a pass is no window ([`Windows::halting`], [`Windows::woken`]), +//! because a wake ends it. [`Windows::raised`] follows every raise of the count +//! by one and [`Windows::lowering`] precedes every lowering by one; each acts +//! only on a crossing of zero. +//! +//! **Every transition is checked against the state it finds**, and one that +//! could not have followed it is [`Unseen`]: a transition before it that +//! nothing reported. The record is written by its CPU alone and [`Windows::take`] +//! empties it from any. Nothing here reads a clock: `now` is the caller's +//! counter, read only by a transition that needs it. + +use core::fmt; + +use crate::sync::{AtomicU64, Ordering}; + +/// A CPU that has not joined the scheduler, or that stopped being tracked: +/// every transition is accepted and records nothing. +const UNTRACKED: u64 = u64::MAX; + +/// One CPU's windows. The counter is never zero once firmware has run, so a +/// stamp of zero is no open window. +pub struct Windows { + /// [`UNTRACKED`], 0 while interrupts are open, else the counter at which they were masked. + irqs_off: AtomicU64, + /// 0 while the preempt count is zero or the CPU halts inside a pass, else + /// the counter at which the count left zero or a pass or a wake last ran. + preempt_off: AtomicU64, + irqs_longest: AtomicU64, + preempt_longest: AtomicU64, +} + +/// A transition the record says could not have happened, named by the one +/// before it that nothing reported. +#[derive(Clone, Copy, PartialEq, Eq, Debug)] +pub enum Unseen { + /// Masked, with a window open. + AnUnmask, + /// Unmasking, or interrupted with interrupts masked, with no window open. + AMask, + /// The count left zero, or a halt ended, with a window open. + ALowering, + /// The count returned to zero, a pass ran, or a halt began, with no window open. + ARaise, +} + +impl fmt::Display for Unseen { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.write_str(match self { + Unseen::AnUnmask => "masked interrupts with a window open: an unmask reached no hook", + Unseen::AMask => "found interrupts masked with no window open: a mask reached no hook", + Unseen::ALowering => { + "left a preempt count of zero with a window open: a lowering reached no hook" + } + Unseen::ARaise => { + "ended a preemption-off window that was never opened: a raise reached no hook" + } + }) + } +} + +impl Windows { + /// No `Default` beside it, for `fair::Frontier::new`'s reason: every + /// record is a `static`, which only a `const fn` can build. + #[cfg(not(feature = "loom"))] + #[allow(clippy::new_without_default)] + pub const fn new() -> Self { + Self { + irqs_off: AtomicU64::new(UNTRACKED), + preempt_off: AtomicU64::new(0), + irqs_longest: AtomicU64::new(0), + preempt_longest: AtomicU64::new(0), + } + } + + // Loom's atomics have no const constructor, so this arm alone drops `const`. + #[cfg(feature = "loom")] + #[allow(clippy::new_without_default)] + pub fn new() -> Self { + Self { + irqs_off: AtomicU64::new(UNTRACKED), + preempt_off: AtomicU64::new(0), + irqs_longest: AtomicU64::new(0), + preempt_longest: AtomicU64::new(0), + } + } + + fn tracked(&self) -> bool { + self.irqs_off.load(Ordering::Relaxed) != UNTRACKED + } + + fn record(longest: &AtomicU64, since: u64, now: u64) { + let span = now.saturating_sub(since); + if span > longest.load(Ordering::Relaxed) { + longest.fetch_max(span, Ordering::Relaxed); + } + } + + /// The CPU joins the scheduler with interrupts masked and its preempt + /// count at `count`, and is tracked from here. + pub fn start(&self, count: u32, now: u64) { + self.preempt_off.store(if count == 0 { 0 } else { now }, Ordering::Relaxed); + self.irqs_off.store(now, Ordering::Relaxed); + } + + /// Nothing more is tracked or checked: what a caller does before it + /// reports an [`Unseen`], so its own masking finds nothing to check. + pub fn stop(&self) { + self.irqs_off.store(UNTRACKED, Ordering::Relaxed); + } + + /// Interrupts were open and have just been masked. + pub fn masked(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + match self.irqs_off.load(Ordering::Relaxed) { + UNTRACKED => Ok(()), + 0 => { + self.irqs_off.store(now(), Ordering::Relaxed); + Ok(()) + } + _ => Err(Unseen::AnUnmask), + } + } + + /// The CPU was interrupted with interrupts masked. + pub fn found_masked(&self) -> Result<(), Unseen> { + match self.irqs_off.load(Ordering::Relaxed) { + 0 => Err(Unseen::AMask), + _ => Ok(()), + } + } + + /// Interrupts are masked and about to be opened. + pub fn unmasking(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + match self.irqs_off.load(Ordering::Relaxed) { + UNTRACKED => Ok(()), + 0 => Err(Unseen::AMask), + since => { + Self::record(&self.irqs_longest, since, now()); + self.irqs_off.store(0, Ordering::Relaxed); + Ok(()) + } + } + } + + /// The preempt count has just been raised by one, to `count`. + pub fn raised(&self, count: u32, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if count != 1 || !self.tracked() { + return Ok(()); + } + self.open_preempt(now) + } + + /// The preempt count, at `count`, is about to be lowered by one. + pub fn lowering(&self, count: u32, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if count != 1 || !self.tracked() { + return Ok(()); + } + self.close_preempt(now()) + } + + /// The preempt count has just been set from `old` to `new` whole. + pub fn set(&self, old: u32, new: u32, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if !self.tracked() { + return Ok(()); + } + match (old, new) { + (0, 0) => Ok(()), + (0, _) => self.open_preempt(now), + (_, 0) => self.close_preempt(now()), + _ => Ok(()), + } + } + + /// A scheduler pass has decided what runs here: the window it ran in + /// ends, and the next starts, since the count is still raised. + pub fn scheduled(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if !self.tracked() { + return Ok(()); + } + let now = now(); + self.close_preempt(now)?; + self.preempt_off.store(now, Ordering::Relaxed); + Ok(()) + } + + /// The CPU halts inside a pass, waiting for whatever runs next. + pub fn halting(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if !self.tracked() { + return Ok(()); + } + self.close_preempt(now()) + } + + /// The halt [`Windows::halting`] began has ended, still inside its pass. + pub fn woken(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if !self.tracked() { + return Ok(()); + } + self.open_preempt(now) + } + + fn open_preempt(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if self.preempt_off.load(Ordering::Relaxed) != 0 { + return Err(Unseen::ALowering); + } + self.preempt_off.store(now(), Ordering::Relaxed); + Ok(()) + } + + fn close_preempt(&self, now: u64) -> Result<(), Unseen> { + match self.preempt_off.load(Ordering::Relaxed) { + 0 => Err(Unseen::ARaise), + since => { + Self::record(&self.preempt_longest, since, now); + self.preempt_off.store(0, Ordering::Relaxed); + Ok(()) + } + } + } + + /// The longest interrupts-off and preemption-off windows closed since the + /// last take, in counter ticks; the next take starts from none. + pub fn take(&self) -> (u64, u64) { + ( + self.irqs_longest.swap(0, Ordering::Relaxed), + self.preempt_longest.swap(0, Ordering::Relaxed), + ) + } +} + +#[cfg(test)] +mod tests { + use super::{Unseen, Windows}; + + /// A record tracked from `at` with interrupts open and the count at zero, + /// as a CPU stands once its start's guard has let go. + fn open_at(at: u64) -> Windows { + let w = Windows::new(); + w.start(0, at); + w.unmasking(|| at).unwrap(); + w.take(); + w + } + + #[test] + fn an_interrupts_off_window_is_mask_to_unmask_and_the_longest_is_taken_once() { + let w = open_at(1); + w.masked(|| 10).unwrap(); + w.unmasking(|| 25).unwrap(); + w.masked(|| 30).unwrap(); + w.unmasking(|| 34).unwrap(); + assert_eq!(w.take(), (15, 0)); + assert_eq!(w.take(), (0, 0), "a take starts the next report from none"); + } + + #[test] + fn only_a_crossing_of_zero_opens_or_closes_a_preemption_off_window() { + let w = open_at(1); + w.raised(1, || 10).unwrap(); + w.raised(2, || panic!("a raise past one reads no clock")).unwrap(); + w.lowering(2, || panic!("a lowering to one reads no clock")).unwrap(); + w.lowering(1, || 17).unwrap(); + assert_eq!(w.take(), (0, 7)); + } + + #[test] + fn a_pass_ends_the_preemption_off_window_and_starts_the_next() { + let w = open_at(1); + w.raised(1, || 10).unwrap(); + w.scheduled(|| 20).unwrap(); + w.lowering(1, || 23).unwrap(); + assert_eq!(w.take(), (0, 10), "the window is the pass's, not the whole raise"); + } + + #[test] + fn the_idle_halt_inside_a_pass_is_no_window() { + let w = open_at(1); + w.raised(1, || 10).unwrap(); + w.halting(|| 14).unwrap(); + w.woken(|| 1_000).unwrap(); + w.lowering(1, || 1_003).unwrap(); + assert_eq!(w.take(), (0, 4), "the wait is not counted, either side of it is"); + } + + #[test] + fn a_whole_set_opens_or_closes_only_across_zero() { + let w = open_at(1); + w.set(0, 2, || 10).unwrap(); + w.set(2, 3, || panic!("a set between two raised counts reads no clock")).unwrap(); + w.set(3, 0, || 16).unwrap(); + assert_eq!(w.take(), (0, 6)); + } + + #[test] + fn a_start_counts_from_how_the_cpu_stands() { + let w = Windows::new(); + w.start(1, 5); + w.unmasking(|| 9).unwrap(); + w.lowering(1, || 12).unwrap(); + assert_eq!(w.take(), (4, 7)); + } + + #[test] + fn every_transition_nothing_reported_before_is_named() { + let w = open_at(1); + assert_eq!(w.unmasking(|| 2), Err(Unseen::AMask)); + assert_eq!(w.found_masked(), Err(Unseen::AMask)); + w.masked(|| 3).unwrap(); + w.found_masked().unwrap(); + assert_eq!(w.masked(|| 4), Err(Unseen::AnUnmask)); + + let w = open_at(1); + assert_eq!(w.lowering(1, || 2), Err(Unseen::ARaise)); + assert_eq!(w.scheduled(|| 2), Err(Unseen::ARaise)); + assert_eq!(w.halting(|| 2), Err(Unseen::ARaise)); + assert_eq!(w.set(1, 0, || 2), Err(Unseen::ARaise)); + w.raised(1, || 3).unwrap(); + assert_eq!(w.raised(1, || 4), Err(Unseen::ALowering)); + assert_eq!(w.woken(|| 4), Err(Unseen::ALowering)); + assert_eq!(w.set(0, 1, || 4), Err(Unseen::ALowering)); + } + + #[test] + fn an_untracked_cpu_records_and_refuses_nothing() { + let w = Windows::new(); + w.masked(|| 1).unwrap(); + w.masked(|| 2).unwrap(); + w.unmasking(|| 3).unwrap(); + w.raised(1, || 4).unwrap(); + w.lowering(1, || 5).unwrap(); + w.lowering(1, || 6).unwrap(); + w.scheduled(|| 7).unwrap(); + assert_eq!(w.take(), (0, 0)); + + let w = open_at(1); + w.masked(|| 2).unwrap(); + w.stop(); + w.masked(|| 3).unwrap(); + assert_eq!(w.take(), (0, 0), "a stopped CPU is untracked again"); + } +} From 772bac7daf1f19267bede9c4add869b0b69d8f36 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 00:34:58 +0200 Subject: [PATCH 05/13] A named build carrying the test kernel arms an actuator in the image build too At 66530cf6b both guest arms of the windows' instrument died before a kernel was built. `mask_windows` and `virt_mask_windows` boot `MASK_WINDOWS_KERNEL` (`boot-actuators,mask-windows,test-actuators`) armed with `windows-staged`. `kernel_of` had been widened to let a named build that carries `boot-actuators` arm an actuator. `build_test_parts` still required the exact `TEST_KERNEL` for any parameter outside the kernel's own and the valued ones, so it panicked: "a boot asking for ["windows-staged"] must boot the test kernel, not ["boot-actuators", "mask-windows", "test-actuators"]". Every mutation arm then failed on that same refusal, so none of them measured anything. The two sites now ask one predicate, `build::carries_the_actuators`: the build carries every feature of `TEST_KERNEL`, alone or under an instrument. `kernel_of`'s `boot-actuators` check becomes the same predicate, so it can no longer disagree with the image build. `build_test_parts`' refusal moves into `refuse_an_unarmable_boot` so a host test can ask it directly. The test is `a_named_build_over_the_test_kernel_arms_an_actuator`: the windows' kernel and the test kernel arm `windows-staged`, and the scheduler's check kernel is refused. Negative control: restoring the exact-equality rule at the refusal builds, and the test is red with the guest's own message. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- src/build.rs | 37 +++++++++++++++++++++++++++++++------ tests/common/qemu.rs | 5 +++-- 2 files changed, 34 insertions(+), 8 deletions(-) diff --git a/src/build.rs b/src/build.rs index 3578a161d50..c4fb91736ac 100644 --- a/src/build.rs +++ b/src/build.rs @@ -1369,6 +1369,22 @@ fn declared_kernel_features(root: &Path) -> Vec { /// so. pub const TEST_KERNEL: &[&str] = &["boot-actuators", "test-actuators"]; +/// Whether a kernel built with `features` answers every actuator: it carries +/// [`TEST_KERNEL`], alone or under an instrument built beside it. The harness's +/// choice of kernel and [`build_test_parts`]' refusal both ask this. +pub fn carries_the_actuators>(features: &[S]) -> bool { + TEST_KERNEL.iter().all(|t| features.iter().any(|f| f.as_ref() == *t)) +} + +/// Refuse a boot arming a parameter its kernel cannot answer: one outside the +/// kernel's `own` and the valued ones needs [`carries_the_actuators`]. +fn refuse_an_unarmable_boot(own: &[String], features: &[String], params: &[String]) -> Result<(), String> { + if params.iter().all(|p| own.contains(p) || is_valued_param(p)) || carries_the_actuators(features) { + return Ok(()); + } + Err(format!("a boot asking for {params:?} must boot a kernel carrying {TEST_KERNEL:?}, not {features:?}")) +} + /// Kernel builds the ordinary test suite is allowed to make. pub const TEST_SUITE_KERNEL_BUILDS: [&str; 6] = [ "", @@ -2052,12 +2068,9 @@ pub fn build_test_parts( // parameter picks which actuator the one test kernel arms, so 45 builds // became two; keying the image on it is what keeps two boots asking for // different actuators from sharing one disk. - let own = declared_params(root); - assert!( - kernel_params.iter().all(|p| own.contains(p) || is_valued_param(p)) - || kernel_features.iter().eq(TEST_KERNEL.iter().copied()), - "a boot asking for {kernel_params:?} must boot the test kernel, not {kernel_features:?}" - ); + if let Err(why) = refuse_an_unarmable_boot(&declared_params(root), kernel_features, kernel_params) { + panic!("{why}"); + } let arch = plan.arch; let kernel_key = kernel_key(arch, &features); // The loader and ROOT (whose `/system/bin/update` embeds it) are each a @@ -2532,6 +2545,18 @@ mod tests { } } + /// `mask_windows` arms `windows-staged` on the windows' kernel, which + /// carries every actuator; the scheduler's check kernel carries none. + #[test] + fn a_named_build_over_the_test_kernel_arms_an_actuator() { + let own = declared_params(Path::new(env!("CARGO_MANIFEST_DIR"))); + let owned = |list: &[&str]| list.iter().map(|s| (*s).to_string()).collect::>(); + let staged = owned(&["windows-staged"]); + assert_eq!(refuse_an_unarmable_boot(&own, &owned(MASK_WINDOWS_KERNEL), &staged), Ok(())); + assert_eq!(refuse_an_unarmable_boot(&own, &owned(TEST_KERNEL), &staged), Ok(())); + assert!(refuse_an_unarmable_boot(&own, &owned(SCHED_CHECK_KERNEL), &staged).is_err()); + } + /// **The two lists of valued parameters are one list.** A prefix /// `kernel/src/params.rs`'s `claims` matches and this file does not know is /// a name the pre-flash gate refuses; one this file clears and `claims` does diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 9dcb2c5d263..4f9c5d3be74 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -2635,11 +2635,12 @@ fn kernel_of(options: &BootOptions) -> Vec<&'static str> { return toyos_build::build::TEST_KERNEL.to_vec(); } assert!( - options.kernel_features.contains(&"boot-actuators"), - "a boot asking to arm {:?} asks for the kernel build {:?}, which carries no actuator; \ + toyos_build::build::carries_the_actuators(options.kernel_features), + "a boot asking to arm {:?} asks for the kernel build {:?}, which does not carry {:?}; \ an actuator is a parameter and the test kernel carries all of them", options.kernel_params, options.kernel_features, + toyos_build::build::TEST_KERNEL, ); options.kernel_features.to_vec() } From 737803d48ccc96f822fd662dc3d785d1a7c50b36 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 01:19:35 +0200 Subject: [PATCH 06/13] mask_windows judges no duration: the stage marks its windows, and a report says each closed once MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit At 772bac7da, `virt_mask_windows` was red twice. In both runs the report after the stage carried a preemption-off window longer than the 250 ms spin (271362000 ns and 292094000 ns), and an interrupts-off window shorter than it (65031000 ns and 153183000 ns). The two clocks did not disagree. The spin and the record both read `cpu::counter` (RDTSC on x86-64, CNTVCT_EL0 after an ISB on AArch64) and convert with the one period in `clock`. The cause was where the spin ran. In `virtjobcase` the first process to exit is `preempt`, whose counting thread never enters the kernel. Its main thread's `SYS_EXIT` is not the last out. The killed sibling tears the process down at its exit boundary, and `leave_user_if_due` opens interrupts across that teardown. So the spin ran with preemption off and interrupts open, and the record said exactly that. A QEMU verdict asserts order, completion, content and counts, never how long something took. The guest verdict now reads no duration: - `toyos_sched::windows::Windows::mark` marks the window of each kind open now. A missing open window is refused as `Unseen`. Each mark rides to its window's close, and `take_marked` answers each marked close once. - `windows-staged` marks at the first `SYS_EXIT`, whose entry masked interrupts and raised the preempt count, and it spins no longer. It asserts both from the CPU first, so a stage moved to where a window is shut is refused as that and not as a missed hook. It prints `windows: staged cpuK open`. A later report of cpuK prints `windows: staged cpuK closed irqs_off=… preempt_off=…` for the marked windows that closed since the report before. - `common::irqcensus::windows` holds a stage to this: after the stage, its CPU's reports say each marked window closed exactly once, and no close precedes its stage. The census pairing and the every-CPU-closed-both checks stay. Durations are judged on the T14 alone, which arms no actuator. The record's new mark word costs every close one relaxed load, in the metal build too. The verdicts move above the control-registers doc block they had been inserted into. That block's own misplacement onto `irq_census` is main's, filed as issues/build/the-control-registers-verdicts-doc-comment-sits-on-the-census-verdict.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-doc-comment-sits-on-the-census-verdict.md | 18 +++++ kernel/src/actuator.rs | 5 +- kernel/src/process.rs | 7 -- kernel/src/syscall/proc.rs | 7 ++ kernel/src/windows.rs | 40 ++++----- tests/checks.rs | 57 ++++++------- tests/common/irqcensus.rs | 71 ++++++++++------ tests/common/qemu.rs | 2 +- tests/toyos.rs | 60 +++++++------- toyos-sched/src/windows.rs | 81 ++++++++++++++++++- 10 files changed, 232 insertions(+), 116 deletions(-) create mode 100644 issues/build/the-control-registers-verdicts-doc-comment-sits-on-the-census-verdict.md diff --git a/issues/build/the-control-registers-verdicts-doc-comment-sits-on-the-census-verdict.md b/issues/build/the-control-registers-verdicts-doc-comment-sits-on-the-census-verdict.md new file mode 100644 index 00000000000..6c3765ace81 --- /dev/null +++ b/issues/build/the-control-registers-verdicts-doc-comment-sits-on-the-census-verdict.md @@ -0,0 +1,18 @@ +--- +status: open +kind: tooling +opened: 2026-10-01 +--- + +# The control registers verdict's doc comment sits on the census verdict + +In `tests/toyos.rs`, the doc block that starts "Every CPU's `CR0` and `CR4`, +against what a CPU running this kernel must hold" runs straight into +"The interrupt census adds up, …". Both paragraphs render as the doc of +`irq_census`. `control_regs`, which the first block describes, has no doc +comment. Nothing checks that a doc comment names the item it is attached to, +so rustdoc and a reader both credit the census verdict with the +control-register rules. + +**Exit:** the block sits on `control_regs`, and `irq_census` carries only its +own doc. diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 3cb80765b40..f04b349321f 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -270,9 +270,8 @@ actuators! { /// handler posted it there. handler_post = "handler-post"; - /// Spin a known span inside the first process exit, where both of - /// `mask-windows`' windows are open, and say how long; judged by - /// `mask_windows`. + /// Mark the windows open at the first `SYS_EXIT`, whose entry opened both + /// of `mask-windows`' kinds, and say so; judged by `mask_windows`. windows_staged = "windows-staged"; /// Starve the four xHCI bring-up register waits in `init_one`. diff --git a/kernel/src/process.rs b/kernel/src/process.rs index d3527d7cdd2..c7ebfbdc078 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -958,13 +958,6 @@ fn teardown_resources( data.peak_memory / (1024 * 1024), data.alloc_count, data.free_count); } - #[cfg(feature = "boot-actuators")] - if crate::actuator::windows_staged() { - #[cfg(feature = "mask-windows")] - crate::windows::stage_once(); - #[cfg(not(feature = "mask-windows"))] - panic!("windows-staged: armed on a kernel without `mask-windows`, which has no window to hold to it"); - } // Machine-wide, cumulative counters, printed here (not at shutdown) because process exit is the one recurring moment every boot reaches. crate::irq_census::log_census(); // After the irq lines: the tlb conservation check reads deliveries first, issues second. diff --git a/kernel/src/syscall/proc.rs b/kernel/src/syscall/proc.rs index ec676756172..1441c5ce421 100644 --- a/kernel/src/syscall/proc.rs +++ b/kernel/src/syscall/proc.rs @@ -26,6 +26,13 @@ pub(super) fn sys_thread_exit(code: i32) -> u64 { } pub(super) fn sys_exit(code: i32) -> u64 { + #[cfg(feature = "boot-actuators")] + if crate::actuator::windows_staged() { + #[cfg(feature = "mask-windows")] + crate::windows::stage_once(); + #[cfg(not(feature = "mask-windows"))] + panic!("windows-staged: armed on a kernel without `mask-windows`, which has no window to mark"); + } process::exit(code); } diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index aedf712e8b8..4f8ab662684 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -103,7 +103,9 @@ pub fn woken() { on(|w| w.woken(cpu::counter)); } -/// `cpu`'s line, taking its longest windows so the next report starts from none. +/// `cpu`'s line, taking its longest windows so the next report starts from +/// none, and under `boot-actuators` which of `windows-staged`'s marked windows +/// closed since the report before. pub fn log_cpu(cpu: u32) { let Some(of) = CPUS.get(cpu as usize) else { return }; let (irqs, preempt) = of.take(); @@ -112,17 +114,18 @@ pub fn log_cpu(cpu: u32) { crate::clock::nanos_of_ticks(irqs), crate::clock::nanos_of_ticks(preempt), ); + #[cfg(feature = "boot-actuators")] + { + let (irqs_off, preempt_off) = of.take_marked(); + if irqs_off || preempt_off { + crate::log!("windows: staged cpu{cpu} closed irqs_off={irqs_off} preempt_off={preempt_off}"); + } + } } -/// What `windows-staged` spins for: past any window an emulated guest closes -/// on its own, so a report carrying it carries the spin, and far inside -/// `time::DEAF_CPU`. -#[cfg(feature = "boot-actuators")] -const STAGED_NS: u64 = 250_000_000; - -/// `windows-staged`: at the first process exit, spin for [`STAGED_NS`] inside -/// the exit syscall, where both windows are open, and say how long, so a later -/// report of this CPU must carry both windows at least that long. +/// `windows-staged`: at the first `SYS_EXIT`, whose entry masked interrupts +/// and raised the preempt count, mark this CPU's open windows and say so; a +/// later report of this CPU must say each marked window closed, once. #[cfg(feature = "boot-actuators")] pub fn stage_once() { use core::sync::atomic::AtomicBool; @@ -130,15 +133,12 @@ pub fn stage_once() { if STAGED.swap(true, Relaxed) { return; } - let ticks = crate::clock::counter_ticks(STAGED_NS); - assert!(ticks > 0, "windows-staged: the clock has no period to spin by"); - let from = cpu::counter(); - while cpu::counter().saturating_sub(from) < ticks { - core::hint::spin_loop(); - } - crate::log!( - "windows: staged cpu{} {}ns", - percpu::cpu_id(), - crate::clock::nanos_of_ticks(ticks) + // From the CPU, not the record: a stage moved where either window is shut + // is refused as that, not as a hook the record says it missed. + assert!( + !cpu::interrupts_enabled() && crate::preempt::count() > 0, + "windows-staged: staged with interrupts open or the preempt count at zero, where no window is open" ); + on(Windows::mark); + crate::log!("windows: staged cpu{} open", percpu::cpu_id()); } diff --git a/tests/checks.rs b/tests/checks.rs index 2a3fb34962b..a63f719f3a5 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -346,7 +346,7 @@ mod checks { } /// [`mask_windows`] against captures no guest has to produce: two CPUs, - /// two reports, and a span staged between them. + /// three reports, and a stage on cpu1 whose marked windows close apart. #[test] fn mask_windows_verdict() -> Result<(), String> { let census = |cpu: u32| { @@ -358,13 +358,16 @@ mod checks { let windows = |cpu: u32, irqs: u64, preempt: u64| { format!("[kernel 0.1 cpu0] windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}\n") }; - let staged = "[kernel 0.1 cpu1] windows: staged cpu1 1000000ns\n"; - let good = [ - census(0), windows(0, 5, 7), census(1), windows(1, 3, 4), - staged.to_string(), - census(0), windows(0, 2, 2), census(1), windows(1, 1_000_000, 1_200_000), - ] - .concat(); + let open = |cpu: u32| format!("[kernel 0.1 cpu{cpu}] windows: staged cpu{cpu} open\n"); + let closed = |cpu: u32, irqs: bool, preempt: bool| { + format!("[kernel 0.1 cpu0] windows: staged cpu{cpu} closed irqs_off={irqs} preempt_off={preempt}\n") + }; + let report = |cpu1_closed: &str| { + [census(0), windows(0, 2, 2), census(1), windows(1, 1, 1), cpu1_closed.to_string()].concat() + }; + let first = [census(0), windows(0, 5, 7), census(1), windows(1, 3, 4)].concat(); + let (irqs, preempt) = (closed(1, true, false), closed(1, false, true)); + let good = [first.clone(), open(1), report(&irqs), report(&preempt)].concat(); let refused = |what: &str, capture: &str, says: &str| match mask_windows(capture, 2) { Ok(()) => Err(format!("{what} was accepted")), Err(e) if e.contains(says) => Ok(()), @@ -372,33 +375,31 @@ mod checks { }; mask_windows(&good, 2).map_err(|e| format!("the good capture was refused: {e}"))?; - - refused("no staged span", &good.replace(staged, ""), "said no span")?; - refused( - "a staged span no later report carries", - &good.replace("irqs_off_ns=1000000", "irqs_off_ns=999999"), - "spun 1000000ns", - )?; - refused( - "a staged span carried only by a report before it", - &[ - census(0), windows(0, 5, 7), census(1), windows(1, 1_000_000, 1_200_000), - staged.to_string(), - census(0), windows(0, 2, 2), census(1), windows(1, 3, 4), - ] - .concat(), - "spun 1000000ns", - )?; - refused("a census without its windows", &good.replace(&windows(0, 2, 2), ""), "went out without")?; + let together = [first.clone(), open(1), report(&closed(1, true, true))].concat(); + mask_windows(&together, 2).map_err(|e| format!("both closes in one report were refused: {e}"))?; + + refused("no stage", &good.replace(&open(1), "").replace(&irqs, "").replace(&preempt, ""), "marked nothing")?; + refused("a stage no report says closed", &good.replace(&irqs, "").replace(&preempt, ""), "closed 0 time(s)")?; + refused("only the interrupts-off window closed", &good.replace(&preempt, ""), "preemption-off window 0")?; + refused("a marked window closed twice", &[good.clone(), report(&irqs)].concat(), "closed 2 time(s)")?; + refused("a close before the stage", &[first, report(&irqs), open(1), report(&preempt)].concat(), "no stage before it")?; + refused("a close on a CPU nobody staged", &good.replace(&irqs, &closed(0, true, false)), "cpu0 closed a window no stage")?; + refused("a second stage", &[good.clone(), open(0)].concat(), "a second stage")?; + refused("a staged span in nanoseconds", &good.replace(&open(1), "[kernel 0.1 cpu1] windows: staged cpu1 250000000ns\n"), "unreadable staged line")?; + refused("a census without its windows", &good.replace(&windows(0, 5, 7), ""), "went out without")?; refused( "a CPU that closed no window", &good.replace(&windows(0, 5, 7), &windows(0, 0, 7)).replace(&windows(0, 2, 2), &windows(0, 0, 2)), "closed no window", )?; - refused("one CPU of two", &[census(0), windows(0, 5, 7), staged.replace("cpu1", "cpu0"), census(0), windows(0, 1_000_000, 1_000_000)].concat(), "1 of 2")?; + refused( + "one CPU of two", + &[census(0), windows(0, 5, 7), open(0), census(0), windows(0, 1, 1), closed(0, true, true)].concat(), + "1 of 2", + )?; refused("a field missing", &good.replace(" preempt_off_ns=7", ""), "fields")?; - eprintln!(" [mask_windows] the verdict refuses 7 captures and accepts one"); + eprintln!(" [mask_windows] the verdict refuses 12 captures and accepts two"); Ok(()) } diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index aaac694b745..e52b88d6f02 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -132,38 +132,64 @@ impl Windows { } } -/// The head of the line `windows-staged` says what it spun with, -/// `windows: staged cpuK ns`. +/// The head of `windows-staged`'s lines: `windows: staged cpuK open` where it +/// marks cpuK's open windows, and `windows: staged cpuK closed +/// irqs_off= preempt_off=` in a report of cpuK after a marked +/// window closed. pub const STAGED: &str = "windows: staged cpu"; -fn staged(line: &str) -> Option> { +enum Staged { + Open(u32), + Closed { cpu: u32, irqs_off: bool, preempt_off: bool }, +} + +fn staged(line: &str) -> Option> { let rest = line.split(STAGED).nth(1)?; - let parsed = rest - .trim() - .split_once(' ') - .and_then(|(cpu, ns)| Some((cpu.parse().ok()?, ns.strip_suffix("ns")?.parse().ok()?))) - .ok_or_else(|| format!("unreadable staged span in {rest:?}")); - Some(parsed) + let flag = |field: &str, name: &str| field.strip_prefix(name)?.parse::().ok(); + let parsed = match rest.split_whitespace().collect::>().as_slice() { + [cpu, "open"] => cpu.parse().ok().map(Staged::Open), + [cpu, "closed", irqs, preempt] => (|| { + Some(Staged::Closed { + cpu: cpu.parse().ok()?, + irqs_off: flag(irqs, "irqs_off=")?, + preempt_off: flag(preempt, "preempt_off=")?, + }) + })(), + _ => None, + }; + Some(parsed.ok_or_else(|| format!("unreadable staged line {rest:?}"))) } -/// The judge of every `mask-windows` boot: each census line has its CPU's -/// windows line beside it, each CPU closed both kinds of window at some point -/// of the boot, and a span `windows-staged` spun is carried, in both windows, -/// by a later report of the CPU it spun on. Answers each CPU's longest windows -/// over the whole capture. +/// The judge of every `mask-windows` boot, and it judges no duration: each +/// census line has its CPU's windows line beside it, each CPU closed both +/// kinds of window at some point of the boot, and a stage's CPU says each of +/// its marked windows closed exactly once, in the reports after the stage. +/// Answers each CPU's longest windows over the whole capture. pub fn windows(capture: &str) -> Result, String> { let mut censuses: BTreeMap = BTreeMap::new(); let mut reports: Vec = Vec::new(); - // Where each staged span was said, as a position in `reports`. - let mut spun: Vec<(usize, u32, u64)> = Vec::new(); + // The staged CPU, and how many of its marked windows of each kind closed. + let mut stage: Option<(u32, u32, u32)> = None; for line in capture.lines() { if let Some(census) = Census::parse(line) { *censuses.entry(census.map_err(|why| format!("{why}\nline: {line}"))?.cpu).or_default() += 1; } else if let Some(report) = Windows::parse(line) { reports.push(report.map_err(|why| format!("{why}\nline: {line}"))?); } else if let Some(said) = staged(line) { - let (cpu, ns) = said?; - spun.push((reports.len(), cpu, ns)); + match said.map_err(|why| format!("{why}\nline: {line}"))? { + Staged::Open(cpu) => { + if stage.replace((cpu, 0, 0)).is_some() { + return Err(format!("a second stage, and the kernel stages once a boot\nline: {line}")); + } + } + Staged::Closed { cpu, irqs_off, preempt_off } => match &mut stage { + Some((staged, irqs, preempt)) if *staged == cpu => { + *irqs += u32::from(irqs_off); + *preempt += u32::from(preempt_off); + } + _ => return Err(format!("cpu{cpu} closed a window no stage before it marked\nline: {line}")), + }, + } } } if censuses.is_empty() { @@ -194,12 +220,11 @@ pub fn windows(capture: &str) -> Result, String> { )); } } - for (at, cpu, ns) in spun { - let later: Vec<&Windows> = reports[at..].iter().filter(|r| r.cpu == cpu).collect(); - if !later.iter().any(|r| r.irqs_off_ns >= ns) || !later.iter().any(|r| r.preempt_off_ns >= ns) { + if let Some((cpu, irqs, preempt)) = stage { + if (irqs, preempt) != (1, 1) { return Err(format!( - "cpu{cpu} spun {ns}ns with both windows open, and no later report of it carries \ - both that long: {later:?}" + "cpu{cpu}'s reports after its stage say its marked interrupts-off window closed \ + {irqs} time(s) and its marked preemption-off window {preempt}; each closes once" )); } } diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 4f9c5d3be74..6a0a2e8d3e6 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -190,7 +190,7 @@ pub fn boot_census() -> (u32, u32, Vec) { /// made afresh. [`toyos_build::build::MASK_WINDOWS_KERNEL`] made it: its hooks /// sit on every entry and masking primitive, where a parameter would be a /// branch on the path they measure, and it carries the test kernel's actuators -/// so a staged span can hold it to one. Interactive debug mode is separate: it +/// so a stage can mark its windows. Interactive debug mode is separate: it /// builds [`toyos_build::build::DEBUG_KERNEL_BUILD`] and returns before the suite. pub const DECLARED_KERNEL_BUILDS: [&str; 6] = toyos_build::build::TEST_SUITE_KERNEL_BUILDS; diff --git a/tests/toyos.rs b/tests/toyos.rs index ee57ec581c6..14195ac3fbe 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -523,7 +523,7 @@ const SCREEN_TESTS: &[(&str, Sched, qemu::Profile)] = &[ ("virt_debug_refused", Sched::Parallel, qemu::Profile::VirtEl2), ("virt_readonly_copyout", Sched::Parallel, qemu::Profile::VirtEl2), // `mask_windows`' judge over every AArch64 job: the windows each report - // carries and the staged span, counts and an order; no clock. + // carries and the stage's marked ones, counts and an order; no clock. ("virt_mask_windows", Sched::Parallel, qemu::Profile::VirtEl2), ("virt_smp", Sched::Parallel, qemu::Profile::VirtEl2), ("virt_el1_smp", Sched::Parallel, qemu::Profile::VirtTcg), @@ -584,9 +584,9 @@ const MACHINE_TESTS: &[(&str, Sched)] = &[ // of it. ("irq_census_conservation", Sched::Parallel), // The longest interrupts-off and preemption-off windows, beside the - // census, under one process's 256 threads parked on one ring: a staged - // span is carried by a later report, and every hook's check held. Counts - // and an order of reports; no clock in the verdict. + // census, under one process's 256 threads parked on one ring: each window + // the stage marked closes once in a later report, and every hook's check + // held. Counts and an order of reports; no clock in the verdict. ("mask_windows", Sched::Parallel), ("control_regs", Sched::Parallel), ("control_regs_negative", Sched::Parallel), @@ -3598,8 +3598,8 @@ fn virt_job(profile: qemu::Profile, job: &str, said: &str) -> Result<(), String> } /// `mask_windows` on AArch64: every job of `tests/virtjobcase` run on a -/// `mask-windows` kernel with a span staged in the first exit, judged once the -/// last has ended. +/// `mask-windows` kernel staged at the first `SYS_EXIT`, judged once the last +/// has ended. fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { let config = compile::repo_root().join("tests/virtjobcase/system.toml"); let case = config.parent().expect("system.toml has a directory"); @@ -12132,9 +12132,9 @@ fn run_machine_test( )) } "mask_windows" => { - // Four CPUs, and a first process whose exit the staged span is - // spun inside, so the herd's exit reports it: every hook runs - // under the herd, and a transition none saw panics the guest. + // Four CPUs, and a first process whose `SYS_EXIT` the stage marks, + // so the herd's exit reports the marked windows closed: every hook + // runs under the herd, and a transition none saw panics the guest. let options = BootOptions { smp: 4, kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL, @@ -14223,30 +14223,11 @@ fn parse_xhci_binds(log: &str) -> Vec { .collect() } -/// Every CPU's `CR0` and `CR4`, against what a CPU running this kernel must -/// hold. -/// -/// **Not the same question the kernel's own self-check asks.** That one compares -/// each CPU against the declaration, so it catches a CPU that missed it and -/// nothing else; a declaration that is wrong satisfies it on every core. The -/// bits below are spelled out here, away from the constants that produce them, -/// so the two have to agree independently — and the ones that matter are the -/// ones an AP used to arrive with: `CD`/`NW` set is caching off, `WP` clear is -/// the kernel's own read-only mappings not binding supervisor writes, `NE` -/// clear routes an unmasked x87 exception to a pin nothing listens on. -/// -/// `OSXSAVE` is asserted *clear*: with it set the CPU would permit `XCR0` to -/// name components `FXSAVE64` does not save, and this kernel saves user FP -/// state with `FXSAVE64`. -/// -/// Both halves, because the kernel writes both registers whole: every bit named -/// below must hold its named value, **and a bit named nowhere below may not be -/// set at all**. Silence about a bit is a hole rather than a permission. /// A `windows-staged` boot's windows: `common::irqcensus::windows`'s verdict, -/// with the staged span said and `cpus` CPUs reporting. +/// with a stage made and `cpus` CPUs reporting. fn mask_windows(capture: &str, cpus: u32) -> Result<(), String> { if !capture.contains(common::irqcensus::STAGED) { - return Err(format!("`windows-staged` said no span, so nothing was held to one:\n{capture}")); + return Err(format!("`windows-staged` marked nothing, so no window was held to a stage:\n{capture}")); } let longest = common::irqcensus::windows(capture)?; if longest.len() != cpus as usize { @@ -14301,6 +14282,25 @@ fn windows_on_metal(boot: &metal::Readback) -> Result<(), String> { boot.measured("windows.windowscase.herd_preempt_off_ns", herd_preempt) } +/// Every CPU's `CR0` and `CR4`, against what a CPU running this kernel must +/// hold. +/// +/// **Not the same question the kernel's own self-check asks.** That one compares +/// each CPU against the declaration, so it catches a CPU that missed it and +/// nothing else; a declaration that is wrong satisfies it on every core. The +/// bits below are spelled out here, away from the constants that produce them, +/// so the two have to agree independently — and the ones that matter are the +/// ones an AP used to arrive with: `CD`/`NW` set is caching off, `WP` clear is +/// the kernel's own read-only mappings not binding supervisor writes, `NE` +/// clear routes an unmasked x87 exception to a pin nothing listens on. +/// +/// `OSXSAVE` is asserted *clear*: with it set the CPU would permit `XCR0` to +/// name components `FXSAVE64` does not save, and this kernel saves user FP +/// state with `FXSAVE64`. +/// +/// Both halves, because the kernel writes both registers whole: every bit named +/// below must hold its named value, **and a bit named nowhere below may not be +/// set at all**. Silence about a bit is a hole rather than a permission. /// The interrupt census adds up, is monotonic, and every device delivery is /// still cpu0's. /// diff --git a/toyos-sched/src/windows.rs b/toyos-sched/src/windows.rs index cb273a31890..20a629ea735 100644 --- a/toyos-sched/src/windows.rs +++ b/toyos-sched/src/windows.rs @@ -14,20 +14,31 @@ //! by one and [`Windows::lowering`] precedes every lowering by one; each acts //! only on a crossing of zero. //! +//! **A mark names a window without judging its length**: [`Windows::mark`] +//! marks the window of each kind open now, the mark rides to that window's +//! close, and [`Windows::take_marked`] answers each marked close once. +//! //! **Every transition is checked against the state it finds**, and one that //! could not have followed it is [`Unseen`]: a transition before it that -//! nothing reported. The record is written by its CPU alone and [`Windows::take`] +//! nothing reported. The record is written by its CPU alone and a take //! empties it from any. Nothing here reads a clock: `now` is the caller's //! counter, read only by a transition that needs it. use core::fmt; -use crate::sync::{AtomicU64, Ordering}; +use crate::sync::{AtomicU32, AtomicU64, Ordering}; /// A CPU that has not joined the scheduler, or that stopped being tracked: /// every transition is accepted and records nothing. const UNTRACKED: u64 = u64::MAX; +/// [`Windows::marks`]: the open window of each kind carries a mark, and a +/// marked window of each kind closed since the last [`Windows::take_marked`]. +const IRQS_MARKED: u32 = 1; +const PREEMPT_MARKED: u32 = 2; +const IRQS_MARK_CLOSED: u32 = 4; +const PREEMPT_MARK_CLOSED: u32 = 8; + /// One CPU's windows. The counter is never zero once firmware has run, so a /// stamp of zero is no open window. pub struct Windows { @@ -38,6 +49,8 @@ pub struct Windows { preempt_off: AtomicU64, irqs_longest: AtomicU64, preempt_longest: AtomicU64, + /// Its CPU sets and moves the `*_MARKED` bits; a take clears the `*_MARK_CLOSED` ones. + marks: AtomicU32, } /// A transition the record says could not have happened, named by the one @@ -50,7 +63,8 @@ pub enum Unseen { AMask, /// The count left zero, or a halt ended, with a window open. ALowering, - /// The count returned to zero, a pass ran, or a halt began, with no window open. + /// The count returned to zero, a pass ran, a halt began, or a mark was + /// made, with no window open. ARaise, } @@ -63,7 +77,7 @@ impl fmt::Display for Unseen { "left a preempt count of zero with a window open: a lowering reached no hook" } Unseen::ARaise => { - "ended a preemption-off window that was never opened: a raise reached no hook" + "found the preempt count raised with no window open: a raise reached no hook" } }) } @@ -80,6 +94,7 @@ impl Windows { preempt_off: AtomicU64::new(0), irqs_longest: AtomicU64::new(0), preempt_longest: AtomicU64::new(0), + marks: AtomicU32::new(0), } } @@ -92,6 +107,7 @@ impl Windows { preempt_off: AtomicU64::new(0), irqs_longest: AtomicU64::new(0), preempt_longest: AtomicU64::new(0), + marks: AtomicU32::new(0), } } @@ -147,6 +163,7 @@ impl Windows { since => { Self::record(&self.irqs_longest, since, now()); self.irqs_off.store(0, Ordering::Relaxed); + self.carry(IRQS_MARKED, IRQS_MARK_CLOSED); Ok(()) } } @@ -223,11 +240,35 @@ impl Windows { since => { Self::record(&self.preempt_longest, since, now); self.preempt_off.store(0, Ordering::Relaxed); + self.carry(PREEMPT_MARKED, PREEMPT_MARK_CLOSED); Ok(()) } } } + /// A window of the kind `marked` names has closed: a mark it carried is + /// left for the next [`Windows::take_marked`] as `closed`. + fn carry(&self, marked: u32, closed: u32) { + if self.marks.load(Ordering::Relaxed) & marked != 0 { + self.marks.fetch_or(closed, Ordering::Relaxed); + self.marks.fetch_and(!marked, Ordering::Relaxed); + } + } + + /// Mark the window of each kind open now, where the caller knows both are. + pub fn mark(&self) -> Result<(), Unseen> { + match self.irqs_off.load(Ordering::Relaxed) { + UNTRACKED => return Ok(()), + 0 => return Err(Unseen::AMask), + _ => {} + } + if self.preempt_off.load(Ordering::Relaxed) == 0 { + return Err(Unseen::ARaise); + } + self.marks.fetch_or(IRQS_MARKED | PREEMPT_MARKED, Ordering::Relaxed); + Ok(()) + } + /// The longest interrupts-off and preemption-off windows closed since the /// last take, in counter ticks; the next take starts from none. pub fn take(&self) -> (u64, u64) { @@ -236,6 +277,13 @@ impl Windows { self.preempt_longest.swap(0, Ordering::Relaxed), ) } + + /// Whether a marked interrupts-off and a marked preemption-off window + /// closed since the last such take; the next starts from none. + pub fn take_marked(&self) -> (bool, bool) { + let closed = self.marks.fetch_and(!(IRQS_MARK_CLOSED | PREEMPT_MARK_CLOSED), Ordering::Relaxed); + (closed & IRQS_MARK_CLOSED != 0, closed & PREEMPT_MARK_CLOSED != 0) + } } #[cfg(test)] @@ -328,6 +376,29 @@ mod tests { assert_eq!(w.raised(1, || 4), Err(Unseen::ALowering)); assert_eq!(w.woken(|| 4), Err(Unseen::ALowering)); assert_eq!(w.set(0, 1, || 4), Err(Unseen::ALowering)); + + let w = open_at(1); + assert_eq!(w.mark(), Err(Unseen::AMask)); + w.masked(|| 2).unwrap(); + assert_eq!(w.mark(), Err(Unseen::ARaise)); + } + + #[test] + fn a_mark_rides_to_its_windows_close_and_is_answered_once() { + let w = open_at(1); + w.masked(|| 10).unwrap(); + w.raised(1, || 11).unwrap(); + w.mark().unwrap(); + assert_eq!(w.take_marked(), (false, false), "no marked window has closed yet"); + w.unmasking(|| 20).unwrap(); + assert_eq!(w.take_marked(), (true, false)); + w.scheduled(|| 25).unwrap(); + assert_eq!(w.take_marked(), (false, true), "a pass closes the marked window"); + assert_eq!(w.take_marked(), (false, false), "a take starts the next from none"); + w.lowering(1, || 30).unwrap(); + w.masked(|| 40).unwrap(); + w.unmasking(|| 50).unwrap(); + assert_eq!(w.take_marked(), (false, false), "the windows after the marked ones carry no mark"); } #[test] @@ -340,7 +411,9 @@ mod tests { w.lowering(1, || 5).unwrap(); w.lowering(1, || 6).unwrap(); w.scheduled(|| 7).unwrap(); + w.mark().unwrap(); assert_eq!(w.take(), (0, 0)); + assert_eq!(w.take_marked(), (false, false)); let w = open_at(1); w.masked(|| 2).unwrap(); From 72f16e39a474340b788151ce732e9918a42795b1 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 2 Oct 2026 19:16:16 +0200 Subject: [PATCH 07/13] The windows' baseline is step 1 reverted on the instrumented tree Stage 6 step 2's exit compared the two windows at stage 6's first commit (53b1ef7d3, the instrument applied as a patch) with those at step 1's head. Both arms are behind main by the whole guest-suite cut and its neighbours: their toolchain is in no store, a build at either starts with an LLVM and compiler rebuild, and their `keystore::sweep` panics on today's stores and could sweep stores other worktrees use. The comparison is taken instead as root CLAUDE.md gives a negative control: on one tree, today's with the instrument, with step 1 (#634) as it stands and with it reverted. That reads what the exit is for, whether step 1 lengthened either window, with today's toolchain. The track's step 2 and the stage's rule for steps 2 to 5 say so, and the exit of the issue step 2 holds moves with them. The kernel's lines are still counted against stage 6's first commit. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...ff-walk-by-the-threads-it-parks-on-one-ring.md | 4 ++-- ...l-is-small-interrupts-post-and-threads-wait.md | 15 ++++++++------- 2 files changed, 10 insertions(+), 9 deletions(-) diff --git a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md index b38d2a9496f..b959cebf82b 100644 --- a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md +++ b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md @@ -37,5 +37,5 @@ measured: no instrument in the tree reads an interrupts-off window. **Exit**: step 2's interrupts-off window, read on the T14 while one process parks 256 threads in `submit` on one ring and a sibling thread completes into -it, is no longer at step 1's head than at stage 6's first commit under the -same load. +it, is no longer with step 1 than with it reverted on the same tree, under +the same load. diff --git a/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md b/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md index 065269837c1..efc11f04399 100644 --- a/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md +++ b/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md @@ -148,8 +148,9 @@ times: device's `Watch` and ends its interrupt; the thread waiting on that watch does the work, and no step creates a kernel thread. `irq_ring`, the driver list in `drain_irqs` and the idle loop's device checks are gone by step 5. - Each step measures the kernel's lines, and from step 2 the longest - interrupts-off and preemption-off windows, against stage 6's first commit. + Each step measures the kernel's lines against stage 6's first commit, and + from step 2 the longest interrupts-off and preemption-off windows against + the readings step 2 records. Steps 3 and 4 do not land alone: they land with #592's i8042 stage and with usbd. 1. **Interrupts post.** A post is legal in a handler: the watches a handler @@ -167,10 +168,10 @@ times: 2. **The windows, measured**: the longest interrupts-off and preemption-off windows per CPU, reported beside the IRQ census and fed by each architecture's masking primitives and entries, the number the ARM - track's stage 4 owes as well. Applied to stage 6's first commit for - the baseline. **Exit**: both windows read on the T14, which is x86 - metal, at stage 6's start and at step 1's head, and neither is longer - at step 1's head than at the start, under the load + track's stage 4 owes as well. The baseline is step 1 reverted on the + tree that carries the instrument. **Exit**: both windows read on the + T14, which is x86 metal, on that tree with step 1 and with it reverted, + and neither is longer with step 1 than without it, under the load `issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md` names as well. 3. **The i8042's thread is ps2server's** (#592's i8042 stage): `irq_ring`'s @@ -185,7 +186,7 @@ times: report on the panel and holding it there, a device the pass reaches (owner, 2026-09-30). **Exit**: `drain_irqs` and the idle loop's device checks are gone, both windows are measured against - stage 6's start, and the exits of + the readings step 2 records, and the exits of `issues/kernel/an-irq-watchs-freeing-cancel-compiles-in-a-handler.md` and `issues/kernel/nothing-fails-when-a-devices-release-or-close-stops-answering-its-polls.md` From d7bc80aca41a00e9147705f5d73f8cf38e55ac09 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 2 Oct 2026 20:36:59 +0200 Subject: [PATCH 08/13] The windows' instrument proves itself on the machine: a held window read back, the load's own report, and no stage Answers the review of #649 at 72f16e39a (comment 5958368996). The stage that tested the stage goes (BLOCKER 5). `Windows::mark`, `take_marked`, `carry` and the mark word shared no state with `record`, `take` or the report's conversion, so a mutation of the mark mutated nothing of the instrument. With it go the `windows-staged` actuator, its arm in `SYS_EXIT`, `carries_the_actuators`, `refuse_an_unarmable_boot` and its host test, both clippy shapes of the three-feature build, the harness's widened `kernel_of`, and the staged half of the judge. `build::MASK_WINDOWS_KERNEL` is now `mask-windows` alone, declared once and read by the suite's build list, the QEMU test and the metal arm (NOTE 3). The known-span control is written fresh and not converted from the stage. Converting kept the actuator, and an actuator on the T14 needs the three-feature kernel: a second metal boot, the build predicate, its test and the clippy shapes all stay. Fresh, it is `windows::hold_once`: the boot's first `SYS_EXIT` on a `mask-windows` kernel masks interrupts, raises the preempt count, spins `toyos_sched::windows::HELD_NS` (50 ms) by `cpu::counter` and prints `windows: held cpuK ns=` from the same two counter reads. No parameter arms it and no harness code knows about it; the windows it holds reach a report through `record`, `take` and `nanos_of_ticks` like every other. The T14 row reads its durations through one pure function, `irqcensus::windows_under` (BLOCKER 2, BLOCKER 3, NOTE 2): - The load's reading is the report its exit printed and the next one, which carries the teardown the first cannot. It is refused unless a report before them emptied every CPU's record. At 72f16e39a the row ran one job, so the herd's report was the boot's only one and carried every window since each CPU joined. - The holding CPU's reports between its hold and the load's start read back a window of each kind no shorter than the span the held line states, and that span is no shorter than `HELD_NS`. The row's jobs are `idle_span`, `pwd`, the herd and `echo`. `idle_span` is new: half a second asleep, and its exit is the boot's first, so the CPU that holds has just come out of a halt the record must not have counted. The rows recorded are the held pair and the herd's pair; the boot's longest goes, since the hold would be it. `mask_windows_verdict` holds both judges to captures: the four-report shape read to its numbers, and eleven refusals of `windows_under`. The arm that read an exception frame's `IF` goes (BLOCKER 4). Every Ring 0 exception ends the machine, so `trap_dispatch`'s hook stops that CPU's record on a Ring 0 frame, as `refuse` does, and a dying kernel's fault is never displaced by a refusal. `Windows::found_masked` goes with it. The device stubs' leaving hook reads the ring through `toyos_userbound::Ring`, which the module says is the only reader of the RPL bits. `virt_mask_windows` boots `tests/virtsmpcase` on eight CPUs. `tests/virtjobcase` runs `debug_refused`, which needs `SYS_DEBUG`, and the instrument's kernel no longer carries the actuators. `log_cpu` indexes its CPU's record (BLOCKER 7): `cpu` is below `cpu_count()`, which is at most `MAX_CPUS`. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- kernel/src/actuator.rs | 4 - kernel/src/arch/x86_64/idt/device_irq.rs | 2 +- kernel/src/arch/x86_64/idt/mod.rs | 28 ++-- kernel/src/syscall/proc.rs | 9 +- kernel/src/windows.rs | 82 ++++++----- src/build.rs | 45 ++---- src/clippy.rs | 14 -- tests/checks.rs | 89 +++++++----- tests/common/irqcensus.rs | 151 +++++++++++++------- tests/common/qemu.rs | 19 +-- tests/toyos-rust-tests/src/bin/idle_span.rs | 16 +++ tests/toyos.rs | 129 ++++++++--------- toyos-sched/src/windows.rs | 92 +----------- 13 files changed, 304 insertions(+), 376 deletions(-) create mode 100644 tests/toyos-rust-tests/src/bin/idle_span.rs diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 430d0ec68ad..ea0305d1cd3 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -70,10 +70,6 @@ actuators! { /// `usb_reset_records_the_phase_it_cut`. usb_reset_under_load = "usb-reset-under-load"; - /// Mark the windows open at the first `SYS_EXIT`, whose entry opened both - /// of `mask-windows`' kinds, and say so; judged by `virt_mask_windows`. - windows_staged = "windows-staged"; - /// Make one CPU ignore a kick. dump_deaf_cpu = "dump-deaf-cpu"; diff --git a/kernel/src/arch/x86_64/idt/device_irq.rs b/kernel/src/arch/x86_64/idt/device_irq.rs index d3b355e102c..4b7db10bd7e 100644 --- a/kernel/src/arch/x86_64/idt/device_irq.rs +++ b/kernel/src/arch/x86_64/idt/device_irq.rs @@ -83,7 +83,7 @@ pub(super) extern "sysv64" fn windows_entered() { #[cfg(feature = "mask-windows")] pub(super) extern "sysv64" fn windows_leaving(cs: u64) { crate::windows::preempt_lowering(); - if cs & 3 == 0 { + if !toyos_userbound::Ring::of_cs(cs).is_user() { crate::windows::irqs_unmasking(); } } diff --git a/kernel/src/arch/x86_64/idt/mod.rs b/kernel/src/arch/x86_64/idt/mod.rs index 8f4973b9aba..c7f63b30495 100644 --- a/kernel/src/arch/x86_64/idt/mod.rs +++ b/kernel/src/arch/x86_64/idt/mod.rs @@ -367,8 +367,10 @@ extern "sysv64" fn trap_dispatch(frame: *mut TrapFrame) { cpu::enable_interrupts(); exceptions::page_fault_handler(frame); cpu::disable_interrupts(); + // Only a Ring 3 fault comes back: `common_entry` lowers the count + // next, and `exit_to_user` opens interrupts. #[cfg(feature = "mask-windows")] - windows_leaving(frame); + crate::windows::preempt_lowering(); } _ => { #[cfg(feature = "mask-windows")] @@ -378,29 +380,19 @@ extern "sysv64" fn trap_dispatch(frame: *mut TrapFrame) { } } -/// The gate masked interrupts if the frame says they were open, and a window -/// is already open if it says they were not; `common_entry` raised the preempt -/// count by one. +/// A Ring 3 frame had interrupts open, the gate masked them, and +/// `common_entry` raised the preempt count by one. A Ring 0 frame ends the +/// machine: its CPU's record stops first, so no hook from here on refuses in +/// place of the fault's report. #[cfg(feature = "mask-windows")] fn windows_entered(frame: &TrapFrame) { - if frame_interrupts_enabled(frame.rflags) { - crate::windows::irqs_masked(); - } else { - crate::windows::irqs_found_masked(); + if !toyos_userbound::Ring::of_cs(frame.cs).is_user() { + crate::windows::stop_here(); } + crate::windows::irqs_masked(); crate::windows::preempt_raised(); } -/// `common_entry` lowers the count next; its `iretq` opens interrupts on a -/// return to Ring 0 that had them, and `exit_to_user` on one to Ring 3. -#[cfg(feature = "mask-windows")] -fn windows_leaving(frame: &TrapFrame) { - crate::windows::preempt_lowering(); - if frame.cs & 3 == 0 && frame_interrupts_enabled(frame.rflags) { - crate::windows::irqs_unmasking(); - } -} - /// This CPU's state as the black box records it, read out of the frame the stub /// pushed and the three control registers the frame does not carry. /// diff --git a/kernel/src/syscall/proc.rs b/kernel/src/syscall/proc.rs index 61d1f08a0d9..01892d35ae2 100644 --- a/kernel/src/syscall/proc.rs +++ b/kernel/src/syscall/proc.rs @@ -26,13 +26,8 @@ pub(super) fn sys_thread_exit(code: i32) -> u64 { } pub(super) fn sys_exit(code: i32) -> u64 { - #[cfg(feature = "boot-actuators")] - if crate::actuator::windows_staged() { - #[cfg(feature = "mask-windows")] - crate::windows::stage_once(); - #[cfg(not(feature = "mask-windows"))] - panic!("windows-staged: armed on a kernel without `mask-windows`, which has no window to mark"); - } + #[cfg(feature = "mask-windows")] + crate::windows::hold_once(); process::exit(code); } diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index 4f8ab662684..49c5ca5ad67 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -7,25 +7,29 @@ //! masking primitives, the halt, every entry (a gate, `SYSCALL` or an //! exception masks) and every return (`scheduler::exit_to_user`'s end for a //! return to user mode, the entry's own hook for a return to the kernel). -//! Every entry is also held to what the hardware says it interrupted: a -//! maskable interrupt is delivered only with interrupts open, and an -//! exception's frame carries the flag. A context switch changes nothing: this -//! build switches inside an `IrqGuard`, so every saved context holds -//! interrupts masked. An NMI is not a window: nothing masks it, and it runs no -//! hook. [`preempt_raised`] and [`preempt_lowering`] follow the preempt count's -//! accessors and the entries that move it inline. +//! Every maskable interrupt is also held to what the hardware says it +//! interrupted: one is delivered only with interrupts open. A context switch +//! changes nothing: this build switches inside an `IrqGuard`, so every saved +//! context holds interrupts masked. An NMI is not a window: nothing masks it, +//! and it runs no hook. [`preempt_raised`] and [`preempt_lowering`] follow the +//! preempt count's accessors and the entries that move it inline. //! //! The hooks that change `IF` run with interrupts masked; a preempt hook may //! run with them open, since an interrupt cannot move the count across zero //! between it and the count it follows or precedes. A transition the record //! refuses panics, after the CPU stops being tracked so the panic's own -//! masking finds nothing to check. A CPU is tracked from [`start_here`], where -//! it joins the scheduler, and a window is reported by the report after it -//! closes. +//! masking finds nothing to check; an exception the kernel itself took stops +//! it too ([`stop_here`]), so the fault's report is the one that is read. A CPU +//! is tracked from [`start_here`], where it joins the scheduler, and a window +//! is reported by the report after it closes. +//! +//! Once a boot, [`hold_once`] holds both windows for a span it reads off the +//! counter and prints, which a later report of that CPU reads back. +use core::sync::atomic::AtomicBool; use core::sync::atomic::Ordering::Relaxed; -use toyos_sched::windows::{Unseen, Windows}; +use toyos_sched::windows::{Unseen, Windows, HELD_NS}; use crate::arch::{cpu, percpu}; use crate::sched::MAX_CPUS; @@ -63,9 +67,13 @@ pub fn irqs_masked() { on(|w| w.masked(cpu::counter)); } -/// An exception's frame says it interrupted this CPU with interrupts masked. -pub fn irqs_found_masked() { - on(Windows::found_masked); +/// This CPU took an exception in the kernel, which ends the machine: nothing +/// more of it is tracked or checked. +pub fn stop_here() { + on(|w| { + w.stop(); + Ok(()) + }); } /// Interrupts are masked and this CPU is about to open them. @@ -103,42 +111,32 @@ pub fn woken() { on(|w| w.woken(cpu::counter)); } -/// `cpu`'s line, taking its longest windows so the next report starts from -/// none, and under `boot-actuators` which of `windows-staged`'s marked windows -/// closed since the report before. +/// `cpu`'s line, taking its longest windows so the next report starts from none. pub fn log_cpu(cpu: u32) { - let Some(of) = CPUS.get(cpu as usize) else { return }; - let (irqs, preempt) = of.take(); + let (irqs, preempt) = CPUS[cpu as usize].take(); crate::log!( "windows: cpu{cpu} irqs_off_ns={} preempt_off_ns={}", crate::clock::nanos_of_ticks(irqs), crate::clock::nanos_of_ticks(preempt), ); - #[cfg(feature = "boot-actuators")] - { - let (irqs_off, preempt_off) = of.take_marked(); - if irqs_off || preempt_off { - crate::log!("windows: staged cpu{cpu} closed irqs_off={irqs_off} preempt_off={preempt_off}"); - } - } } -/// `windows-staged`: at the first `SYS_EXIT`, whose entry masked interrupts -/// and raised the preempt count, mark this CPU's open windows and say so; a -/// later report of this CPU must say each marked window closed, once. -#[cfg(feature = "boot-actuators")] -pub fn stage_once() { - use core::sync::atomic::AtomicBool; - static STAGED: AtomicBool = AtomicBool::new(false); - if STAGED.swap(true, Relaxed) { +/// The boot's first `SYS_EXIT` holds both windows for [`HELD_NS`] by this +/// CPU's counter and says how long that was: `windows: held cpuN ns=…`. +pub fn hold_once() { + static HELD: AtomicBool = AtomicBool::new(false); + if HELD.swap(true, Relaxed) { return; } - // From the CPU, not the record: a stage moved where either window is shut - // is refused as that, not as a hook the record says it missed. - assert!( - !cpu::interrupts_enabled() && crate::preempt::count() > 0, - "windows-staged: staged with interrupts open or the preempt count at zero, where no window is open" - ); - on(Windows::mark); - crate::log!("windows: staged cpu{} open", percpu::cpu_id()); + let _masked = crate::arch::IrqGuard::close(); + crate::preempt::disable(); + let from = cpu::counter(); + let owed = crate::clock::counter_ticks(HELD_NS); + let mut held = 0; + while held < owed { + core::hint::spin_loop(); + held = cpu::counter() - from; + } + crate::log!("windows: held cpu{} ns={}", percpu::cpu_id(), crate::clock::nanos_of_ticks(held)); + crate::preempt::enable(); } diff --git a/src/build.rs b/src/build.rs index 1380ca2281b..daf0f1fbf04 100644 --- a/src/build.rs +++ b/src/build.rs @@ -1329,29 +1329,13 @@ fn declared_kernel_features(root: &Path) -> Vec { /// so. pub const TEST_KERNEL: &[&str] = &["boot-actuators", "test-actuators"]; -/// Whether a kernel built with `features` answers every actuator: it carries -/// [`TEST_KERNEL`], alone or under an instrument built beside it. The harness's -/// choice of kernel and [`build_test_parts`]' refusal both ask this. -pub fn carries_the_actuators>(features: &[S]) -> bool { - TEST_KERNEL.iter().all(|t| features.iter().any(|f| f.as_ref() == *t)) -} - -/// Refuse a boot arming a parameter its kernel cannot answer: one outside the -/// kernel's `own` and the valued ones needs [`carries_the_actuators`]. -fn refuse_an_unarmable_boot(own: &[String], features: &[String], params: &[String]) -> Result<(), String> { - if params.iter().all(|p| own.contains(p) || is_valued_param(p)) || carries_the_actuators(features) { - return Ok(()); - } - Err(format!("a boot asking for {params:?} must boot a kernel carrying {TEST_KERNEL:?}, not {features:?}")) -} - /// Kernel builds the ordinary test suite is allowed to make. pub const TEST_SUITE_KERNEL_BUILDS: [&str; 3] = - ["", "boot-actuators,test-actuators", "boot-actuators,mask-windows,test-actuators"]; + ["", "boot-actuators,test-actuators", MASK_WINDOWS_KERNEL[0]]; -/// The windows' instrument over the test kernel, for [`SCHED_CHECK_KERNEL`]'s -/// reason: one spelling, so one build. -pub const MASK_WINDOWS_KERNEL: &[&str] = &["boot-actuators", "mask-windows", "test-actuators"]; +/// The shipping kernel with the windows' instrument and nothing else, for +/// [`SCHED_CHECK_KERNEL`]'s reason: one spelling, so one build. +pub const MASK_WINDOWS_KERNEL: &[&str] = &["mask-windows"]; /// The scheduler core's own asserts, compiled in: `toyos-sched/check`. /// @@ -1918,9 +1902,12 @@ pub fn build_test_parts( // parameter picks which actuator the one test kernel arms, so 45 builds // became two; keying the image on it is what keeps two boots asking for // different actuators from sharing one disk. - if let Err(why) = refuse_an_unarmable_boot(&declared_params(root), kernel_features, kernel_params) { - panic!("{why}"); - } + let own = declared_params(root); + assert!( + kernel_params.iter().all(|p| own.contains(p) || is_valued_param(p)) + || kernel_features.iter().eq(TEST_KERNEL.iter().copied()), + "a boot asking for {kernel_params:?} must boot the test kernel, not {kernel_features:?}" + ); let arch = plan.arch; let kernel_key = kernel_key(arch, &features); // The loader and ROOT (whose `/system/bin/update` embeds it) are each a @@ -2472,18 +2459,6 @@ mod tests { } } - /// `virt_mask_windows` arms `windows-staged` on the windows' kernel, which - /// carries every actuator; the scheduler's check kernel carries none. - #[test] - fn a_named_build_over_the_test_kernel_arms_an_actuator() { - let own = declared_params(Path::new(env!("CARGO_MANIFEST_DIR"))); - let owned = |list: &[&str]| list.iter().map(|s| (*s).to_string()).collect::>(); - let staged = owned(&["windows-staged"]); - assert_eq!(refuse_an_unarmable_boot(&own, &owned(MASK_WINDOWS_KERNEL), &staged), Ok(())); - assert_eq!(refuse_an_unarmable_boot(&own, &owned(TEST_KERNEL), &staged), Ok(())); - assert!(refuse_an_unarmable_boot(&own, &owned(SCHED_CHECK_KERNEL), &staged).is_err()); - } - /// **The two lists of valued parameters are one list.** A prefix /// `kernel/src/params.rs`'s `claims` matches and this file does not know is /// a name the pre-flash gate refuses; one this file clears and `claims` does diff --git a/src/clippy.rs b/src/clippy.rs index 6f26adf41cc..a158825af6f 100644 --- a/src/clippy.rs +++ b/src/clippy.rs @@ -47,10 +47,6 @@ const AARCH64_INSTRUMENTS: &str = "debug-wait,sched-check,sched-tripwire,heap-tr switch-witness-mutate-frame,switch-witness-mutate-rsp,\ mask-windows"; -/// `build::MASK_WINDOWS_KERNEL`, the one build whose arms need both the -/// windows and the actuators. -const MASK_WINDOWS_KERNEL: &str = "boot-actuators,mask-windows,test-actuators"; - const UNCONTROLLED: &[&str] = &["toyos-pcid/counting-allocator", "toyos-sched/tripwire"]; /// Every model's negative control and [`UNCONTROLLED`], as one `--features` list. @@ -100,11 +96,6 @@ const SHAPES: &[Shape] = &[ before: &["--target", Arch::X86_64.kernel(), "--features", INSTRUMENTS], after: &["$ADOPTED", "-D", "warnings"], }, - Shape { - dir: "kernel", - before: &["--target", Arch::X86_64.kernel(), "--features", MASK_WINDOWS_KERNEL], - after: &["$ADOPTED", "-D", "warnings"], - }, Shape { dir: "kernel", before: &["--target", Arch::X86_64.kernel(), "--features", "heap-band-notail,heap-lockspin"], @@ -135,11 +126,6 @@ const SHAPES: &[Shape] = &[ before: &["--target", Arch::Aarch64.kernel(), "--features", AARCH64_INSTRUMENTS], after: &["$ADOPTED", "-D", "warnings"], }, - Shape { - dir: "kernel", - before: &["--target", Arch::Aarch64.kernel(), "--features", MASK_WINDOWS_KERNEL], - after: &["$ADOPTED", "-D", "warnings"], - }, Shape { dir: "bootloader", before: &["--target", Arch::X86_64.loader()], diff --git a/tests/checks.rs b/tests/checks.rs index 1fd8948c0d8..83a5a2007f1 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -396,61 +396,78 @@ mod checks { Ok(()) } - /// [`mask_windows`] against captures no guest has to produce: two CPUs, - /// three reports, and a stage on cpu1 whose marked windows close apart. + /// [`mask_windows`] and `irqcensus::windows_under` against captures no + /// boot has to produce: two CPUs and the T14 row's four exits, a report + /// each, with cpu1 holding at the first. #[test] fn mask_windows_verdict() -> Result<(), String> { + use common::irqcensus::{windows_under, Measured}; let census = |cpu: u32| { format!( "[kernel 0.1 cpu0] irq: cpu{cpu} total=0 timer=0 xhci=0 userdev=0 sound=0 i8042=0 \ dmafault=0 hda=0 tlb=0 nmi=0 spurious=0 unclaimed=0\n" ) }; - let windows = |cpu: u32, irqs: u64, preempt: u64| { + let windows = |cpu: u32, (irqs, preempt): (u64, u64)| { format!("[kernel 0.1 cpu0] windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}\n") }; - let open = |cpu: u32| format!("[kernel 0.1 cpu{cpu}] windows: staged cpu{cpu} open\n"); - let closed = |cpu: u32, irqs: bool, preempt: bool| { - format!("[kernel 0.1 cpu0] windows: staged cpu{cpu} closed irqs_off={irqs} preempt_off={preempt}\n") - }; - let report = |cpu1_closed: &str| { - [census(0), windows(0, 2, 2), census(1), windows(1, 1, 1), cpu1_closed.to_string()].concat() - }; - let first = [census(0), windows(0, 5, 7), census(1), windows(1, 3, 4)].concat(); - let (irqs, preempt) = (closed(1, true, false), closed(1, false, true)); - let good = [first.clone(), open(1), report(&irqs), report(&preempt)].concat(); - let refused = |what: &str, capture: &str, says: &str| match mask_windows(capture, 2) { + let report = |cpu0: (u64, u64), cpu1: (u64, u64)| [census(0), windows(0, cpu0), census(1), windows(1, cpu1)].concat(); + let exit = |name: &str| format!("[kernel 0.1 cpu0] exit: {name} pid=9 code=0 cpu=1ms\n"); + let held_ns = toyos_sched::windows::HELD_NS; + let hold = format!("[kernel 0.1 cpu1] windows: held cpu1 ns={}\n", held_ns + 7); + // Since each CPU joined: longer on cpu0 than anything under the load. + let first = [report((6_500_000, 6_400_000), (900, 800)), exit("test_rs_idle_span")].concat(); + let read_back = (held_ns + 400, held_ns + 300); + let opening = [report((100, 100), read_back), exit("pwd")].concat(); + let own = [report((3_000_000, 1_100_000), (700_000, 600_000)), exit(WINDOWS_LOAD)].concat(); + let after = [report((300, 200), (2_000_000, 1_900_000)), exit("echo")].concat(); + let good = [hold.as_str(), &first, &opening, &own, &after].concat(); + let exited = windows_load_exited(); + + mask_windows(&good, 2).map_err(|e| format!("the good capture was refused: {e}"))?; + let unpaired = |what: &str, capture: &str, says: &str| match mask_windows(capture, 2) { Ok(()) => Err(format!("{what} was accepted")), Err(e) if e.contains(says) => Ok(()), Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")), }; + unpaired("a census without its windows", &good.replace(&windows(0, (100, 100)), ""), "went out without")?; + unpaired("a CPU that closed no window", &report((0, 7), (3, 4)), "closed no window")?; + unpaired("one CPU of two", &[census(0), windows(0, (5, 7))].concat(), "1 of 2")?; + unpaired("a field missing", &good.replace(" preempt_off_ns=100", ""), "fields")?; - mask_windows(&good, 2).map_err(|e| format!("the good capture was refused: {e}"))?; - let together = [first.clone(), open(1), report(&closed(1, true, true))].concat(); - mask_windows(&together, 2).map_err(|e| format!("both closes in one report were refused: {e}"))?; - - refused("no stage", &good.replace(&open(1), "").replace(&irqs, "").replace(&preempt, ""), "marked nothing")?; - refused("a stage no report says closed", &good.replace(&irqs, "").replace(&preempt, ""), "closed 0 time(s)")?; - refused("only the interrupts-off window closed", &good.replace(&preempt, ""), "preemption-off window 0")?; - refused("a marked window closed twice", &[good.clone(), report(&irqs)].concat(), "closed 2 time(s)")?; - refused("a close before the stage", &[first, report(&irqs), open(1), report(&preempt)].concat(), "no stage before it")?; - refused("a close on a CPU nobody staged", &good.replace(&irqs, &closed(0, true, false)), "cpu0 closed a window no stage")?; - refused("a second stage", &[good.clone(), open(0)].concat(), "a second stage")?; - refused("a staged span in nanoseconds", &good.replace(&open(1), "[kernel 0.1 cpu1] windows: staged cpu1 250000000ns\n"), "unreadable staged line")?; - refused("a census without its windows", &good.replace(&windows(0, 5, 7), ""), "went out without")?; + let read = windows_under(&good, 2, &exited)?; + let want = Measured { held: read_back, load: (3_000_000, 1_900_000) }; + if read != want { + return Err(format!("the good capture read {read:?}, and the hold's and the load's reports say {want:?}")); + } + let refused = |what: &str, capture: &str, says: &str| match windows_under(capture, 2, &exited) { + Ok(read) => Err(format!("{what} was read as {read:?}")), + Err(e) if e.contains(says) => Ok(()), + Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")), + }; + refused("the load's report alone", &own, "the boot's first")?; + refused("a load's report with none before it", &[hold.as_str(), &own, &after].concat(), "the boot's first")?; + refused("no report after the load's exit", &good.replace(&after, ""), "no report after")?; + refused("a load that never ended", &good.replace(&exit(WINDOWS_LOAD), ""), "never ended")?; + refused("no hold", &good.replace(&hold, ""), "held no window of known length")?; + refused("a second hold", &[hold.as_str(), &good].concat(), "a second hold")?; + refused("a hold cut short", &good.replace(&hold, "[kernel 0.1 cpu1] windows: held cpu1 ns=1000\n"), "the kernel owes")?; refused( - "a CPU that closed no window", - &good.replace(&windows(0, 5, 7), &windows(0, 0, 7)).replace(&windows(0, 2, 2), &windows(0, 0, 2)), - "closed no window", + "an interrupts-off window read back at half", + &good.replace(&windows(1, read_back), &windows(1, (read_back.0 / 2, read_back.1))), + "shorter than it was held", )?; refused( - "one CPU of two", - &[census(0), windows(0, 5, 7), open(0), census(0), windows(0, 1, 1), closed(0, true, true)].concat(), - "1 of 2", + "a preemption-off window read back at half", + &good.replace(&windows(1, read_back), &windows(1, (read_back.0, read_back.1 / 2))), + "shorter than it was held", )?; - refused("a field missing", &good.replace(" preempt_off_ns=7", ""), "fields")?; - - eprintln!(" [mask_windows] the verdict refuses 12 captures and accepts two"); + refused( + "a hold the load's own report reads back", + &[first.as_str(), &opening, &hold, &own, &after].concat(), + "reported nothing between", + )?; + refused("a report that skips a CPU", &good.replace(&windows(0, (300, 200)), ""), "names cpu1 at place 0")?; Ok(()) } diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index 0edf3dc0e81..2b4d583e361 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -132,64 +132,32 @@ impl Windows { } } -/// The head of `windows-staged`'s lines: `windows: staged cpuK open` where it -/// marks cpuK's open windows, and `windows: staged cpuK closed -/// irqs_off= preempt_off=` in a report of cpuK after a marked -/// window closed. -pub const STAGED: &str = "windows: staged cpu"; +/// The line a `mask-windows` kernel prints once a boot, where it held both of +/// cpuK's windows for a span read off that CPU's counter +/// (`kernel/src/windows.rs`): `windows: held cpuK ns=`. +const HELD: &str = "windows: held cpu"; -enum Staged { - Open(u32), - Closed { cpu: u32, irqs_off: bool, preempt_off: bool }, -} - -fn staged(line: &str) -> Option> { - let rest = line.split(STAGED).nth(1)?; - let flag = |field: &str, name: &str| field.strip_prefix(name)?.parse::().ok(); +fn held(line: &str) -> Option> { + let rest = line.split(HELD).nth(1)?; let parsed = match rest.split_whitespace().collect::>().as_slice() { - [cpu, "open"] => cpu.parse().ok().map(Staged::Open), - [cpu, "closed", irqs, preempt] => (|| { - Some(Staged::Closed { - cpu: cpu.parse().ok()?, - irqs_off: flag(irqs, "irqs_off=")?, - preempt_off: flag(preempt, "preempt_off=")?, - }) - })(), + [cpu, ns] => cpu.parse().ok().zip(ns.strip_prefix("ns=").and_then(|ns| ns.parse().ok())), _ => None, }; - Some(parsed.ok_or_else(|| format!("unreadable staged line {rest:?}"))) + Some(parsed.ok_or_else(|| format!("unreadable held line {rest:?}"))) } /// The judge of every `mask-windows` boot, and it judges no duration: each -/// census line has its CPU's windows line beside it, each CPU closed both -/// kinds of window at some point of the boot, and a stage's CPU says each of -/// its marked windows closed exactly once, in the reports after the stage. -/// Answers each CPU's longest windows over the whole capture. +/// census line has its CPU's windows line beside it, and each CPU closed both +/// kinds of window at some point of the boot. Answers each CPU's longest +/// windows over the whole capture. pub fn windows(capture: &str) -> Result, String> { let mut censuses: BTreeMap = BTreeMap::new(); let mut reports: Vec = Vec::new(); - // The staged CPU, and how many of its marked windows of each kind closed. - let mut stage: Option<(u32, u32, u32)> = None; for line in capture.lines() { if let Some(census) = Census::parse(line) { *censuses.entry(census.map_err(|why| format!("{why}\nline: {line}"))?.cpu).or_default() += 1; } else if let Some(report) = Windows::parse(line) { reports.push(report.map_err(|why| format!("{why}\nline: {line}"))?); - } else if let Some(said) = staged(line) { - match said.map_err(|why| format!("{why}\nline: {line}"))? { - Staged::Open(cpu) => { - if stage.replace((cpu, 0, 0)).is_some() { - return Err(format!("a second stage, and the kernel stages once a boot\nline: {line}")); - } - } - Staged::Closed { cpu, irqs_off, preempt_off } => match &mut stage { - Some((staged, irqs, preempt)) if *staged == cpu => { - *irqs += u32::from(irqs_off); - *preempt += u32::from(preempt_off); - } - _ => return Err(format!("cpu{cpu} closed a window no stage before it marked\nline: {line}")), - }, - } } } if censuses.is_empty() { @@ -220,15 +188,98 @@ pub fn windows(capture: &str) -> Result, String> { )); } } - if let Some((cpu, irqs, preempt)) = stage { - if (irqs, preempt) != (1, 1) { - return Err(format!( - "cpu{cpu}'s reports after its stage say its marked interrupts-off window closed \ - {irqs} time(s) and its marked preemption-off window {preempt}; each closes once" - )); + Ok(longest) +} + +/// What a machine's boot read, each the longest interrupts-off and +/// preemption-off window in nanoseconds. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct Measured { + /// What the holding CPU reported between its hold and the load's start. + pub held: (u64, u64), + /// What any CPU closed under the load. + pub load: (u64, u64), +} + +/// The durations a machine's boot is judged by, read from the reports of +/// `cpus` CPUs around the record `load_exited` heads, the load's exit. +/// +/// **The load's reading is its own.** A report carries what closed since the +/// report before, and the load's exit prints one before it tears the process +/// down. So the reading is that report and the next, which carries the +/// teardown, and it is refused unless a report before them emptied every CPU's +/// record as the load started. +/// +/// **A window of known length is read back.** The kernel held both of one +/// CPU's windows for the span its held line states: that CPU's reports from +/// there to the load's start carry a window of each kind no shorter. +pub fn windows_under(capture: &str, cpus: u32, load_exited: &str) -> Result { + let mut reports: Vec<(usize, Vec)> = Vec::new(); + let mut open: Vec = Vec::new(); + let mut hold: Option<(usize, u32, u64)> = None; + let mut exited: Option = None; + for (at, line) in capture.lines().enumerate() { + if let Some(report) = Windows::parse(line) { + let report = report.map_err(|why| format!("{why}\nline: {line}"))?; + if report.cpu as usize != open.len() { + return Err(format!("a report of {cpus} CPUs names cpu{} at place {}\nline: {line}", report.cpu, open.len())); + } + open.push(report); + if open.len() == cpus as usize { + reports.push((at, std::mem::take(&mut open))); + } + } else if let Some(said) = held(line) { + let (cpu, ns) = said.map_err(|why| format!("{why}\nline: {line}"))?; + if hold.replace((at, cpu, ns)).is_some() { + return Err(format!("a second hold, and the kernel holds once a boot\nline: {line}")); + } + } else if exited.is_none() && line.contains(load_exited) { + exited = Some(at); } } - Ok(longest) + let exited = exited.ok_or_else(|| format!("no `{load_exited}` record: the load never ended"))?; + let own = reports + .iter() + .rposition(|(at, _)| *at < exited) + .ok_or_else(|| format!("no report before `{load_exited}`: the load's exit printed none"))?; + if own == 0 { + return Err("the load's report is the boot's first: none was taken as the load started, so it \ + carries every window since each CPU joined" + .to_string()); + } + let after = reports.get(own + 1).ok_or_else(|| { + format!("no report after `{load_exited}`: what the load's own exit closed was never read") + })?; + let longest = |lines: &mut dyn Iterator| { + lines.fold((0, 0), |(irqs, preempt), w| (irqs.max(w.irqs_off_ns), preempt.max(w.preempt_off_ns))) + }; + + let (hold_at, cpu, ns) = + hold.ok_or_else(|| format!("no `{HELD}` line: this kernel held no window of known length"))?; + if ns < toyos_sched::windows::HELD_NS { + return Err(format!("cpu{cpu} held its windows for {ns} ns, and the kernel owes {}", toyos_sched::windows::HELD_NS)); + } + let mut read_back = reports[..own] + .iter() + .filter(|(at, _)| *at > hold_at) + .filter_map(|(_, report)| report.get(cpu as usize)) + .peekable(); + if read_back.peek().is_none() { + return Err(format!( + "cpu{cpu} reported nothing between its hold and the load's own report, so the load's \ + reading carries the hold" + )); + } + let held = longest(&mut read_back); + if held.0 < ns || held.1 < ns { + return Err(format!( + "cpu{cpu} held both windows for {ns} ns, and its reports before the load's read back \ + irqs_off_ns={} preempt_off_ns={}: a window was reported shorter than it was held", + held.0, held.1 + )); + } + let load = longest(&mut reports[own].1.iter().chain(&after.1)); + Ok(Measured { held, load }) } /// The newest census each CPU of each guest printed, keyed by the boot's own diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 386146128c6..6e2d07f0f39 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -156,8 +156,7 @@ pub fn boot_census() -> (u32, u32, Vec) { /// to pay a kernel build per suite run forever. /// [`toyos_build::build::MASK_WINDOWS_KERNEL`] made it: its hooks sit on every /// entry and masking primitive, where a parameter would be a branch on the path -/// they measure, and it carries the test kernel's actuators so a stage can mark -/// its windows. Interactive debug mode is separate: it builds +/// they measure. Interactive debug mode is separate: it builds /// [`toyos_build::build::DEBUG_KERNEL_BUILD`] and returns before the suite. pub const DECLARED_KERNEL_BUILDS: [&str; 3] = toyos_build::build::TEST_SUITE_KERNEL_BUILDS; @@ -1072,24 +1071,20 @@ pub struct QemuInstance { /// Which of [`DECLARED_KERNEL_BUILDS`] this boot wants. /// /// **A parameter never decides a build.** Every actuator lives in the one test -/// kernel, so asking for one selects that kernel and nothing more; a build -/// asked for by name arms one only if it carries them all too. +/// kernel, so asking for one selects that kernel and nothing more; the third +/// build is asked for by name and by one test. fn kernel_of(options: &BootOptions) -> Vec<&'static str> { if options.kernel_params.is_empty() { return options.kernel_features.to_vec(); } - if options.kernel_features.is_empty() { - return toyos_build::build::TEST_KERNEL.to_vec(); - } assert!( - toyos_build::build::carries_the_actuators(options.kernel_features), - "a boot asking to arm {:?} asks for the kernel build {:?}, which does not carry {:?}; \ - an actuator is a parameter and the test kernel carries all of them", + options.kernel_features.is_empty(), + "a boot asking to arm {:?} also asks for the kernel build {:?}; an actuator is a \ + parameter and the test kernel carries all of them", options.kernel_params, options.kernel_features, - toyos_build::build::TEST_KERNEL, ); - options.kernel_features.to_vec() + toyos_build::build::TEST_KERNEL.to_vec() } // Eight, because an image is its architecture as much as its files and its kernel. diff --git a/tests/toyos-rust-tests/src/bin/idle_span.rs b/tests/toyos-rust-tests/src/bin/idle_span.rs new file mode 100644 index 00000000000..058e681fdb6 --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/idle_span.rs @@ -0,0 +1,16 @@ +//! **The machine idles for a span nothing can mistake for work**, and this +//! process's exit is the boot's first. It asserts nothing: `mask_windows` +//! reads what a `mask-windows` kernel reports of the CPU that slept through +//! it, whose halt is no preemption-off window. + +use std::thread::sleep; +use std::time::Duration; + +/// Five times what the record's ceiling allows the window the kernel holds at +/// this exit (`toyos_sched::windows::HELD_NS`, doubled), so a halt counted as +/// a window is past it. +const SPAN: Duration = Duration::from_millis(500); + +fn main() { + sleep(SPAN); +} diff --git a/tests/toyos.rs b/tests/toyos.rs index 0aa9dcb7f84..6fc93eac592 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -74,6 +74,9 @@ const RUST_SKIP: &[&str] = &[ // its 256 threads' stacks would crowd every member after it in one boot. // The `mask_windows` metal row runs it. "ring_park_herd", + // It asserts nothing: it is half a second of an idle machine, which the + // same row reads the windows across. + "idle_span", // The C corpus's comparator: a helper reached through one symlink per case, // never a test of its own. `shared_metal` stages every name on this list. "ccheck", @@ -155,8 +158,8 @@ const SCREEN_TESTS: &[(&str, qemu::Profile)] = &[ ("virt_unmap_touch", qemu::Profile::VirtEl2), ("virt_debug_refused", qemu::Profile::VirtEl2), ("virt_readonly_copyout", qemu::Profile::VirtEl2), - // The windows on AArch64, over every job of the case: the windows each - // report carries and the stage's marked ones, counts and an order; no clock. + // The windows on AArch64, on eight CPUs: every hook's check, and the lines + // each report carries; no clock. ("virt_mask_windows", qemu::Profile::VirtEl2), ("virt_smp", qemu::Profile::VirtEl2), ("virt_el1_smp", qemu::Profile::VirtTcg), @@ -237,7 +240,7 @@ const METAL: &[(&str, metal::Metal)] = &[ ), ( // The windows on the machine that owes them: every CPU reported beside - // its census, and the boot's longest and the herd's own recorded. + // its census, a held window read back, and the herd's own recorded. "mask_windows", metal::Metal { arms: WINDOWSCASE, judge: |b| windows_on_metal(b[0]) }, ), @@ -648,12 +651,28 @@ const TESTCASES_READDIR: &[metal::Arm] = const JOBCASE: &[metal::Arm] = &[metal::once("jobcase", "tests/jobcase", &[], &[])]; /// The shipping kernel with the windows' instrument and nothing else, so what -/// it reads is that kernel under the herd. +/// it reads is that kernel under the herd. Four exits, a report each: +/// `idle_span`'s is the boot's first, where the kernel holds; `pwd`'s reads the +/// hold back and empties every record as the herd starts; the herd's and +/// `echo`'s are the herd's reading, the second carrying its teardown. const WINDOWSCASE: &[metal::Arm] = &[metal::Arm { - features: &["mask-windows"], - ..metal::once("windowscase", "tests/testcases", &[], &["test_rs_ring_park_herd"]) + features: toyos_build::build::MASK_WINDOWS_KERNEL, + ..metal::once( + "windowscase", + "tests/testcases", + &[], + &["test_rs_idle_span", "pwd", WINDOWS_LOAD, "echo"], + ) }]; +/// The load `mask_windows` reads the windows under. +const WINDOWS_LOAD: &str = "test_rs_ring_park_herd"; + +/// The head of the kernel's record of [`WINDOWS_LOAD`]'s exit. +fn windows_load_exited() -> String { + format!("{}{} pid=", toyos_build::bootlog::EXIT, toyos_build::bootlog::recorded_name(WINDOWS_LOAD)) +} + /// A `logd` that leaves soundd's ring unread until the job says the tone played. const LOGSTALLCASE: &[metal::Arm] = &[metal::once("logstallcase", "tests/logstallcase", &[], &["test_rs_soundd_log_stall"])]; @@ -1361,36 +1380,9 @@ fn virt_job(profile: qemu::Profile, job: &str, said: &str) -> Result<(), String> judge_virt_job(qemu, job, said).map(drop) } -/// The windows on AArch64: every job of `tests/virtjobcase` run on a -/// `mask-windows` kernel staged at the first `SYS_EXIT`, judged once the last -/// has ended. -fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { - let config = compile::repo_root().join("tests/virtjobcase/system.toml"); - let case = config.parent().expect("system.toml has a directory"); - let qemu = QemuInstance::boot_with_options( - case, - &[], - &[], - BootOptions { - profile, - smp: 1, - kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL, - kernel_params: &["windows-staged"], - ready_marker: "control registers: SCTLR_EL1=", - extra_root_files: vec![(format!("bin/test_rs_{VIRT_COPYOUT}"), virt_copyout(profile.arch()).to_vec())], - ..Default::default() - }, - ); - let serial = judge_virt_job(qemu, &format!("test_rs_{VIRT_COPYOUT}"), "a syscall writes only where its caller could store")?; - mask_windows(&serial, 1) -} - -/// A `windows-staged` boot's windows: `common::irqcensus::windows`'s verdict, -/// with a stage made and `cpus` CPUs reporting. +/// A `mask-windows` boot's windows: `common::irqcensus::windows`'s verdict, +/// with `cpus` CPUs reporting. fn mask_windows(capture: &str, cpus: u32) -> Result<(), String> { - if !capture.contains(common::irqcensus::STAGED) { - return Err(format!("`windows-staged` marked nothing, so no window was held to a stage:\n{capture}")); - } let longest = common::irqcensus::windows(capture)?; if longest.len() != cpus as usize { return Err(format!("{} of {cpus} CPUs reported windows: {longest:?}", longest.len())); @@ -1436,8 +1428,22 @@ const UNMAP_TOUCH_SAID: &str = /// The CPUs `virt_smp` boots. const VIRT_CPUS: u32 = 8; -/// Boot `tests/virtsmpcase` under `profile` on `cpus` CPUs, with `params` armed. -fn boot_virt_smp(profile: qemu::Profile, cpus: u32, params: &'static [&'static str]) -> QemuInstance { +/// 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 has ended. +fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { + let qemu = boot_virt_smp(profile, VIRT_CPUS, toyos_build::build::MASK_WINDOWS_KERNEL, &[]); + mask_windows(&judge_virt_job(qemu, "unmap_touch", UNMAP_TOUCH_SAID)?, VIRT_CPUS) +} + +/// Boot `tests/virtsmpcase` under `profile` on `cpus` CPUs of the kernel built +/// with `features`, with `params` armed. +fn boot_virt_smp( + profile: qemu::Profile, + cpus: u32, + features: &'static [&'static str], + params: &'static [&'static str], +) -> QemuInstance { let config = compile::repo_root().join("tests/virtsmpcase/system.toml"); let case = config.parent().expect("system.toml has a directory"); QemuInstance::boot_with_options( @@ -1447,6 +1453,7 @@ fn boot_virt_smp(profile: qemu::Profile, cpus: u32, params: &'static [&'static s BootOptions { profile, smp: cpus, + kernel_features: features, kernel_params: params, ready_marker: "control registers: SCTLR_EL1=", ..Default::default() @@ -1460,7 +1467,7 @@ fn boot_virt_smp(profile: qemu::Profile, cpus: u32, params: &'static [&'static s /// entered there and joins the scheduler, and the case's job `unmap_touch` /// ends with exit 0. fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String> { - let serial = judge_virt_job(boot_virt_smp(profile, VIRT_CPUS, &[]), "unmap_touch", UNMAP_TOUCH_SAID)?; + let serial = judge_virt_job(boot_virt_smp(profile, VIRT_CPUS, &[], &[]), "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}")); @@ -1491,7 +1498,7 @@ fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String /// exit 0. fn virt_failed_ap_leaves_no_hole(profile: qemu::Profile) -> Result<(), String> { const CPUS: u32 = 4; - let qemu = boot_virt_smp(profile, CPUS, &["smp-skip-ap"]); + let qemu = boot_virt_smp(profile, CPUS, &[], &["smp-skip-ap"]); let serial = judge_virt_job(qemu, "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"] { @@ -2263,44 +2270,22 @@ fn irq_census(capture: &str) -> Result<(), String> { Ok(()) } -/// The T14's windows: `common::irqcensus::windows`' verdict with every CPU -/// reporting, and the longest over the boot and in the herd's own report — the -/// one its exit printed, just before its exit record — recorded. +/// The T14's windows: [`mask_windows`]' verdict with every CPU reporting, and +/// `common::irqcensus::windows_under`'s durations, recorded. fn windows_on_metal(boot: &metal::Readback) -> Result<(), String> { - const HERD: &str = "test_rs_ring_park_herd"; - boot.job_passed(HERD)?; + boot.job_passed(WINDOWS_LOAD)?; let kernel = boot.kernel(); - let text = kernel.text(); - let longest = common::irqcensus::windows(text)?; let cpus = boot.cpus()?; - if longest.len() != cpus as usize { - return Err(format!("{} of {cpus} CPUs reported windows: {longest:?}", longest.len())); - } - let exited = format!("{}{} pid=", toyos_build::bootlog::EXIT, toyos_build::bootlog::recorded_name(HERD)); - let mut latest = std::collections::BTreeMap::new(); - let mut herd = None; - for line in text.lines() { - if let Some(Ok(report)) = common::irqcensus::Windows::parse(line) { - latest.insert(report.cpu, report); - } else if line.contains(&exited) { - herd = Some(latest.clone()); - break; - } - } - let herd = herd.ok_or_else(|| format!("no `{exited}` record after a report:\n{text}"))?; - let most = |of: &mut dyn Iterator| { - of.fold((0, 0), |(i, p), w| (w.irqs_off_ns.max(i), w.preempt_off_ns.max(p))) - }; - let (irqs, preempt) = most(&mut longest.values()); - let (herd_irqs, herd_preempt) = most(&mut herd.values()); + mask_windows(kernel.text(), cpus)?; + let read = common::irqcensus::windows_under(kernel.text(), cpus, &windows_load_exited())?; eprintln!( - " [windows] boot irqs_off_ns={irqs} preempt_off_ns={preempt}; herd irqs_off_ns={herd_irqs} \ - preempt_off_ns={herd_preempt}" + " [windows] held irqs_off_ns={} preempt_off_ns={}; herd irqs_off_ns={} preempt_off_ns={}", + read.held.0, read.held.1, read.load.0, read.load.1 ); - boot.measured("windows.windowscase.irqs_off_ns", irqs)?; - boot.measured("windows.windowscase.preempt_off_ns", preempt)?; - boot.measured("windows.windowscase.herd_irqs_off_ns", herd_irqs)?; - boot.measured("windows.windowscase.herd_preempt_off_ns", herd_preempt) + boot.measured("windows.windowscase.held_irqs_off_ns", read.held.0)?; + boot.measured("windows.windowscase.held_preempt_off_ns", read.held.1)?; + boot.measured("windows.windowscase.herd_irqs_off_ns", read.load.0)?; + boot.measured("windows.windowscase.herd_preempt_off_ns", read.load.1) } fn pci_cap_selftest(log: &str) -> Result<(), String> { diff --git a/toyos-sched/src/windows.rs b/toyos-sched/src/windows.rs index 20a629ea735..8c80caffb45 100644 --- a/toyos-sched/src/windows.rs +++ b/toyos-sched/src/windows.rs @@ -14,10 +14,6 @@ //! by one and [`Windows::lowering`] precedes every lowering by one; each acts //! only on a crossing of zero. //! -//! **A mark names a window without judging its length**: [`Windows::mark`] -//! marks the window of each kind open now, the mark rides to that window's -//! close, and [`Windows::take_marked`] answers each marked close once. -//! //! **Every transition is checked against the state it finds**, and one that //! could not have followed it is [`Unseen`]: a transition before it that //! nothing reported. The record is written by its CPU alone and a take @@ -26,18 +22,16 @@ use core::fmt; -use crate::sync::{AtomicU32, AtomicU64, Ordering}; +use crate::sync::{AtomicU64, Ordering}; /// A CPU that has not joined the scheduler, or that stopped being tracked: /// every transition is accepted and records nothing. const UNTRACKED: u64 = u64::MAX; -/// [`Windows::marks`]: the open window of each kind carries a mark, and a -/// marked window of each kind closed since the last [`Windows::take_marked`]. -const IRQS_MARKED: u32 = 1; -const PREEMPT_MARKED: u32 = 2; -const IRQS_MARK_CLOSED: u32 = 4; -const PREEMPT_MARK_CLOSED: u32 = 8; +/// How long the kernel holds both windows, once a boot, for a report to read +/// back: more than twice any window a boot closes by itself, so no other +/// window stands in for it, whole or halved. +pub const HELD_NS: u64 = 50_000_000; /// One CPU's windows. The counter is never zero once firmware has run, so a /// stamp of zero is no open window. @@ -49,8 +43,6 @@ pub struct Windows { preempt_off: AtomicU64, irqs_longest: AtomicU64, preempt_longest: AtomicU64, - /// Its CPU sets and moves the `*_MARKED` bits; a take clears the `*_MARK_CLOSED` ones. - marks: AtomicU32, } /// A transition the record says could not have happened, named by the one @@ -59,12 +51,11 @@ pub struct Windows { pub enum Unseen { /// Masked, with a window open. AnUnmask, - /// Unmasking, or interrupted with interrupts masked, with no window open. + /// Unmasking, with no window open. AMask, /// The count left zero, or a halt ended, with a window open. ALowering, - /// The count returned to zero, a pass ran, a halt began, or a mark was - /// made, with no window open. + /// The count returned to zero, a pass ran or a halt began, with no window open. ARaise, } @@ -94,7 +85,6 @@ impl Windows { preempt_off: AtomicU64::new(0), irqs_longest: AtomicU64::new(0), preempt_longest: AtomicU64::new(0), - marks: AtomicU32::new(0), } } @@ -107,7 +97,6 @@ impl Windows { preempt_off: AtomicU64::new(0), irqs_longest: AtomicU64::new(0), preempt_longest: AtomicU64::new(0), - marks: AtomicU32::new(0), } } @@ -147,14 +136,6 @@ impl Windows { } } - /// The CPU was interrupted with interrupts masked. - pub fn found_masked(&self) -> Result<(), Unseen> { - match self.irqs_off.load(Ordering::Relaxed) { - 0 => Err(Unseen::AMask), - _ => Ok(()), - } - } - /// Interrupts are masked and about to be opened. pub fn unmasking(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { match self.irqs_off.load(Ordering::Relaxed) { @@ -163,7 +144,6 @@ impl Windows { since => { Self::record(&self.irqs_longest, since, now()); self.irqs_off.store(0, Ordering::Relaxed); - self.carry(IRQS_MARKED, IRQS_MARK_CLOSED); Ok(()) } } @@ -240,35 +220,11 @@ impl Windows { since => { Self::record(&self.preempt_longest, since, now); self.preempt_off.store(0, Ordering::Relaxed); - self.carry(PREEMPT_MARKED, PREEMPT_MARK_CLOSED); Ok(()) } } } - /// A window of the kind `marked` names has closed: a mark it carried is - /// left for the next [`Windows::take_marked`] as `closed`. - fn carry(&self, marked: u32, closed: u32) { - if self.marks.load(Ordering::Relaxed) & marked != 0 { - self.marks.fetch_or(closed, Ordering::Relaxed); - self.marks.fetch_and(!marked, Ordering::Relaxed); - } - } - - /// Mark the window of each kind open now, where the caller knows both are. - pub fn mark(&self) -> Result<(), Unseen> { - match self.irqs_off.load(Ordering::Relaxed) { - UNTRACKED => return Ok(()), - 0 => return Err(Unseen::AMask), - _ => {} - } - if self.preempt_off.load(Ordering::Relaxed) == 0 { - return Err(Unseen::ARaise); - } - self.marks.fetch_or(IRQS_MARKED | PREEMPT_MARKED, Ordering::Relaxed); - Ok(()) - } - /// The longest interrupts-off and preemption-off windows closed since the /// last take, in counter ticks; the next take starts from none. pub fn take(&self) -> (u64, u64) { @@ -277,13 +233,6 @@ impl Windows { self.preempt_longest.swap(0, Ordering::Relaxed), ) } - - /// Whether a marked interrupts-off and a marked preemption-off window - /// closed since the last such take; the next starts from none. - pub fn take_marked(&self) -> (bool, bool) { - let closed = self.marks.fetch_and(!(IRQS_MARK_CLOSED | PREEMPT_MARK_CLOSED), Ordering::Relaxed); - (closed & IRQS_MARK_CLOSED != 0, closed & PREEMPT_MARK_CLOSED != 0) - } } #[cfg(test)] @@ -362,9 +311,7 @@ mod tests { fn every_transition_nothing_reported_before_is_named() { let w = open_at(1); assert_eq!(w.unmasking(|| 2), Err(Unseen::AMask)); - assert_eq!(w.found_masked(), Err(Unseen::AMask)); w.masked(|| 3).unwrap(); - w.found_masked().unwrap(); assert_eq!(w.masked(|| 4), Err(Unseen::AnUnmask)); let w = open_at(1); @@ -376,29 +323,6 @@ mod tests { assert_eq!(w.raised(1, || 4), Err(Unseen::ALowering)); assert_eq!(w.woken(|| 4), Err(Unseen::ALowering)); assert_eq!(w.set(0, 1, || 4), Err(Unseen::ALowering)); - - let w = open_at(1); - assert_eq!(w.mark(), Err(Unseen::AMask)); - w.masked(|| 2).unwrap(); - assert_eq!(w.mark(), Err(Unseen::ARaise)); - } - - #[test] - fn a_mark_rides_to_its_windows_close_and_is_answered_once() { - let w = open_at(1); - w.masked(|| 10).unwrap(); - w.raised(1, || 11).unwrap(); - w.mark().unwrap(); - assert_eq!(w.take_marked(), (false, false), "no marked window has closed yet"); - w.unmasking(|| 20).unwrap(); - assert_eq!(w.take_marked(), (true, false)); - w.scheduled(|| 25).unwrap(); - assert_eq!(w.take_marked(), (false, true), "a pass closes the marked window"); - assert_eq!(w.take_marked(), (false, false), "a take starts the next from none"); - w.lowering(1, || 30).unwrap(); - w.masked(|| 40).unwrap(); - w.unmasking(|| 50).unwrap(); - assert_eq!(w.take_marked(), (false, false), "the windows after the marked ones carry no mark"); } #[test] @@ -411,9 +335,7 @@ mod tests { w.lowering(1, || 5).unwrap(); w.lowering(1, || 6).unwrap(); w.scheduled(|| 7).unwrap(); - w.mark().unwrap(); assert_eq!(w.take(), (0, 0)); - assert_eq!(w.take_marked(), (false, false)); let w = open_at(1); w.masked(|| 2).unwrap(); From 19a51fe7ede1a4bb942c418e23a63c06d04d08c4 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 2 Oct 2026 20:37:16 +0200 Subject: [PATCH 09/13] Step 2 is built and its exit open; the herd's defect and two the T14 found say what was read The review of #649 at 72f16e39a ruled that its eight T14 readings cannot decide whether stage 6 step 1 lengthened a window (BLOCKER 6, NOTE 1): each boot printed one report, so the herd's reading was the boot's; no handler step 1 changed took an interrupt; and the herd's walks start in `SYS_INBOX_SUBMIT`, which runs masked with step 1 and without it. The track's step 2 says so: built, exit open, and the exit is the instrument reading back a known window on the T14 with its rows recorded, then medians of at least five interleaved boots an arm from the load's own report, against a tolerance stated first, under a load that reaches a handler step 1 changed. Steps 3 to 5 measure against the readings that exit leaves in the tree. The herd's defect no longer says its walks ran with interrupts open before #634, which `issues/kernel/syscall-preemption-is-incidental.md` has refuted since July. Its exit is the window not growing with the threads parked, read at two sizes on one kernel: the defect stands on both arms, so a comparison of arms would close it while it is true. Two defects those eight boots measured are filed with their numbers: cpu0's 6.5 ms window in every boot, and the windows of 9 ms or more in some. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...alk-by-the-threads-it-parks-on-one-ring.md | 27 ++++++-- ...nd-preemption-off-for-6-5-ms-on-the-t14.md | 52 +++++++++++++++ ...n-interrupts-off-window-of-9-ms-or-more.md | 65 +++++++++++++++++++ ...-small-interrupts-post-and-threads-wait.md | 27 +++++--- 4 files changed, 155 insertions(+), 16 deletions(-) create mode 100644 issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md create mode 100644 issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md diff --git a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md index b959cebf82b..06f15a44644 100644 --- a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md +++ b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md @@ -31,11 +31,24 @@ holder, decides how long a CPU runs with interrupts masked: registrations sweep them four at a time. Nothing caps N: a thread costs its process a 128 KiB kernel stack -(`kernel/src/process.rs`) and no count. Before #634 every one of these -walks ran with interrupts open, under preemption off. By reading, not -measured: no instrument in the tree reads an interrupts-off window. +(`kernel/src/process.rs`) and no count. The first walk starts in +`SYS_INBOX_SUBMIT`, and a syscall runs with interrupts masked from entry to +exit (`issues/kernel/syscall-preemption-is-incidental.md`), with #634 and +without it: #634 did not mask it, and reverting #634 does not shorten it. +The second runs in the device's handler since #634. -**Exit**: step 2's interrupts-off window, read on the T14 while one process -parks 256 threads in `submit` on one ring and a sibling thread completes into -it, is no longer with step 1 than with it reverted on the same tree, under -the same load. +How long either is has not been read. The eight T14 boots of #649 at +`72f16e39a` ran the first with N = 256 (`test_rs_ring_park_herd`), but each +printed one report, which spans every window since its CPU joined the +scheduler, and none took an interrupt a handler #634 changed serves +(`userdev=0 sound=0 dmafault=0 hda=0` on every CPU). They bound it from +above: in the six boots no longer window covers, the seven CPUs other than +cpu0 read 251,452 to 4,720,498 ns of interrupts off. + +**Exit**: the interrupts-off window step 2's instrument reads on the T14 +under N threads parked in `submit` on one ring, a sibling thread completing +into it, does not grow with N: read at two sizes on one kernel, each from the +load's own report. `ring_park_herd`'s sibling waits on the kernel's roster, +which is itself a masked walk over every thread of the machine (3,619 to +4,111 `SYS_SYSINFO` calls a run in those boots, and 768 to 847 ms of syscall +wall in a run of 0.9 s), so that reading has to tell the two walks apart. diff --git a/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md b/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md new file mode 100644 index 00000000000..ed7f668e280 --- /dev/null +++ b/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md @@ -0,0 +1,52 @@ +--- +status: open +kind: defect +opened: 2026-10-02 +--- + +# cpu0 holds interrupts and preemption off for 6.5 ms on the T14 + +Read by the `mask-windows` kernel (`kernel/src/windows.rs`) on LENOVO +20W0003AMZ, BIOS N34ET71W (1.71), in the eight `mask_windows` boots of #649 +at `72f16e39a`: four as that head stands and four with stage 6 step 1 (#634) +reverted on it. Each boot printed one report, at `test_rs_ring_park_herd`'s +exit, so a line is its CPU's longest window from the moment it joined the +scheduler to that exit. + +cpu0's line, in the seven boots where no longer window covers it: + +| boot | `irqs_off_ns` | `preempt_off_ns` | +|---|---|---| +| 1, reverted | 6551791 | 6551707 | +| 2 | 6540754 | 6540671 | +| 3, reverted | 6549549 | 6549484 | +| 5, reverted | 6540326 | 6540262 | +| 6 | 6589053 | 6588992 | +| 7, reverted | 6590095 | 6590031 | +| 8 | 6587342 | 6587281 | + +- The two kinds differ by 61 to 84 ns in every row, so one section holds + both. +- It is cpu0's alone. In the six of those boots where no CPU carries a + longer one, the other seven CPUs' interrupts-off lines read 251,452 to + 4,720,498 ns. +- It is there with step 1 and without it. +- In all eight logs cpu0 says `sched: cpu=0 ready=0 … current=None trips=1` + at 1.155 or 1.156 s, as the CPUs join the scheduler, and nothing more + before init's first line at 1.161 or 1.162 s. + +The fourth boot's cpu0 reads 9644415 and 9643939, the event +`issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md` +records. + +Nothing names what opens it. A report carries a span and no address, and one +report a boot cannot say whether the window recurs. What will: the record +keeping, beside each CPU's longest span, the address its opening hook was +called from, printed in the report and resolved through the kernel's symbols. +The row's first report now ends at its first job's exit, half a second after +the CPUs join, and no longer at the herd's: it says whether the window opens +before that, and no more. + +**Exit**: the section that opens the window is named by that reading on the +T14, and cpu0's longest window there no longer includes it, or this file is +replaced by the bound the section is held to and the derivation of it. diff --git a/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md b/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md new file mode 100644 index 00000000000..6f64bff0eac --- /dev/null +++ b/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md @@ -0,0 +1,65 @@ +--- +status: open +kind: defect +opened: 2026-10-02 +--- + +# Some T14 boots carry an interrupts-off window of 9 ms or more + +Read by the `mask-windows` kernel (`kernel/src/windows.rs`) on LENOVO +20W0003AMZ, BIOS N34ET71W (1.71), in the eight `mask_windows` boots of #649 +at `72f16e39a`: four as that head stands and four with stage 6 step 1 (#634) +reverted on it, one job each, `test_rs_ring_park_herd`. The longest window +that recurs in every boot is cpu0's 6.5 ms +(`issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md`). +Three readings are longer, each in some boots and not in others, on both +arms: + +- **Every CPU at once, the fourth boot** (step 1 in). The herd's report: + + | CPU | `irqs_off_ns` | `preempt_off_ns` | + |---|---|---| + | cpu0 | 9644415 | 9643939 | + | cpu1 | 9603617 | 9588515 | + | cpu2 | 9627971 | 9625674 | + | cpu3 | 9641999 | 9620791 | + | cpu4 | 9651846 | 9635137 | + | cpu5 | 9623545 | 9612295 | + | cpu6 | 9624969 | 9621345 | + | cpu7 | 9614836 | 9614716 | + + The same report's shootdown line reads + `tlb: shootdowns=280 wait=125911us max=9575us`, where the other seven + boots read at most `wait=49119us` and at most `max=1421us`, and cpu0's + census reads `nmi=2`, where the other seven read `nmi=1`. +- **One CPU, the seventh boot** (step 1 reverted). cpu7 reads 9260193 and + 9260124. cpu0 reads its 6590095, the other six 920,455 to 1,404,001, and + the shootdown line `max=1386us`. +- **One CPU, after the herd's report, in four boots of the eight.** The stop + prints a report too, of which the black box keeps the lines of cpu2 to + cpu7. In it one CPU reads + + | boot | CPU | `irqs_off_ns` | `preempt_off_ns` | + |---|---|---|---| + | 1, reverted | cpu7 | 10677997 | 10677829 | + | 2 | cpu7 | 11267384 | 11267320 | + | 5, reverted | cpu2 | 10214820 | 10214656 | + | 6 | cpu7 | 10874427 | 10874364 | + + and in the other four cpu7 reads 1,424,134 to 1,532,702 ns and no kept + line more. What that report spans is the herd's teardown, which its own + report precedes, the spawn of `reboot` on cpu7 and the stop. + +By reading, not measured: every CPU waiting out one CPU's masked window +inside a shootdown would read as the fourth boot does. + +Nothing names what opens any of them. A report carries a span and no address, +and no time: eight equal spans are not shown to be one event. What will: the +record keeping, beside each CPU's longest span, the address its opening hook +was called from and the counter it closed at, printed in the report. The row +now takes a report after the herd's exit and before `reboot` is spawned, +which says on which side of that the third reading falls. + +**Exit**: each of the three is named by that reading on the T14, and is +removed, or this file is replaced by the bound it is held to and the +derivation of it. diff --git a/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md b/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md index efc11f04399..3b3c48ee521 100644 --- a/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md +++ b/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md @@ -149,8 +149,8 @@ times: does the work, and no step creates a kernel thread. `irq_ring`, the driver list in `drain_irqs` and the idle loop's device checks are gone by step 5. Each step measures the kernel's lines against stage 6's first commit, and - from step 2 the longest interrupts-off and preemption-off windows against - the readings step 2 records. + the longest interrupts-off and preemption-off windows against the readings + step 2's exit puts in the tree, by that exit's rule. Steps 3 and 4 do not land alone: they land with #592's i8042 stage and with usbd. 1. **Interrupts post.** A post is legal in a handler: the watches a handler @@ -168,12 +168,21 @@ times: 2. **The windows, measured**: the longest interrupts-off and preemption-off windows per CPU, reported beside the IRQ census and fed by each architecture's masking primitives and entries, the number the ARM - track's stage 4 owes as well. The baseline is step 1 reverted on the - tree that carries the instrument. **Exit**: both windows read on the - T14, which is x86 metal, on that tree with step 1 and with it reverted, - and neither is longer with step 1 than without it, under the load - `issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md` - names as well. + track's stage 4 owes as well. Built: the `mask-windows` kernel and the + T14's `mask_windows` row. **Exit**, open: the instrument reads back a + window of known length on the T14, which is x86 metal, and its rows are + in that machine's record; and neither window is longer with step 1 than + with it reverted on the tree that carries the instrument, the patch + posted on #649 being what reverted means. That comparison is the median + of at least five interleaved boots an arm, each read from the load's own + report with a report taken as the load starts, against a tolerance + stated before measuring, the reverted arm's own spread, with the tail + reported beside it, under a load in which a handler step 1 changed posts + into a watch that reaches a ring with parked threads + (`issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md`'s + second bullet). `ring_park_herd` is not that load: its walks start in + `SYS_INBOX_SUBMIT`, which runs with interrupts masked on both arms, and + it reaches no handler step 1 changed. 3. **The i8042's thread is ps2server's** (#592's i8042 stage): `irq_ring`'s `I8042`, `keyboard_controller::service` and the idle loop's `verdict_due` go with the kernel's driver. **Exit**: that stage's. @@ -186,7 +195,7 @@ times: report on the panel and holding it there, a device the pass reaches (owner, 2026-09-30). **Exit**: `drain_irqs` and the idle loop's device checks are gone, both windows are measured against - the readings step 2 records, and the exits of + step 2's readings by its rule, and the exits of `issues/kernel/an-irq-watchs-freeing-cancel-compiles-in-a-handler.md` and `issues/kernel/nothing-fails-when-a-devices-release-or-close-stops-answering-its-polls.md` From 8b73eba69fd3c03c7aa638b157e535e496001b74 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 2 Oct 2026 20:38:26 +0200 Subject: [PATCH 10/13] The hold rests on its site: a syscall is already inside both windows `hold_once` masked interrupts and raised the preempt count around its spin. Its one caller is `SYS_EXIT`, whose entry did both, so deleting the two lines changed nothing a boot could show, on either architecture. What says the hold is inside both windows is the T14's judge: a hold outside one reads back shorter than it was held. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- kernel/src/windows.rs | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index 49c5ca5ad67..a24da1575cc 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -23,8 +23,8 @@ //! is tracked from [`start_here`], where it joins the scheduler, and a window //! is reported by the report after it closes. //! -//! Once a boot, [`hold_once`] holds both windows for a span it reads off the -//! counter and prints, which a later report of that CPU reads back. +//! Once a boot, [`hold_once`] keeps both windows open for a span it reads off +//! the counter and prints, which a later report of that CPU reads back. use core::sync::atomic::AtomicBool; use core::sync::atomic::Ordering::Relaxed; @@ -121,15 +121,14 @@ pub fn log_cpu(cpu: u32) { ); } -/// The boot's first `SYS_EXIT` holds both windows for [`HELD_NS`] by this -/// CPU's counter and says how long that was: `windows: held cpuN ns=…`. +/// The boot's first `SYS_EXIT`, which its entry left with interrupts masked +/// and the preempt count raised, stays there for [`HELD_NS`] by this CPU's +/// counter and says how long that was: `windows: held cpuN ns=…`. pub fn hold_once() { static HELD: AtomicBool = AtomicBool::new(false); if HELD.swap(true, Relaxed) { return; } - let _masked = crate::arch::IrqGuard::close(); - crate::preempt::disable(); let from = cpu::counter(); let owed = crate::clock::counter_ticks(HELD_NS); let mut held = 0; @@ -138,5 +137,4 @@ pub fn hold_once() { held = cpu::counter() - from; } crate::log!("windows: held cpu{} ns={}", percpu::cpu_id(), crate::clock::nanos_of_ticks(held)); - crate::preempt::enable(); } From f96aa97ccab7ae8ae562d5e4a53754dedcf032ff Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 2 Oct 2026 21:37:26 +0200 Subject: [PATCH 11/13] The load is read from its own report, the hold is bounded above, and no windows row is recorded Review round 2 on #649, at 8b73eba69. The load's reading was its own report and the one after. In all three T14 boots at 8b73eba69 the second was set by cpu7, the CPU test-runner spawns from, in the span that held its spawn of `echo`: 1,499,808, 2 x 748,872 and 1,479,558 ns, against 1,032,292, 2 x 519,358 and 1,175,943 in the herd's own report. So `windows_under` reads the load's report alone, the refusal of a boot with no report after it goes with its capture, and `echo` leaves the row's job list: three exits, three reports. The judge refused a hold read back shorter than it was held and none read back longer, so a kernel that counts the idle halt as a preemption-off window passed every test in the tree and was red on the T14 only against a row recorded from an earlier boot. The capture carries the span itself: a read-back past `metaltimings::ceiling` of the held line is refused. On the existing readback of that kernel (486,343,787 ns against 50,000,069 held) the row is now red on a tree with no `windows.*` row. No `windows.*` row is recorded. Twice one boot's longest window is a ceiling this machine has already been past, at 9.2 to 9.7 ms in two of eight earlier boots, and the held pair is bounded by the capture. The judge prints both pairs. `boot.windowscase.*`, which every boot of the row measures, is committed from the head's boot at 8b73eba69, so a judging leaves the tree as it found it. `hold_once` converted `HELD_NS` to ticks and looped on the tick count. At the T14's 413,479 fs a tick that count is 120,925,125, which converts back to 49,999,999 ns: a hold that left at exactly that count would print one nanosecond under what the judge demands. It loops on the nanoseconds it prints. Two comments that said their neighbours again go: `mask-windows`' reason in `src/build.rs`, which `kernel/Cargo.toml` states, and `virt_mask_windows`' row comment, which its function's doc states. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- kernel/src/windows.rs | 11 +++++----- src/build.rs | 3 --- tests/checks.rs | 25 +++++++++++++-------- tests/common/irqcensus.rs | 35 +++++++++++++++++------------- tests/metal/lenovo-20w0003amz.toml | 3 +++ tests/toyos.rs | 19 ++++++---------- 6 files changed, 52 insertions(+), 44 deletions(-) diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index a24da1575cc..2b7e5eef161 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -130,11 +130,12 @@ pub fn hold_once() { return; } let from = cpu::counter(); - let owed = crate::clock::counter_ticks(HELD_NS); - let mut held = 0; - while held < owed { + let mut ns = 0; + // In the nanoseconds it prints: a tick count that stands for `HELD_NS` can + // convert back to one less. + while ns < HELD_NS { core::hint::spin_loop(); - held = cpu::counter() - from; + ns = crate::clock::nanos_of_ticks(cpu::counter() - from); } - crate::log!("windows: held cpu{} ns={}", percpu::cpu_id(), crate::clock::nanos_of_ticks(held)); + crate::log!("windows: held cpu{} ns={ns}", percpu::cpu_id()); } diff --git a/src/build.rs b/src/build.rs index d27d5220fd5..6536f543ee7 100644 --- a/src/build.rs +++ b/src/build.rs @@ -2648,9 +2648,6 @@ mod tests { "lock-acquire-off", "log-commit-release-off", "loom", - // The longest interrupts-off and preemption-off windows: a - // counter read on every masking transition and entry, so its - // own build and never one being measured for anything else. "mask-windows", // `heap-lockspin`'s other arm: the same visit to the pass path, // for the same span, without the allocator's lock. diff --git a/tests/checks.rs b/tests/checks.rs index 995f0b00ce0..fbc4f576194 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -397,7 +397,7 @@ mod checks { } /// [`mask_windows`] and `irqcensus::windows_under` against captures no - /// boot has to produce: two CPUs and the T14 row's four exits, a report + /// boot has to produce: two CPUs and the T14 row's three exits, a report /// each, with cpu1 holding at the first. #[test] fn mask_windows_verdict() -> Result<(), String> { @@ -420,8 +420,7 @@ mod checks { let read_back = (held_ns + 400, held_ns + 300); let opening = [report((100, 100), read_back), exit("pwd")].concat(); let own = [report((3_000_000, 1_100_000), (700_000, 600_000)), exit(WINDOWS_LOAD)].concat(); - let after = [report((300, 200), (2_000_000, 1_900_000)), exit("echo")].concat(); - let good = [hold.as_str(), &first, &opening, &own, &after].concat(); + let good = [hold.as_str(), &first, &opening, &own].concat(); let exited = windows_load_exited(); mask_windows(&good, 2).map_err(|e| format!("the good capture was refused: {e}"))?; @@ -436,7 +435,7 @@ mod checks { unpaired("a field missing", &good.replace(" preempt_off_ns=100", ""), "fields")?; let read = windows_under(&good, 2, &exited)?; - let want = Measured { held: read_back, load: (3_000_000, 1_900_000) }; + let want = Measured { held: read_back, load: (3_000_000, 1_100_000) }; if read != want { return Err(format!("the good capture read {read:?}, and the hold's and the load's reports say {want:?}")); } @@ -445,9 +444,7 @@ mod checks { Err(e) if e.contains(says) => Ok(()), Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")), }; - refused("the load's report alone", &own, "the boot's first")?; - refused("a load's report with none before it", &[hold.as_str(), &own, &after].concat(), "the boot's first")?; - refused("no report after the load's exit", &good.replace(&after, ""), "no report after")?; + refused("a load's report with none before it", &[hold.as_str(), &own].concat(), "the boot's first")?; refused("a load that never ended", &good.replace(&exit(WINDOWS_LOAD), ""), "never ended")?; refused("no hold", &good.replace(&hold, ""), "held no window of known length")?; refused("a second hold", &[hold.as_str(), &good].concat(), "a second hold")?; @@ -462,12 +459,22 @@ mod checks { &good.replace(&windows(1, read_back), &windows(1, (read_back.0, read_back.1 / 2))), "shorter than it was held", )?; + refused( + "an interrupts-off window read back at ten times", + &good.replace(&windows(1, read_back), &windows(1, (read_back.0 * 10, read_back.1))), + "past the ceiling", + )?; + refused( + "a preemption-off window read back at ten times", + &good.replace(&windows(1, read_back), &windows(1, (read_back.0, read_back.1 * 10))), + "past the ceiling", + )?; refused( "a hold the load's own report reads back", - &[first.as_str(), &opening, &hold, &own, &after].concat(), + &[first.as_str(), &opening, &hold, &own].concat(), "reported nothing between", )?; - refused("a report that skips a CPU", &good.replace(&windows(0, (300, 200)), ""), "names cpu1 at place 0")?; + refused("a report that skips a CPU", &good.replace(&windows(0, (3_000_000, 1_100_000)), ""), "names cpu1 at place 0")?; Ok(()) } diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index 2b4d583e361..d317a468056 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -197,22 +197,23 @@ pub fn windows(capture: &str) -> Result, String> { pub struct Measured { /// What the holding CPU reported between its hold and the load's start. pub held: (u64, u64), - /// What any CPU closed under the load. + /// What any CPU closed in the load's own report. pub load: (u64, u64), } /// The durations a machine's boot is judged by, read from the reports of -/// `cpus` CPUs around the record `load_exited` heads, the load's exit. +/// `cpus` CPUs before the record `load_exited` heads, the load's exit. /// -/// **The load's reading is its own.** A report carries what closed since the -/// report before, and the load's exit prints one before it tears the process -/// down. So the reading is that report and the next, which carries the -/// teardown, and it is refused unless a report before them emptied every CPU's -/// record as the load started. +/// **The load's reading is its own report alone.** A report carries what +/// closed since the report before, and the load's exit prints one before it +/// tears the process down. So that report spans the teardown of the job +/// before, the runner's spawn of the load and the load up to its exit, and it +/// is refused unless a report before it emptied every CPU's record. /// /// **A window of known length is read back.** The kernel held both of one /// CPU's windows for the span its held line states: that CPU's reports from -/// there to the load's start carry a window of each kind no shorter. +/// there to the load's start carry a window of each kind no shorter, and none +/// past `metaltimings::ceiling` of it. pub fn windows_under(capture: &str, cpus: u32, load_exited: &str) -> Result { let mut reports: Vec<(usize, Vec)> = Vec::new(); let mut open: Vec = Vec::new(); @@ -247,9 +248,6 @@ pub fn windows_under(capture: &str, cpus: u32, load_exited: &str) -> Result| { lines.fold((0, 0), |(irqs, preempt), w| (irqs.max(w.irqs_off_ns), preempt.max(w.preempt_off_ns))) }; @@ -271,14 +269,21 @@ pub fn windows_under(capture: &str, cpus: u32, load_exited: &str) -> Result ceiling || held.1 > ceiling { return Err(format!( - "cpu{cpu} held both windows for {ns} ns, and its reports before the load's read back \ - irqs_off_ns={} preempt_off_ns={}: a window was reported shorter than it was held", - held.0, held.1 + "{read}, past the ceiling of {ceiling}: a window was reported at more than twice what was held" )); } - let load = longest(&mut reports[own].1.iter().chain(&after.1)); + let load = longest(&mut reports[own].1.iter()); Ok(Measured { held, load }) } diff --git a/tests/metal/lenovo-20w0003amz.toml b/tests/metal/lenovo-20w0003amz.toml index 501e12cc8cc..38f0210185c 100644 --- a/tests/metal/lenovo-20w0003amz.toml +++ b/tests/metal/lenovo-20w0003amz.toml @@ -73,6 +73,9 @@ bios = "N34ET71W (1.71 )" "boot.usbload.complete_ms" = 1165 "boot.usbload.panel_max_us" = 3837 "boot.usbload.panel_us" = 21428 +"boot.windowscase.complete_ms" = 1152 +"boot.windowscase.panel_max_us" = 3825 +"boot.windowscase.panel_us" = 21453 "latency.p99_us" = 16 "tlb.latencycase.p50_ns" = 2194 "tlb.latencycase.p99_ns" = 3740 diff --git a/tests/toyos.rs b/tests/toyos.rs index fc5a2dde02a..14c6e065721 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -161,8 +161,6 @@ const SCREEN_TESTS: &[(&str, qemu::Profile)] = &[ ("virt_unmap_touch", qemu::Profile::VirtEl2), ("virt_debug_refused", qemu::Profile::VirtEl2), ("virt_readonly_copyout", qemu::Profile::VirtEl2), - // The windows on AArch64, on eight CPUs: every hook's check, and the lines - // each report carries; no clock. ("virt_mask_windows", qemu::Profile::VirtEl2), ("virt_smp", qemu::Profile::VirtEl2), ("virt_el1_smp", qemu::Profile::VirtTcg), @@ -250,7 +248,7 @@ const METAL: &[(&str, metal::Metal)] = &[ ), ( // The windows on the machine that owes them: every CPU reported beside - // its census, a held window read back, and the herd's own recorded. + // its census, and a held window read back. "mask_windows", metal::Metal { arms: WINDOWSCASE, judge: |b| windows_on_metal(b[0]) }, ), @@ -664,17 +662,16 @@ const TESTCASES_READDIR: &[metal::Arm] = const JOBCASE: &[metal::Arm] = &[metal::once("jobcase", "tests/jobcase", &[], &[])]; /// The shipping kernel with the windows' instrument and nothing else, so what -/// it reads is that kernel under the herd. Four exits, a report each: +/// it reads is that kernel under the herd. Three exits, a report each: /// `idle_span`'s is the boot's first, where the kernel holds; `pwd`'s reads the -/// hold back and empties every record as the herd starts; the herd's and -/// `echo`'s are the herd's reading, the second carrying its teardown. +/// hold back and empties every record; the herd's is the herd's reading. const WINDOWSCASE: &[metal::Arm] = &[metal::Arm { features: toyos_build::build::MASK_WINDOWS_KERNEL, ..metal::once( "windowscase", "tests/testcases", &[], - &["test_rs_idle_span", "pwd", WINDOWS_LOAD, "echo"], + &["test_rs_idle_span", "pwd", WINDOWS_LOAD], ) }]; @@ -2491,7 +2488,8 @@ fn irq_census(capture: &str) -> Result<(), String> { } /// The T14's windows: [`mask_windows`]' verdict with every CPU reporting, and -/// `common::irqcensus::windows_under`'s durations, recorded. +/// `common::irqcensus::windows_under`'s. Its durations are printed and none is +/// recorded: one boot's longest window is no baseline for the next. fn windows_on_metal(boot: &metal::Readback) -> Result<(), String> { boot.job_passed(WINDOWS_LOAD)?; let kernel = boot.kernel(); @@ -2502,10 +2500,7 @@ fn windows_on_metal(boot: &metal::Readback) -> Result<(), String> { " [windows] held irqs_off_ns={} preempt_off_ns={}; herd irqs_off_ns={} preempt_off_ns={}", read.held.0, read.held.1, read.load.0, read.load.1 ); - boot.measured("windows.windowscase.held_irqs_off_ns", read.held.0)?; - boot.measured("windows.windowscase.held_preempt_off_ns", read.held.1)?; - boot.measured("windows.windowscase.herd_irqs_off_ns", read.load.0)?; - boot.measured("windows.windowscase.herd_preempt_off_ns", read.load.1) + Ok(()) } fn pci_cap_selftest(log: &str) -> Result<(), String> { From 0aa8d4c88bd845b45997fe83bf976cb788170caf Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 2 Oct 2026 21:37:26 +0200 Subject: [PATCH 12/13] The three boots at 8b73eba69 enter the issues they answer, and the spawning CPU's window is filed Each of three issue files said what the row's new reports would tell, and the T14's three boots at 8b73eba69 (comment 5959415453 on #649) have told it: cpu0's 6.5 ms window is in the first report and nothing like it after; the 10 to 11 ms reading falls after `echo`'s report, on the `reboot` and stop side; and the herd's own report reads 1.0 to 1.2 ms of interrupts off at N = 256. One window those boots measured was filed nowhere: cpu7, which test-runner spawns from, reads 1,379,642 to 1,499,808 ns of interrupts and preemption off in each report that spans the spawn of a toybox applet. The track's step 2: the exit's first half, a window of known length read back on the T14, is met and no longer rests on rows in the machine's record. The comparison stays its open exit. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...alk-by-the-threads-it-parks-on-one-ring.md | 19 +++++--- ...nd-preemption-off-for-6-5-ms-on-the-t14.md | 12 +++-- ...n-interrupts-off-window-of-9-ms-or-more.md | 15 ++++-- ...nterrupts-and-preemption-off-on-the-t14.md | 46 +++++++++++++++++++ ...-small-interrupts-post-and-threads-wait.md | 8 ++-- 5 files changed, 84 insertions(+), 16 deletions(-) create mode 100644 issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md diff --git a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md index 06f15a44644..448f449cd92 100644 --- a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md +++ b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md @@ -37,13 +37,18 @@ exit (`issues/kernel/syscall-preemption-is-incidental.md`), with #634 and without it: #634 did not mask it, and reverting #634 does not shorten it. The second runs in the device's handler since #634. -How long either is has not been read. The eight T14 boots of #649 at -`72f16e39a` ran the first with N = 256 (`test_rs_ring_park_herd`), but each -printed one report, which spans every window since its CPU joined the -scheduler, and none took an interrupt a handler #634 changed serves -(`userdev=0 sound=0 dmafault=0 hda=0` on every CPU). They bound it from -above: in the six boots no longer window covers, the seven CPUs other than -cpu0 read 251,452 to 4,720,498 ns of interrupts off. +How long the second is has not been read. The first has, at one size: the +three T14 boots of #649 at `8b73eba69` (comment 5959415453, readbacks +`649-r5/1-head`, `649-r5/2-report-halved`, whose kernel prints half of every +span, and `649-r5/3-idle-halt-counted`) ran it with N = 256 +(`test_rs_ring_park_herd`) and read it from the herd's own report, which +spans the runner's spawn of the herd as well. The longest `irqs_off_ns` on +any CPU there is 1032292 (`windowscase/kernel.log:428`), 2 × 519358 (`:426`) +and 1175943 (`:430`). The third is cpu7's, the CPU that spawned the herd +(`issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md`), +and the other seven read 257646 to 364953 in that boot. None of the three +took an interrupt a handler #634 changed serves +(`userdev=0 sound=0 dmafault=0 hda=0` on every CPU). **Exit**: the interrupts-off window step 2's instrument reads on the T14 under N threads parked in `submit` on one ring, a sibling thread completing diff --git a/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md b/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md index ed7f668e280..19ebc5402e4 100644 --- a/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md +++ b/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md @@ -43,9 +43,15 @@ Nothing names what opens it. A report carries a span and no address, and one report a boot cannot say whether the window recurs. What will: the record keeping, beside each CPU's longest span, the address its opening hook was called from, printed in the report and resolved through the kernel's symbols. -The row's first report now ends at its first job's exit, half a second after -the CPUs join, and no longer at the herd's: it says whether the window opens -before that, and no more. + +It opens before the boot's first job ends. The three boots of #649 at +`8b73eba69` (comment 5959415453, readbacks `649-r5/1-head`, +`649-r5/2-report-halved`, whose kernel prints half of every span, and +`649-r5/3-idle-halt-counted`) print a report at each of four exits. cpu0's +`irqs_off_ns` in the first, at `test_rs_idle_span`'s exit 1.746 s into the +boot (`windowscase/kernel.log:348` in each), reads 6533222, 2 × 3273547 and +6508165. In the three reports after it cpu0 reads at most 943904, 2 × 472938 +and 345229. **Exit**: the section that opens the window is named by that reading on the T14, and cpu0's longest window there no longer includes it, or this file is diff --git a/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md b/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md index 6f64bff0eac..830244ca0ea 100644 --- a/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md +++ b/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md @@ -56,9 +56,18 @@ inside a shootdown would read as the fourth boot does. Nothing names what opens any of them. A report carries a span and no address, and no time: eight equal spans are not shown to be one event. What will: the record keeping, beside each CPU's longest span, the address its opening hook -was called from and the counter it closed at, printed in the report. The row -now takes a report after the herd's exit and before `reboot` is spawned, -which says on which side of that the third reading falls. +was called from and the counter it closed at, printed in the report. + +The third reading falls on the `reboot` and stop side of the herd's +teardown. The three boots of #649 at `8b73eba69` (comment 5959415453, +readbacks `649-r5/1-head`, `649-r5/2-report-halved`, whose kernel prints half +of every span, and `649-r5/3-idle-halt-counted`) took a report at `echo`'s +exit, after the herd's and before `reboot` was spawned. Its longest +`irqs_off_ns` is cpu7's in each: 1499808, 2 × 748872 and 1479558 +(`windowscase/kernel.log:456`). The stop's report after it, in the six lines +the black box keeps, reads cpu7 11522834 and cpu4 11645411 in the first boot +(`649-r5/1-head/windowscase/loader.log:57`, `:63`), and at most cpu7's +2 × 3799327 in the second and cpu7's 1305656 in the third. **Exit**: each of the three is named by that reading on the T14, and is removed, or this file is replaced by the bound it is held to and the diff --git a/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md b/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md new file mode 100644 index 00000000000..67e12402c90 --- /dev/null +++ b/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md @@ -0,0 +1,46 @@ +--- +status: open +kind: defect +opened: 2026-10-02 +--- + +# The CPU that spawns a toybox applet reads 1.4 ms of interrupts and preemption off on the T14 + +Read by the `mask-windows` kernel (`kernel/src/windows.rs`) on LENOVO +20W0003AMZ, BIOS N34ET71W (1.71), in the three `mask_windows` boots of #649 +at `8b73eba69` (comment 5959415453, readbacks `649-r5/1-head`, +`649-r5/2-report-halved`, whose kernel prints half of every span, and +`649-r5/3-idle-halt-counted`, whose kernel counts the idle halt as a +preemption-off window). + +test-runner spawned every job from cpu7: each `spawn:` record of a job is +cpu7's. Two reports a boot span the spawn of a toybox applet and of nothing +else, `pwd`'s and `echo`'s. cpu7's line in each +(`windowscase/kernel.log:388` and `:456`): + +| boot | report | `irqs_off_ns` | `preempt_off_ns` | +|---|---|---|---| +| `1-head` | `pwd`'s | 1408843 | 1408557 | +| `1-head` | `echo`'s | 1499808 | 1499590 | +| `2-report-halved` | `pwd`'s | 2 × 737408 | 2 × 737277 | +| `2-report-halved` | `echo`'s | 2 × 748872 | 2 × 748704 | +| `3-idle-halt-counted` | `pwd`'s | 1379642 | 536504022, a halt | +| `3-idle-halt-counted` | `echo`'s | 1479558 | 1479398 | + +- The two kinds differ by 160 to 336 ns in the five rows that have both, so + one section holds both. +- No other CPU reads as much in `echo`'s report: 947018 at most. +- It is the floor under a load's reading on that CPU. A load's own report + spans the runner's spawn of it, and in the herd's cpu7 reads 1019488, + 2 × 514392 and 1175943, the last the longest line of its report by three + times. + +By reading, not measured: it is `SYS_SPAWN`, which runs with interrupts +masked from entry to exit like every syscall +(`issues/kernel/syscall-preemption-is-incidental.md`), and whose own record +reads `total=1ms` for each of these applets. A report carries a span and no +address, so nothing names it. + +**Exit**: the section is named on the T14 by the address its opening hook was +called from, and the spawning CPU's longest window no longer includes it, or +this file is replaced by the bound it is held to and the derivation of it. diff --git a/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md b/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md index 3b3c48ee521..60ae398449a 100644 --- a/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md +++ b/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md @@ -169,9 +169,11 @@ times: windows per CPU, reported beside the IRQ census and fed by each architecture's masking primitives and entries, the number the ARM track's stage 4 owes as well. Built: the `mask-windows` kernel and the - T14's `mask_windows` row. **Exit**, open: the instrument reads back a - window of known length on the T14, which is x86 metal, and its rows are - in that machine's record; and neither window is longer with step 1 than + T14's `mask_windows` row. The exit's first half is met: the instrument + reads back a window of known length on the T14, which is x86 metal, and + the row's judge refuses a boot that reads it back shorter than it was + held or at more than twice that. **Exit**, open: neither window is + longer with step 1 than with it reverted on the tree that carries the instrument, the patch posted on #649 being what reverted means. That comparison is the median of at least five interleaved boots an arm, each read from the load's own From b6635359ac1b34ac53267b0de1b4498f9b6a236e Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 2 Oct 2026 22:28:00 +0200 Subject: [PATCH 13/13] The three boots at 0aa8d4c88 enter the issues they answer, and virt_smp's line is main's again The named changes of #649's third review (comment 5960868119). tests/toyos.rs: the merge of dd8738302 took a space out of a line of #647's in `virt_smp`. It is main's line again, so the file's diff against main is this branch's alone. The herd's defect: its own report at N = 256 read 1980239, 2 x 5075290 and 4725822 in this head's three T14 boots (comment 5960575031, readbacks 649-r6/), against 1032292, 2 x 519358 and 1175943 at 8b73eba69. One reading a size is decided by which boot carried one of the machine's own events, so the exit takes the track's statistic: the median of at least five boots a size, the tail beside it. The roster's syscall counts are said of the fourteen boots they are the range of. The 9 ms defect: its first reading recurred in 2-report-halved inside the herd's own report, all eight CPUs at 2 x 5014552 to 2 x 5075290 with the shootdown line's max=10038us beside it and nmi=1; and cpu7's line of the first report read 11492028, 2 x 1308074 and 8456658, where the stop's kept lines read at most 1396887, 2 x 758960 and 1470910. The exit covers the one-CPU reading before the first job's exit as well. The spawning CPU's defect: cpu7's line of the herd's report read 1980239 in 1-head, 468787 past the 1511452 that boot's `pwd` report reads for an applet's spawn. No byte of an image moves: the three boots at 0aa8d4c88 stand for this head if its staged kernel is the one 1-head booted. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...alk-by-the-threads-it-parks-on-one-ring.md | 30 +++++++++++++++---- ...n-interrupts-off-window-of-9-ms-or-more.md | 26 ++++++++++++++-- ...nterrupts-and-preemption-off-on-the-t14.md | 7 +++++ tests/toyos.rs | 2 +- 4 files changed, 55 insertions(+), 10 deletions(-) diff --git a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md index 448f449cd92..f20f0f83ec1 100644 --- a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md +++ b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md @@ -46,14 +46,32 @@ spans the runner's spawn of the herd as well. The longest `irqs_off_ns` on any CPU there is 1032292 (`windowscase/kernel.log:428`), 2 × 519358 (`:426`) and 1175943 (`:430`). The third is cpu7's, the CPU that spawned the herd (`issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md`), -and the other seven read 257646 to 364953 in that boot. None of the three +and the other seven read 257646 to 364953 in that boot. + +The three at `0aa8d4c88` (comment 5960575031, readbacks `649-r6/1-head`, +`649-r6/2-report-halved` and `649-r6/3-idle-halt-counted`, the same two +mutated kernels) read the same report of the same load at 1980239 +(`windowscase/kernel.log:430`), 2 × 5075290 (`:422`) and 4725822 (`:416`): + +- 1980239 is cpu7's, which spawned the herd (`:395`). The other seven read + 969922 to 1044783. +- 2 × 5075290 is one of eight: every CPU reads 2 × 5014552 to 2 × 5075290 + (`:416` to `:430`), beside `tlb: shootdowns=282 wait=131633us max=10038us` + (`:431`). It is the first reading of + `issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md`. +- 4725822 is cpu0's. The other seven read 544283 to 1018355. + +So one size reads 1.03 to 10.15 ms over six boots, and which boot carried +one of the machine's own events decides a single reading. None of the six took an interrupt a handler #634 changed serves (`userdev=0 sound=0 dmafault=0 hda=0` on every CPU). **Exit**: the interrupts-off window step 2's instrument reads on the T14 under N threads parked in `submit` on one ring, a sibling thread completing -into it, does not grow with N: read at two sizes on one kernel, each from the -load's own report. `ring_park_herd`'s sibling waits on the kernel's roster, -which is itself a masked walk over every thread of the machine (3,619 to -4,111 `SYS_SYSINFO` calls a run in those boots, and 768 to 847 ms of syscall -wall in a run of 0.9 s), so that reading has to tell the two walks apart. +into it, does not grow with N: read at two sizes on one kernel, each size the +median of at least five boots, each boot from the load's own report, with +the tail reported beside it. `ring_park_herd`'s sibling waits on the kernel's +roster, which is itself a masked walk over every thread of the machine (3,619 +to 4,111 `SYS_SYSINFO` calls a run in #649's fourteen T14 boots, and 768 to +847 ms of syscall wall in a run of 0.9 s), so that reading has to tell the +two walks apart. diff --git a/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md b/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md index 830244ca0ea..8d70322a2f2 100644 --- a/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md +++ b/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md @@ -69,6 +69,26 @@ the black box keeps, reads cpu7 11522834 and cpu4 11645411 in the first boot (`649-r5/1-head/windowscase/loader.log:57`, `:63`), and at most cpu7's 2 × 3799327 in the second and cpu7's 1305656 in the third. -**Exit**: each of the three is named by that reading on the T14, and is -removed, or this file is replaced by the bound it is held to and the -derivation of it. +The three boots at `0aa8d4c88` (comment 5960575031, readbacks +`649-r6/1-head`, `649-r6/2-report-halved` and `649-r6/3-idle-halt-counted`, +the same two mutated kernels) print a report at three exits, `idle_span`'s, +`pwd`'s and the herd's, and at the stop: + +- **The first reading recurred, inside the herd's own report**, which opens + at `pwd`'s exit. In `2-report-halved` every CPU reads 2 × 5014552 to + 2 × 5075290 (`windowscase/kernel.log:416` to `:430`), beside + `tlb: shootdowns=282 wait=131633us max=10038us` (`:431`): the shootdown's + `max` is beside it again, 9575us then and 10038us now, and cpu0's second + NMI is not: `nmi=1` (`:415`). That is two boots of #649's fourteen. +- **One CPU, before the first job's exit.** cpu7's line of the first report, + `idle_span`'s (`:362`), reads 11492028 in `1-head`, 2 × 1308074 in + `2-report-halved` and 8456658 in `3-idle-halt-counted`, beside + `max=1655us`, `max=1451us` and `max=1353us` (`:363`). The same line read + 2327848, 2 × 1831727 and 3630933 at `8b73eba69`. +- **Nothing after the herd's report.** The stop's report, in the six lines + the black box keeps, reads at most cpu7's 1396887, 2 × 758960 and 1470910 + (`windowscase/loader.log:57`). + +**Exit**: each of the three, and the one-CPU reading before the first job's +exit, is named by that reading on the T14, and is removed, or this file is +replaced by the bound it is held to and the derivation of it. diff --git a/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md b/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md index 67e12402c90..6dd9368537b 100644 --- a/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md +++ b/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md @@ -34,6 +34,13 @@ else, `pwd`'s and `echo`'s. cpu7's line in each spans the runner's spawn of it, and in the herd's cpu7 reads 1019488, 2 × 514392 and 1175943, the last the longest line of its report by three times. +- It is not all that line reads. In the three boots at `0aa8d4c88` (comment + 5960575031, readbacks `649-r6/1-head`, `649-r6/2-report-halved` and + `649-r6/3-idle-halt-counted`, the same two mutated kernels) `pwd`'s report + reads cpu7 at 1511452, 2 × 740441 and 1360995 + (`windowscase/kernel.log:388`), and the herd's reads it at 1980239 in + `1-head` (`:430`): 468787 past that boot's applet spawn, which the spawn + does not account for and nothing names. By reading, not measured: it is `SYS_SPAWN`, which runs with interrupts masked from entry to exit like every syscall diff --git a/tests/toyos.rs b/tests/toyos.rs index 14c6e065721..9081943e0fa 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1480,7 +1480,7 @@ fn virt_smp(profile: qemu::Profile, conduit: &str, el: u32) -> Result<(), String // 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 psci =serial.lines().find(|l| l.contains("PSCI: ")).unwrap_or_default(); + 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}")); }