From 15c32ad3bf84e9f40fdaf5013150a542dc516192 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 08:37:42 +0200 Subject: [PATCH 1/8] Latency step 2, A1: a syscall's body runs with interrupts open The x86 SYSCALL gate and the AArch64 SVC path open interrupts right after the syscall bracket is entered and close them before it is left; the asm `cli` before `exit_to_user` goes, its reason moving to the Rust close. Preemption is unchanged: a syscall body still runs at preempt depth one, and an expiry or kick inside it only sets need_resched for the exit. The Ring 0 timer expiry re-arms one quantum on (x86: TIMER_TICKS, the calibrated 10 ms count; AArch64: a comparator write that leaves armed_ticks alone), or leaves a stopped timer stopped, so a long syscall takes one expiry per quantum and not one per armed span. Beside it: a handler witness under mask-windows (a sync::Lock taken in a maskable handler body panics, IrqLocks exempt through Lock::lock_masked, stood down on every fatal path); the boot deadline's seal names where each CPU's timer last found the kernel; hold_once masks for itself; the exit pass masks as leave_user_if_due's does; usb_gate's IF dance goes; the wedge judge requires the staging CPU awake and refuses the deaf line; RING0_TIMER_IN_SYSCALL (debug action 26) and its guest test on both architectures; an x86 mask_windows guest row; cyclictest prints its worst wake's time and the SMI counts around its run; counters_metal reads kick lateness under a spawn load. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- issues/hardware/xhci-waits-are-spins.md | 33 +++---- ...alk-by-the-threads-it-parks-on-one-ring.md | 9 +- ...disk-left-a-cpu-deaf-to-a-tlb-shootdown.md | 6 +- ...ck-is-zeroed-twice-with-preemption-off.md} | 6 +- .../syscall-preemption-is-incidental.md | 39 +++----- ...nterrupts-and-preemption-off-on-the-t14.md | 10 +- ...-clear-and-two-callers-spin-with-it-set.md | 22 ----- ...4-lacks-holds-interrupts-off-for-3-8-ms.md | 4 + kernel/loom/Cargo.toml | 2 +- kernel/pure/sched/cpu.rs | 4 +- kernel/pure/sched/mailbox.rs | 5 +- kernel/src/arch/aarch64/irqchip.rs | 48 +++++++-- kernel/src/arch/aarch64/percpu.rs | 2 +- kernel/src/arch/aarch64/trap.rs | 66 +++++++++---- kernel/src/arch/x86_64/apic.rs | 18 +++- kernel/src/arch/x86_64/idt/device_irq.rs | 2 + kernel/src/arch/x86_64/idt/spurious.rs | 10 +- kernel/src/arch/x86_64/idt/timer.rs | 29 ++++-- kernel/src/arch/x86_64/idt/unclaimed.rs | 10 +- kernel/src/arch/x86_64/percpu.rs | 4 +- kernel/src/arch/x86_64/syscall.rs | 7 +- kernel/src/deadline.rs | 68 +++++++++---- kernel/src/drivers/xhci/mod.rs | 4 +- kernel/src/drivers/xhci/wait/msc.rs | 3 +- kernel/src/main.rs | 3 + kernel/src/mm/unmapped.rs | 2 +- kernel/src/panic.rs | 2 + kernel/src/process.rs | 8 +- kernel/src/scheduler.rs | 2 + kernel/src/shootdown.rs | 2 +- kernel/src/sync.rs | 25 ++++- kernel/src/syscall/debug.rs | 24 +++++ kernel/src/syscall/dispatch.rs | 4 +- kernel/src/syscall/vm.rs | 4 +- kernel/src/usb_gate.rs | 16 +-- kernel/src/watch.rs | 4 +- kernel/src/windows.rs | 62 +++++++++++- src/bootlog.rs | 20 ++-- tests/checks.rs | 20 ++-- tests/common/power.rs | 24 +++-- tests/latencycase/system.toml | 3 +- .../src/bin/counters_metal.rs | 99 ++++++++++++++++++- tests/toyos-rust-tests/src/bin/cyclictest.rs | 42 +++++++- .../src/bin/ring0_timer_in_syscall.rs | 20 ++++ tests/toyos.rs | 65 +++++++++++- tests/virtjobcase/system.toml | 11 ++- toyos-abi/src/syscall.rs | 8 ++ 47 files changed, 666 insertions(+), 215 deletions(-) rename issues/kernel/{a-tls-block-is-zeroed-twice-with-interrupts-masked.md => a-tls-block-is-zeroed-twice-with-preemption-off.md} (75%) delete mode 100644 issues/kernel/the-lock-spins-shootdown-poll-says-if-is-clear-and-two-callers-spin-with-it-set.md create mode 100644 tests/toyos-rust-tests/src/bin/ring0_timer_in_syscall.rs diff --git a/issues/hardware/xhci-waits-are-spins.md b/issues/hardware/xhci-waits-are-spins.md index 24edf64406..50bf8a3a69 100644 --- a/issues/hardware/xhci-waits-are-spins.md +++ b/issues/hardware/xhci-waits-are-spins.md @@ -4,7 +4,7 @@ kind: defect opened: 2026-08-03 --- -# The xHCI driver's waits are spins, and a USB disk call spins with interrupts masked +# The xHCI driver's waits are spins, under a lock and with preemption off Every wait in the kernel's xHCI driver spins against a wall-clock deadline while holding `XHCI` (`kernel/src/drivers/xhci/mod.rs`), a ticket spinlock and @@ -19,24 +19,21 @@ and a disk call. A call on a USB disk holds `XHCI` from its first command (`with_disk`, `kernel/src/drivers/xhci/wait/msc.rs`) inside a syscall, which runs with -interrupts masked from entry to exit -(`issues/kernel/syscall-preemption-is-incidental.md`): a partition claim's +preemption off from entry to exit and, since the gate opens them, interrupts +on (`issues/kernel/syscall-preemption-is-incidental.md`): a partition claim's `SYS_PARTITION_READ`, `SYS_PARTITION_WRITE` and `SYS_FSYNC`, the last a cache flush through `xhci::storage_flush` (`partition_fsync`, `kernel/src/object/ops.rs`), and the table `SYS_DEVICE_CLAIM` reads for one (`gpt::claimable`, `kernel/src/gpt.rs`). logd's `fsync` is one of these: the LOG fsd answers each with `SYS_FSYNC` on its claim. So its CPU holds -interrupts and preemption off for as long as the device takes, and a CPU whose -TLB shootdown waits on that CPU's acknowledgement spins as long, masked. +preemption off for as long as the device takes. A disk's bind after boot +spins inside the Ring 3 tick's pass, which runs with interrupts masked, and +`time::DEAF_CPU` (5 s), past which a CPU waiting on a TLB acknowledgement +panics, is held above `CALL_AFTER_BREAK` (4.75 s), the longest one call spins +once its transport has broken. -**Its bound outruns the TLB-ack tripwire.** `time::DEAF_CPU` (5 s), past which -a CPU waiting on an acknowledgement panics, is held above `CALL_AFTER_BREAK` -(4.75 s), the longest a disk call spins once its transport has broken. But that -bound opens at the wait that broke, and `transfer_blocks` starts a batch while -the operation's 2 s `block::OPERATION` has any left: a batch that starts at -1.99 s and breaks runs its ladder to 6.74 s after the operation began, all of -it with `IF` clear. That is arithmetic on the declared constants; no boot has -been seen to do it. +Its "On the T14" readings below were taken while a syscall still ran with +interrupts masked from entry to exit. ## On the T14 @@ -101,11 +98,9 @@ whose step 10 moves the whole xHCI to usbd and deletes the kernel's driver. It owes both exits. **Exit**, two: -- **The tripwire's, short of step 10**: the whole of one operation's `IF`-clear - spin is under `DEAF_CPU` by construction, because the call's bound opens - where the operation opens, or a later batch starts only while a whole call's - bound is still inside it; and a staged boot whose first batch spends most of - the budget and whose next batch breaks shows the operation ending inside - `DEAF_CPU`. +- **The tripwire's, short of step 10**: no disk wait spins with `IF` clear, + because the tick's pass leaves the interrupt gate (step 2 of + `issues/kernel/toyos-beats-linuxs-latency-on-the-t14.md`), and + `kernel/src/drivers/xhci/mod.rs` holds no bound under `DEAF_CPU`. - **The spin's**: the tree has no `kernel/src/drivers/xhci`, so no kernel wait is a USB device's. Step 10 meets both. 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 8e4395730d..a001e0ac70 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 @@ -32,12 +32,11 @@ holder, decides how long a CPU runs with interrupts masked: Nothing caps N: a thread costs its process a 128 KiB kernel stack (`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. +`SYS_INBOX_SUBMIT`, masked by the ring's `IrqLock`. The second runs in the +device's handler since #634. -How long the second is has not been read. The first has, at one size: the +How long the second is has not been read. The first has, at one size, while +syscalls still ran with interrupts masked from entry to exit: 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 diff --git a/issues/kernel/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md b/issues/kernel/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md index 79cca8589e..e788576d9b 100644 --- a/issues/kernel/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md +++ b/issues/kernel/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md @@ -32,7 +32,11 @@ trigger and not the deaf CPU. `issues/hardware/xhci-waits-are-spins.md` carries the arithmetic for one disk operation outrunning `time::DEAF_CPU`; this is a boot that did outrun it, in `quiesce`, across several operations each inside its -own budget. Whether `quiesce` holds `IF` clear between them is not measured. +own budget. Whether `quiesce` holds `IF` clear between them is not measured; +both sightings ran while a syscall's body ran with interrupts masked, and the +shutdown syscall's now runs with them open +(`issues/kernel/syscall-preemption-is-incidental.md`), which no boot has +read since. **Second sighting, with the roles swapped**: `usb_transport_break --nightly` at `e889d03e` (#554), the `AnotherStick` boot (`554r6-usb_transport_break.log` in diff --git a/issues/kernel/a-tls-block-is-zeroed-twice-with-interrupts-masked.md b/issues/kernel/a-tls-block-is-zeroed-twice-with-preemption-off.md similarity index 75% rename from issues/kernel/a-tls-block-is-zeroed-twice-with-interrupts-masked.md rename to issues/kernel/a-tls-block-is-zeroed-twice-with-preemption-off.md index 94f55dcdfe..babe00ddda 100644 --- a/issues/kernel/a-tls-block-is-zeroed-twice-with-interrupts-masked.md +++ b/issues/kernel/a-tls-block-is-zeroed-twice-with-preemption-off.md @@ -4,15 +4,15 @@ kind: defect opened: 2026-10-03 --- -# A TLS block is zeroed twice with interrupts masked +# A TLS block is zeroed twice with preemption off `kernel/src/loader/tls.rs`'s `build_combined` takes its frames from `PageAlloc::new`, which is `pmm::alloc_contiguous`, which zeroes every 2 MiB frame it hands out; then it zeroes the whole block again with `write_bytes`. Every `SYS_THREAD_SPAWN` (`process::spawn_thread`) and every `SYS_SPAWN` -(`loader`) builds one, and a syscall runs with interrupts masked from entry to +(`loader`) builds one, and a syscall runs with preemption off from entry to exit (`issues/kernel/syscall-preemption-is-incidental.md`), so each spawn pays -two writes of the block, at least 2 MiB each, in one interrupts-off window. +two writes of the block, at least 2 MiB each, in one preemption-off window. By reading, not measured. diff --git a/issues/kernel/syscall-preemption-is-incidental.md b/issues/kernel/syscall-preemption-is-incidental.md index 728d8567aa..ea62968e88 100644 --- a/issues/kernel/syscall-preemption-is-incidental.md +++ b/issues/kernel/syscall-preemption-is-incidental.md @@ -4,7 +4,7 @@ kind: defect opened: 2026-07-31 --- -# A syscall runs with interrupts masked, and only incidentally with preemption disabled +# A syscall runs with preemption disabled from entry to exit, only incidentally `syscall_entry` raises the preempt count before `call {handler}` and lowers it after, so `preempt::enable`'s `count() == 0` slow path can never fire inside a @@ -14,23 +14,14 @@ latency by "the longest preempt-disabled section"; in syscall context that section is *the entire syscall*, and the real bound is the next `kernel_exit_to_user_check`. -The preempt count is the weaker of two independent blockers, and it is not the -one that decides the bound. `MSR_FMASK = 0x40200` (`arch/syscall.rs:57`) clears -IF on every SYSCALL entry, and nothing on the straight-line syscall path sets it -again — the only `sti`s in the kernel are `cpu::enable_interrupts` -(`arch/cpu.rs:113`, reached from `trap_dispatch`'s #PF arm and from init), -`kernel_exit_to_user_check`'s own yield window (`arch/idt/mod.rs:232`), and the -idle loop (`sched/driver.rs:494`). With IF=0 the CPU cannot even be *told* to -reschedule: `KernelHw::need_resched` (`hw.rs:96-108`) documents that a remote -CPU's `need_resched` byte is unreachable from here, so a remote request is only -deliverable as a kick IPI — an interrupt the masked target will not take until -it leaves the syscall. - -That makes the entry level's fix ineffective on its own: dropping it around -blocking-capable handler regions cannot move remote RT wake latency at all -while IF stays 0. A fix has to unmask interrupts over those regions — which -means auditing what each one is safe to be interrupted in — or the bound is -accepted and that model corrected. +A syscall's body runs with interrupts open on both architectures: the gate +masks them only from the entry through the user-state save and from the +handler's return to the user return (`kernel/src/arch/x86_64/syscall.rs`, +`kernel/src/arch/aarch64/trap.rs`). A timer's expiry or a kick inside one sets +`need_resched`, which the syscall's exit serves, and the Ring 0 expiry re-arms +one quantum on. What still runs masked is the Ring 3 tick's and kick's pass, +which the handler runs, and the walk under an `IrqWatch`'s lock +(`issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md`). This was masked until the preempt count was made conserved across a context switch (the scheduler's own baselines needed it): before that the count drifted, @@ -43,9 +34,9 @@ step is syscalls running with interrupts on (owner, 2026-10-03). **Exit**, on the T14: the longest interrupts-off window the `mask_windows` row reads under its load (`herd irqs_off_ns=`, printed by `windows_on_metal` in -`tests/toyos.rs`) is no longer than the longest lateness of the timer's -interrupt in Linux's reading of this machine, which that track keeps: a masked -window makes a timer's interrupt late by at most its own length. No figure is -set here. Which of Linux's figures is the bar is that track's open question, -and what the row reads today, and which syscalls those windows are, is in -`issues/hardware/xhci-waits-are-spins.md`, "On the T14". +`tests/toyos.rs`) is no longer than 131 µs, the track's ruled bar: a masked +window makes a timer's interrupt late by at most its own length. The row +cannot read it before step 1: a `mask-windows` kernel charges each of the +firmware's 4.5 ms SMIs +(`issues/hardware/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md`) +to whatever window it lands in. 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 6dd9368537..f02c3cd2d2 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 @@ -42,11 +42,13 @@ else, `pwd`'s and `echo`'s. cpu7's line in each `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 -(`issues/kernel/syscall-preemption-is-incidental.md`), and whose own record +By reading, not measured: it is `SYS_SPAWN`, which ran with interrupts +masked from entry to exit like every syscall then, and whose own record reads `total=1ms` for each of these applets. A report carries a span and no -address, so nothing names it. +address, so nothing names it. A syscall's body now runs with interrupts open +(`issues/kernel/syscall-preemption-is-incidental.md`) and preemption off, so +by reading the section leaves `irqs_off_ns` and stays in `preempt_off_ns`; +no T14 boot has read it since. **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 diff --git a/issues/kernel/the-lock-spins-shootdown-poll-says-if-is-clear-and-two-callers-spin-with-it-set.md b/issues/kernel/the-lock-spins-shootdown-poll-says-if-is-clear-and-two-callers-spin-with-it-set.md deleted file mode 100644 index 5aa7a0976a..0000000000 --- a/issues/kernel/the-lock-spins-shootdown-poll-says-if-is-clear-and-two-callers-spin-with-it-set.md +++ /dev/null @@ -1,22 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-09-28 ---- - -# The lock spin's shootdown poll says `IF` is clear, and two of its callers spin with it set - -`Lock::lock` (`kernel/src/sync.rs`) polls TLB shootdowns inside its spin with the -comment "this spin runs with `IF` clear". Two callers spin there with `IF` set: - -- a kernel thread, which `kernel_start` (`arch/x86_64/entry.rs`) enters with `sti`; -- the idle loop, whose `reap_finished` takes `PROCESS_TABLE.lock()`. - -There the 0xFE IPI can land inside `tlb::poll`'s own `serve_if_owed`, so one -CPU runs a serve nested inside another. `Shootdown::serve` raises `flushed` with -`fetch_max` for exactly that case, and `kernel-loom`'s -`a_nested_serve_is_not_undone_by_the_one_it_interrupted` reds when it stores. -The comment gives the poll a reason that holds only for syscall context. - -**Exit**: the comment states when the spin runs with `IF` set and when clear, and -why the poll is needed in each. diff --git a/issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md b/issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md index 4c81434a31..bbcc7e524a 100644 --- a/issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md +++ b/issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md @@ -16,6 +16,10 @@ is in `PciDevice::is_id` under `pcidev::claim`. By reading, the claim reads the vendor ID of each of the 24 functions the kernel enumerated (`kernel/src/pcidev/mod.rs`); nothing has said what it spends 3.8 ms on. +A syscall's body now runs with interrupts open +(`issues/kernel/syscall-preemption-is-incidental.md`), so by reading this +window has left `irqs_off_ns`; no T14 boot has read it since. + Before the first job's exit cpu0 also carries init's partition claims, 6.0 and 6.6 ms in that boot (`issues/hardware/xhci-waits-are-spins.md`), and the `mask-windows` kernel (`kernel/src/windows.rs`) prints each CPU's longest diff --git a/kernel/loom/Cargo.toml b/kernel/loom/Cargo.toml index 15526da33b..7ddba8da50 100644 --- a/kernel/loom/Cargo.toml +++ b/kernel/loom/Cargo.toml @@ -325,4 +325,4 @@ test = false # library's tests and the simulator run. A `cfg` name and not a feature, since a # feature here is a model control. [lints.rust] -unexpected_cfgs = { level = "warn", check-cfg = ['cfg(feature, values("boot-actuators", "sched-check", "sched-tripwire", "protocol-port", "placement-ignores-staleness"))'] } +unexpected_cfgs = { level = "warn", check-cfg = ['cfg(feature, values("boot-actuators", "mask-windows", "sched-check", "sched-tripwire", "protocol-port", "placement-ignores-staleness"))'] } diff --git a/kernel/pure/sched/cpu.rs b/kernel/pure/sched/cpu.rs index 0c9738cbca..c55146863c 100644 --- a/kernel/pure/sched/cpu.rs +++ b/kernel/pure/sched/cpu.rs @@ -705,9 +705,7 @@ pub const PUSH_THRESHOLD: u32 = 2; /// How long a CPU may owe a pass and still be chosen as a target. /// -/// Ten [`QUANTUM_NS`], because one quantum is the whole of what the wake -/// contract promises: a busy CPU drains at its next safe point, and its next -/// safe point is at worst the end of the quantum it is running. +/// Ten [`QUANTUM_NS`]. /// /// **The direction of error is chosen.** Refusing a CPU that was only slow puts /// one task elsewhere; accepting one that has stopped puts the task where diff --git a/kernel/pure/sched/mailbox.rs b/kernel/pure/sched/mailbox.rs index fd5199e4d7..c94b4039a0 100644 --- a/kernel/pure/sched/mailbox.rs +++ b/kernel/pure/sched/mailbox.rs @@ -421,9 +421,8 @@ pub enum Urgency { /// RT wake, boost wake, adopt of an RT task, retire: the target must /// preempt, so the IPI is unconditional. Preempt, - /// Ordinary wake: a busy target drains at its next safe point (≤ one - /// quantum, matching today's contract) and needs no interrupt; a sleeping - /// target is always kicked. + /// Ordinary wake: a busy target drains at its next safe point and needs no + /// interrupt; a sleeping target is always kicked. Normal, } diff --git a/kernel/src/arch/aarch64/irqchip.rs b/kernel/src/arch/aarch64/irqchip.rs index f2faf93cc3..ebef83ce24 100644 --- a/kernel/src/arch/aarch64/irqchip.rs +++ b/kernel/src/arch/aarch64/irqchip.rs @@ -348,14 +348,20 @@ fn floor_ticks() -> u64 { crate::clock::counter_ticks(MIN_ONE_SHOT.nanos()).max(1) } -/// The only write of the comparator: fire `ticks` counter ticks from now, or -/// after [`MIN_ONE_SHOT`] if that is longer, and remember the span as what an -/// EL1 fire re-arms with. Returns the counter value the comparator was set -/// from, for a caller that must relate CVAL back to it without a second read. +/// Fire `ticks` counter ticks from now, or after [`MIN_ONE_SHOT`] if that is +/// longer, and remember the span as what an EL0 fire re-arms with. Returns the +/// counter value the comparator was set from, for a caller that must relate +/// CVAL back to it without a second read. fn arm_ticks(ticks: u64) -> u64 { let ticks = ticks.max(floor_ticks()); percpu::set_armed_ticks(ticks); let now = cpu::counter(); + compare_at(now + ticks); + now +} + +/// The only write of the comparator: fire when the counter reaches `cval`. +fn compare_at(cval: u64) { // SAFETY: the EL1 virtual timer's comparator and control; CPACR has // nothing to say about them and `CNTKCTL_EL1` keeps EL0 out. unsafe { @@ -363,12 +369,11 @@ fn arm_ticks(ticks: u64) -> u64 { "msr cntv_cval_el0, {cval}", "msr cntv_ctl_el0, {enable}", "isb", - cval = in(reg) now + ticks, + cval = in(reg) cval, enable = in(reg) TIMER_ENABLE, options(nomem, nostack, preserves_flags), ); } - now } fn stop_timer_hardware() { @@ -399,6 +404,24 @@ pub fn arm_within(nanos: u64) -> u64 { arm_ticks(want.min(remaining)) } +/// What the timer was last armed with: `CNTV_CVAL_EL0`, the counter value it +/// fires at. +#[cfg(feature = "test-actuators")] +pub fn comparator() -> u64 { + let cval: u64; + // SAFETY: reads the EL1 virtual timer's comparator. + unsafe { core::arch::asm!("mrs {}, cntv_cval_el0", out(reg) cval, options(nomem, nostack, preserves_flags)) }; + cval +} + +/// Whether an EL1 fire since [`comparator`] read `armed` re-armed one quantum: +/// it fired at `armed` or later, so a quantum on from there is at least that +/// far past `armed`. +#[cfg(feature = "test-actuators")] +pub fn rearmed_a_quantum(armed: u64) -> bool { + comparator() >= armed + crate::clock::counter_ticks(kernel::sched::fair::QUANTUM_NS) +} + /// Stop the timer: no interrupt until it is armed again. pub fn stop_timer() { percpu::set_armed_ticks(0); @@ -406,8 +429,8 @@ pub fn stop_timer() { crate::trace::trace(crate::trace::Kind::TimerStop, 0); } -/// A timer interrupt taken: armed again for what it was last armed for, or -/// stopped if it was stopped — the one thing that deasserts it. +/// A timer interrupt taken from EL0: armed again for what it was last armed +/// for, or stopped if it was stopped — the one thing that deasserts it. pub(super) fn rearm() { match percpu::armed_ticks() { 0 => stop_timer_hardware(), @@ -417,6 +440,15 @@ pub(super) fn rearm() { } } +/// A timer interrupt taken at EL1: one quantum on, or stopped if it was +/// stopped, leaving what the scheduler armed for its next pass to re-arm. +pub(super) fn rearm_in_kernel() { + match percpu::armed_ticks() { + 0 => stop_timer_hardware(), + _ => compare_at(cpu::counter() + crate::clock::counter_ticks(kernel::sched::fair::QUANTUM_NS)), + } +} + /// `timer-floor`: this CPU's timer made due with interrupts masked, then /// asked to fire within a quantum, which leaves it nothing to fire within. /// The comparator it is left holding must be at least [`MIN_ONE_SHOT`] past diff --git a/kernel/src/arch/aarch64/percpu.rs b/kernel/src/arch/aarch64/percpu.rs index 0e962409dd..911c709275 100644 --- a/kernel/src/arch/aarch64/percpu.rs +++ b/kernel/src/arch/aarch64/percpu.rs @@ -39,7 +39,7 @@ pub struct PerCpu { kernel_timer_fires: AtomicU32, last_seen_kernel_timer_fires: AtomicU32, /// Counter ticks the timer was last armed for: what a timer interrupt - /// taken at EL1 re-arms it with, and zero when it is stopped. + /// taken at EL0 re-arms it with, and zero when it is stopped. armed_ticks: AtomicU64, /// The kernel stack a switch last installed, for the stack witness: on /// AArch64 an entry from EL0 lands on `SP_EL1` as the last `ERET` left it, diff --git a/kernel/src/arch/aarch64/trap.rs b/kernel/src/arch/aarch64/trap.rs index 69c8f725f9..783f928461 100644 --- a/kernel/src/arch/aarch64/trap.rs +++ b/kernel/src/arch/aarch64/trap.rs @@ -97,10 +97,16 @@ extern "C" fn dispatch(frame: &mut Frame, entry: u64) { match entry { EL1_IRQ => { #[cfg(feature = "mask-windows")] - crate::windows::irqs_masked(); - irq(false); + { + crate::windows::irqs_masked(); + crate::windows::handler_entered(); + } + irq(frame, false); #[cfg(feature = "mask-windows")] - crate::windows::irqs_unmasking(); + { + crate::windows::handler_leaving(); + crate::windows::irqs_unmasking(); + } } EL0_SYNC => { #[cfg(feature = "mask-windows")] @@ -110,8 +116,16 @@ extern "C" fn dispatch(frame: &mut Frame, entry: u64) { } EL0_IRQ => { #[cfg(feature = "mask-windows")] - crate::windows::irqs_masked(); - irq(true); + { + crate::windows::irqs_masked(); + crate::windows::handler_entered(); + } + let preempt = irq(frame, true); + #[cfg(feature = "mask-windows")] + crate::windows::handler_leaving(); + if preempt { + crate::scheduler::do_preempt(); + } crate::scheduler::exit_to_user(); } _ => exception(frame, entry), @@ -142,22 +156,31 @@ fn exception(frame: &Frame, entry: u64) -> ! { panic!("{entry}: {} at {:#x}", class_name(frame.esr), frame.elr); } -/// One interrupt. From EL0 a tick or a kick -/// preempts here, where the interrupted context holds nothing; from EL1 it -/// only asks for the pass the context will run when it may. -fn irq(from_el0: bool) { +/// One interrupt, and whether its caller preempts the interrupted context: +/// from EL0 a tick or a kick does, once the handler is done, since the context +/// holds nothing; from EL1 it only asks for the pass the context will run when +/// it may. +fn irq(frame: &Frame, from_el0: bool) -> bool { let Some(intid) = irqchip::acknowledge() else { percpu::irq_took(Source::Spurious); - return; + return false; }; if intid == irqchip::timer_intid() { // Before anything that can take a lock or panic: a timer left // asserted re-fires forever, and one left stopped never fires again. - irqchip::rearm(); + if from_el0 { + irqchip::rearm(); + } else { + irqchip::rearm_in_kernel(); + } percpu::irq_took(Source::Timer); // Before anything that can take a lock, in both levels: a CPU spinning // on one still takes this interrupt, which is why the poll is here. - crate::deadline::poll(); + if from_el0 { + crate::deadline::poll(); + } else { + crate::deadline::poll_in_kernel(frame.elr); + } #[cfg(feature = "boot-actuators")] storm::tick(); if from_el0 { @@ -167,13 +190,12 @@ fn irq(from_el0: bool) { let hw = &crate::hw::HW; hw.trace(TraceEvent { ts: hw.now(), cpu: CpuId(percpu::cpu_id()), kind: TraceKind::TimerFire }); irqchip::end(intid); - crate::scheduler::do_preempt(); - } else { - crate::preempt::set_need_resched(); - percpu::note_kernel_timer_fire(); - irqchip::end(intid); + return true; } - return; + crate::preempt::set_need_resched(); + percpu::note_kernel_timer_fire(); + irqchip::end(intid); + return false; } match intid { // Never ended: the running priority it keeps is every interrupt's @@ -188,10 +210,9 @@ fn irq(from_el0: bool) { percpu::preempt_count_down(); irqchip::end(intid); if from_el0 { - crate::scheduler::do_preempt(); - } else { - crate::preempt::set_need_resched(); + return true; } + crate::preempt::set_need_resched(); } #[cfg(feature = "boot-actuators")] irqchip::SGI_STORM => { @@ -205,6 +226,7 @@ fn irq(from_el0: bool) { irqchip::end(intid); } } + false } /// Interrupts no handler here claims, and the last one's INTID. @@ -239,7 +261,9 @@ fn el0_sync(frame: &mut Frame) { fn syscall(frame: &mut Frame) { percpu::enter_syscall(frame.elr, frame.x[0], frame.x[29], frame.sp); percpu::preempt_count_up(); + cpu::enable_interrupts(); let answer = crate::syscall::dispatch::syscall_dispatch(frame.x[0], frame.x[1], frame.x[2], frame.x[3], frame.x[4]); + cpu::disable_interrupts(); percpu::preempt_count_down(); percpu::leave_syscall(); frame.x[0] = answer; diff --git a/kernel/src/arch/x86_64/apic.rs b/kernel/src/arch/x86_64/apic.rs index 1d23f22608..4ce3fe9401 100644 --- a/kernel/src/arch/x86_64/apic.rs +++ b/kernel/src/arch/x86_64/apic.rs @@ -53,8 +53,10 @@ pub fn msi_message(dest: u32, vector: u8) -> Result<(u32, u32), &'static str> { Ok((MSI_DOORBELL | (dest << 12), vector as u32)) } -/// Calibrated LAPIC timer ticks per 10ms (computed on BSP, reused by APs). -static TIMER_TICKS: AtomicU32 = AtomicU32::new(0); +/// Calibrated LAPIC timer ticks per 10ms (computed on BSP, reused by APs), +/// which is one quantum: what the Ring 0 timer branch re-arms with. +pub(crate) static TIMER_TICKS: AtomicU32 = AtomicU32::new(0); +const _: () = assert!(kernel::sched::fair::QUANTUM_NS == 10_000_000); /// Guards IPI sends before the APIC is enabled. static X2APIC_ENABLED: AtomicBool = AtomicBool::new(false); @@ -277,6 +279,18 @@ pub fn arm_within(nanos: u64) { OneShot::ticks(ticks as u64).arm(); } +/// What the timer was last armed with: `TIMER_INIT`, a count of ticks. +#[cfg(feature = "test-actuators")] +pub fn comparator() -> u64 { + Reg::TimerInit.read() +} + +/// Whether a Ring 0 fire since [`comparator`] read `_armed` re-armed one quantum. +#[cfg(feature = "test-actuators")] +pub fn rearmed_a_quantum(_armed: u64) -> bool { + Reg::TimerInit.read() == u64::from(TIMER_TICKS.load(Ordering::Relaxed)) +} + /// Stop the timer. No more interrupts until re-armed. pub fn stop_timer() { percpu::set_last_armed_ticks(0); diff --git a/kernel/src/arch/x86_64/idt/device_irq.rs b/kernel/src/arch/x86_64/idt/device_irq.rs index 4b7db10bd7..90ce2d74c0 100644 --- a/kernel/src/arch/x86_64/idt/device_irq.rs +++ b/kernel/src/arch/x86_64/idt/device_irq.rs @@ -76,12 +76,14 @@ pub(crate) use device_irq_entry; pub(super) extern "sysv64" fn windows_entered() { crate::windows::irqs_masked(); crate::windows::preempt_raised(); + crate::windows::handler_entered(); } /// 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::handler_leaving(); crate::windows::preempt_lowering(); if !toyos_userbound::Ring::of_cs(cs).is_user() { 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 7c06632562..c26a827da7 100644 --- a/kernel/src/arch/x86_64/idt/spurious.rs +++ b/kernel/src/arch/x86_64/idt/spurious.rs @@ -54,13 +54,19 @@ pub(super) extern "sysv64" fn spurious_entry() { /// 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::windows::irqs_masked(); + crate::windows::handler_entered(); + } crate::arch::percpu::irq_took!(Spurious); if apic::in_service(SPURIOUS_VECTOR) { apic::eoi(); } #[cfg(feature = "mask-windows")] - crate::windows::irqs_unmasking(); + { + crate::windows::handler_leaving(); + 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 a5faaa6565..d26595a387 100644 --- a/kernel/src/arch/x86_64/idt/timer.rs +++ b/kernel/src/arch/x86_64/idt/timer.rs @@ -3,7 +3,7 @@ use kernel::sched::hw::{CpuId, Machine, TraceEvent, TraceKind}; use crate::arch::entry::{restore_user_state, ring3_naked_asm, save_user_state}; use crate::hw::HW; -// Ring 0 re-arms the timer itself; without it, a fire in Ring 0 disables preemption for good, since the one-shot never refires on its own. +// A Ring 0 fire re-arms one quantum on, or leaves a stopped timer stopped, and never writes `last_armed_ticks`: what the scheduler planned is re-armed by its next pass, and a syscall that outlasts a quantum takes one expiry per quantum. // Ring 3 exit runs `kernel_exit_to_user_check` like every other return to userland: skipping it here let a thread killed in Ring 3 be redispatched to userland with the kill unread. #[unsafe(naked)] pub(super) extern "sysv64" fn timer_entry() { @@ -51,8 +51,12 @@ pub(super) extern "sysv64" fn timer_entry() { "xor eax, eax", "xor edx, edx", "wrmsr", - "mov ecx, 0x838", // X2APIC_TIMER_INIT — re-arm with last value; - "mov eax, dword ptr gs:[{armed_ticks}]", // 0 = disabled. + "mov ecx, 0x838", // X2APIC_TIMER_INIT + "mov eax, dword ptr gs:[{armed_ticks}]", + "test eax, eax", + "jz 3f", // 0: stopped, and written back as stopped. + "mov eax, dword ptr [rip + {quantum_ticks}]", + "3:", "xor edx, edx", "wrmsr", "mov byte ptr gs:[{need_resched}], 1", @@ -68,6 +72,8 @@ pub(super) extern "sysv64" fn timer_entry() { "push rbp", "mov rbp, rsp", "and rsp, -16", + // The interrupted `rip`, above the ten registers pushed on this branch. + "mov rdi, [rbp + 80]", "call {deadline}", "mov rsp, rbp", "pop rbp", @@ -77,12 +83,13 @@ pub(super) extern "sysv64" fn timer_entry() { "pop rax", "iretq", #[cfg(not(feature = "mask-windows"))] - deadline = sym crate::deadline::poll, + deadline = sym crate::deadline::poll_in_kernel, #[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, + quantum_ticks = sym crate::arch::apic::TIMER_TICKS, need_resched = const crate::arch::percpu::OFF_NEED_RESCHED, ring0_fires = const crate::arch::percpu::OFF_RING0_TIMER_FIRES, irq_total = const crate::arch::percpu::irq_slot_offset(crate::irq_census::TOTAL), @@ -95,16 +102,21 @@ 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() { +extern "sysv64" fn ring0_tick(pc: u64) { crate::windows::irqs_masked(); - crate::deadline::poll(); + crate::windows::handler_entered(); + crate::deadline::poll_in_kernel(pc); + crate::windows::handler_leaving(); 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::windows::irqs_masked(); + crate::windows::handler_entered(); + } 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. @@ -124,5 +136,8 @@ extern "sysv64" fn timer_handler() { }); crate::arch::apic::eoi(); + // The handler ends here: the pass that follows is the interrupted thread's. + #[cfg(feature = "mask-windows")] + crate::windows::handler_leaving(); crate::scheduler::do_preempt(); } diff --git a/kernel/src/arch/x86_64/idt/unclaimed.rs b/kernel/src/arch/x86_64/idt/unclaimed.rs index 49c47f60eb..76d1722261 100644 --- a/kernel/src/arch/x86_64/idt/unclaimed.rs +++ b/kernel/src/arch/x86_64/idt/unclaimed.rs @@ -59,7 +59,10 @@ pub(super) extern "sysv64" fn unclaimed_entry() { /// 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::windows::irqs_masked(); + crate::windows::handler_entered(); + } crate::arch::percpu::irq_took!(Unclaimed); match apic::in_service_highest() { Some(vector) => { @@ -71,7 +74,10 @@ extern "sysv64" fn took() { } } #[cfg(feature = "mask-windows")] - crate::windows::irqs_unmasking(); + { + crate::windows::handler_leaving(); + crate::windows::irqs_unmasking(); + } } /// Whether `vector` has been taken through this gate. diff --git a/kernel/src/arch/x86_64/percpu.rs b/kernel/src/arch/x86_64/percpu.rs index 07cc73c15a..64f9b50db1 100644 --- a/kernel/src/arch/x86_64/percpu.rs +++ b/kernel/src/arch/x86_64/percpu.rs @@ -107,7 +107,7 @@ pub struct PerCpu { pub last_seen_ring0_fires: u32, fault_state: u8, _pad_after_fault_state: [u8; 3], - /// Ticks the Ring 0 timer re-arms with; per-CPU to avoid cross-CPU clobber. + /// Ticks the Ring 3 timer branch re-arms with, and zero when stopped, which the Ring 0 branch leaves stopped. pub last_armed_ticks: AtomicU32, /// This CPU's [`log::Shard`]; never null on a live CPU ([`alloc_percpu`] fills it first). log_shard: u64, @@ -635,7 +635,7 @@ pub fn set_last_seen_kernel_timer_fires(v: u32) { gs::write_u32::(v); } -/// The one-shot count this CPU just armed, for the timer stub's reload; `arch::apic` is the only caller. +/// The one-shot count this CPU just armed, for the timer stub; `arch::apic` is the only caller. pub fn set_last_armed_ticks(ticks: u32) { gs::write_u32::(ticks); } diff --git a/kernel/src/arch/x86_64/syscall.rs b/kernel/src/arch/x86_64/syscall.rs index e48bd3f503..7031f92e0c 100644 --- a/kernel/src/arch/x86_64/syscall.rs +++ b/kernel/src/arch/x86_64/syscall.rs @@ -29,7 +29,7 @@ pub fn init() { const AC: u64 = 1 << 18; // TF must stay masked: an unmasked single-step trap taken between entry and the stack switch takes `#DB` on the user stack, which SMAP refuses and which escalates to a double fault. // `debug_trap`'s `tf-syscall` arm is the check that catches `TF` being left unmasked. - // `IF` stays masked so interrupts are off for the whole syscall, and `RFLAGS.AC` clear is what makes SMAP bind at all. + // `IF` stays masked until `syscall_handler` opens it, past the stack switch and the user-state save; `RFLAGS.AC` clear is what makes SMAP bind at all. // `DF` is cleared to match `arch::entry::ring3_naked_asm`'s `cld`. // `entry-df-unclean` takes out only `DF`, never another bit — a control that removed two bits would be measuring two things. let df = if cfg!(feature = "entry-df-unclean") { 0 } else { DF }; @@ -65,8 +65,6 @@ extern "sysv64" fn syscall_entry() { "call {handler}", "lock sub dword ptr gs:[{preempt_count}], 1", - // `cli` here: an interrupt after `pop rsp` would run on the user RSP as a kernel stack. - "cli", // The helper called before `pop rsp`/`sysretq` (`exit_to_user`) preserves `IF=0` across its return. // Runs before GPR restore: the sysv64 call would otherwise clobber rcx/r11 (sysretq's RIP/RFLAGS) and the restored args. // The 16 bytes both park the syscall return value and keep `rsp` aligned for the `call`. @@ -110,7 +108,10 @@ extern "sysv64" fn syscall_handler(num: u64, a1: u64, a2: u64, _: u64, a3: u64, #[cfg(feature = "df-witness")] cpu::df_witness("syscall_handler"); percpu::enter_syscall(); + cpu::enable_interrupts(); let out = syscall_dispatch(num, a1, a2, a3, a4); + // Closed for the rest of the way out: an interrupt after the entry's `pop rsp` would run on the user RSP as a kernel stack. + cpu::disable_interrupts(); percpu::leave_syscall(); // The entry lowers it by one next; `exit_to_user` opens interrupts. #[cfg(feature = "mask-windows")] diff --git a/kernel/src/deadline.rs b/kernel/src/deadline.rs index d85aca3647..3476a0e166 100644 --- a/kernel/src/deadline.rs +++ b/kernel/src/deadline.rs @@ -33,6 +33,8 @@ use core::sync::atomic::{AtomicBool, AtomicU64, AtomicU8, Ordering::Relaxed}; +use crate::sched::MAX_CPUS; + /// Every phase [`boot_phase!`](crate::boot_phase) publishes, in the order a /// boot reaches them, so a sealed record can name where the machine stopped. /// Index 0 is a machine that has published none; the rest are the literals @@ -188,17 +190,48 @@ pub fn start() { /// **One relaxed load in the callee on the unarmed path.** The Ring 0 call site /// pays a caller-saved prologue on every tick of every CPU armed or not, and /// that cost is the entry's rather than this function's. -/// -/// `extern "C"` because the Ring 0 half of the timer entry calls it from -/// naked assembly, where the ABI is written out rather than inferred. -pub extern "C" fn poll() { - let at = AT_TSC.load(Relaxed); +pub fn poll() { + past(AT_TSC.load(Relaxed)) +} + +fn past(at: u64) { if at == 0 || crate::arch::cpu::counter() < at { return; } expire() } +/// Where each CPU's timer last interrupted the kernel, kept only on a boot +/// with a bound: the seal's account of a CPU stuck with interrupts open, which +/// no hard-lockup sample reports. +static KERNEL_PC: [AtomicU64; MAX_CPUS] = [const { AtomicU64::new(0) }; MAX_CPUS]; + +/// [`poll`], for a timer interrupt that found the kernel at `pc`. +/// +/// `extern "C"` because the Ring 0 half of the x86 timer entry calls it from +/// naked assembly, where the ABI is written out rather than inferred. +pub extern "C" fn poll_in_kernel(pc: u64) { + let at = AT_TSC.load(Relaxed); + if at != 0 { + if let Some(slot) = KERNEL_PC.get(crate::arch::percpu::cpu_id() as usize) { + slot.store(pc, Relaxed); + } + } + past(at) +} + +/// ` cpuN=` for each online CPU, out of [`KERNEL_PC`]. +struct KernelPcs; + +impl core::fmt::Display for KernelPcs { + fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { + for (cpu, pc) in KERNEL_PC.iter().enumerate().take(crate::smp::cpu_count() as usize) { + write!(f, " cpu{cpu}={:#x}", pc.load(Relaxed))?; + } + Ok(()) + } +} + /// Seal why, stop what is doing DMA, and hand the machine back. /// /// Runs inside an interrupt entry on whichever CPU noticed, so it is the same @@ -211,9 +244,12 @@ fn expire() -> ! { // add and must not race it into the page. crate::arch::cpu::halt(); } + #[cfg(feature = "mask-windows")] + crate::windows::stand_down(); crate::drivers::panic_console::seal_wedge(format_args!( - "{EXPIRED}: a bound of {} ms, reached at {} ms, with this machine in `{}`. \ - The tail of the log ring follows — which is what nothing was draining.\n", + "{EXPIRED}: a bound of {} ms, reached at {} ms, with this machine in `{}`, each CPU's \ + timer last finding the kernel at{KernelPcs}. The tail of the log ring follows — which \ + is what nothing was draining.\n", BOUND_MS.load(Relaxed), crate::clock::nanos_since_boot() / 1_000_000, phase(), @@ -271,11 +307,9 @@ fn this_cpu() -> ! { // reach is the Ring 0 half of the timer entry and not the Rust half. // // **All three set, not assumed**, and not an `IrqGuard`: nothing here ever - // puts them back. A CPU arriving from `stage_a_wedge` is inside the shutdown - // syscall with `IF` masked, and one woken out of the idle halt has its - // one-shot stopped however set `IF` is — either leaves a CPU taking no - // interrupt at all, which is a hard lockup and not the state this control - // claims. + // puts them back. One woken out of the idle halt has its one-shot stopped + // however set `IF` is, which leaves a CPU taking no interrupt at all: a + // hard lockup and not the state this control claims. crate::preempt::disable(); let arrived_awake = crate::arch::cpu::interrupts_enabled(); crate::arch::irqchip::arm_within(kernel::sched::fair::QUANTUM_NS); @@ -296,15 +330,15 @@ fn this_cpu() -> ! { } } -/// What the CPU that staged the wedge says about the state it arrived in: a boot -/// on which no CPU says this is one the wedge never reached the CPU that asked -/// for it. Judged by the harness, so it is a constant (`src/bootlog.rs`). +/// What a CPU says that arrived with interrupts masked: the staging CPU, if the +/// syscall gate left them masked, which the harness refuses +/// (`src/bootlog.rs`). #[cfg(feature = "boot-actuators")] pub const WEDGE_ARRIVED_DEAF: &str = "arrived with interrupts off, through the syscall gate, and takes them again here"; -/// What every other CPU says: they arrive from a scheduler pass, which already -/// had them. +/// What every CPU says that arrived with them open, the staging CPU among them: +/// the harness requires it of that CPU (`src/bootlog.rs`). #[cfg(feature = "boot-actuators")] pub const WEDGE_AWAKE: &str = "arrived with interrupts on"; diff --git a/kernel/src/drivers/xhci/mod.rs b/kernel/src/drivers/xhci/mod.rs index 4b65b0e21f..d237490a10 100644 --- a/kernel/src/drivers/xhci/mod.rs +++ b/kernel/src/drivers/xhci/mod.rs @@ -311,8 +311,8 @@ const CALL_AFTER_BREAK: crate::time::Budget = crate::time::Budget::of( "every wait is clipped to where the rungs still ahead of it begin, so the last rung runs whatever was spent before it and the call ends here", ); -// A disk call spins with interrupts off, so one that outlasted this tripwire -// would panic another CPU over a device. +// A bind spins in the tick's pass with interrupts off, so one that outlasted +// this tripwire would panic another CPU over a device. const _: () = assert!(CALL_AFTER_BREAK.nanos() < crate::time::DEAF_CPU.nanos()); diff --git a/kernel/src/drivers/xhci/wait/msc.rs b/kernel/src/drivers/xhci/wait/msc.rs index aca75bcff1..0e1c645e51 100644 --- a/kernel/src/drivers/xhci/wait/msc.rs +++ b/kernel/src/drivers/xhci/wait/msc.rs @@ -1657,8 +1657,7 @@ pub fn storage_flush(index: usize, losses: &mut u64) -> BlockResult { /// **The operation is one call, and its bound is the call's** /// (`toyos_xhci::call`): opened by the first break or by finding the disk /// held, carried across every command, the hold and the command sent again, -/// and closed here. The caller spins with `IF` clear for all of it, which is -/// why `CALL_AFTER_BREAK` is held under `time::DEAF_CPU`, the TLB-ack tripwire. +/// and closed here. /// /// **The hold only waits for a verdict.** It ends at the disk's own window /// (`toyos_xhci::identity::RETURN_WINDOW`), past which the disk is lost and the diff --git a/kernel/src/main.rs b/kernel/src/main.rs index 4a1ce8185a..4c59223481 100644 --- a/kernel/src/main.rs +++ b/kernel/src/main.rs @@ -116,6 +116,9 @@ use toyos_rootimage::handoff::{held, Descriptor}; #[panic_handler] fn panic(info: &core::panic::PanicInfo) -> ! { cpu::disable_interrupts(); + // A handler's own panic reports through locks like any other. + #[cfg(feature = "mask-windows")] + windows::stand_down(); // Must run first: captures state for a possible second panic, declining if this CPU is already inside one. panic::record_panic(info); diff --git a/kernel/src/mm/unmapped.rs b/kernel/src/mm/unmapped.rs index 9a07826f63..5741e04619 100644 --- a/kernel/src/mm/unmapped.rs +++ b/kernel/src/mm/unmapped.rs @@ -2,7 +2,7 @@ use core::mem::ManuallyDrop; /// A value whose page-table entries are cleared but may still be reachable through another CPU's TLB until this drops. /// -/// This must never be dropped while holding a lock a target CPU could be spinning on with `IF` clear, since shootdown blocks on every other CPU. +/// This must never be dropped while holding a lock a target CPU could be spinning on, since shootdown blocks on every other CPU. #[must_use = "the pages are still reachable from another CPU until this is dropped"] pub struct Unmapped(ManuallyDrop); diff --git a/kernel/src/panic.rs b/kernel/src/panic.rs index 89dfbe7967..45f37a4950 100644 --- a/kernel/src/panic.rs +++ b/kernel/src/panic.rs @@ -354,6 +354,8 @@ pub fn halt_all_cpus() -> ! { // this path exists to deliver. crate::hardlockup::stand_down(); crate::deadline::stand_down(); + #[cfg(feature = "mask-windows")] + crate::windows::stand_down(); // **The other CPUs first, before anything else here runs.** A kernel that // has declared itself corrupt runs no userland again and no write path: // the report reaches the console, the panel and the black box, and diff --git a/kernel/src/process.rs b/kernel/src/process.rs index 221f06c075..b134cd1542 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -202,7 +202,7 @@ impl MappedPages { } pub fn release(self, pt: &PageTables) { - // Two statements: the shootdown in drop must not run under the address-space lock, which a sibling's page fault spins on with IF clear. + // Two statements: the shootdown in drop must not run under the address-space lock, which a sibling's page fault spins on. let pages = self.unmap_from(&mut pt.lock()); drop(pages); } @@ -652,7 +652,7 @@ pub fn revoke_pipe_maps(maps: &mut Vec, pt: &PageTables, pipe: pipe::Pi false }); } - // Outside the block: it waits, and a sibling can be spinning on this lock with IF clear. + // Outside the block: it waits, and a sibling can be spinning on this lock. crate::arch::tlb::shootdown(crate::invalidation::Origin::Pipe); } @@ -977,7 +977,7 @@ pub fn spawn_thread(entry: u64, stack_ptr: u64, arg: u64, stack_base: u64) -> Op // Re-checked under the insert lock: a thread refused here would otherwise be invisible to a retire sweep already under way. if !proclife_spawn::admit_thread_insert(table, parent_process).is_yes() { // The unmap cannot run under the table lock (its shootdown is a wait a - // sibling can be spinning against with IF clear), so the mapping is + // sibling can be spinning against), so the mapping is // still solely this scope's here — built into a ThreadData only past // the admission, where the table owns its release. drop(guard); @@ -1286,7 +1286,7 @@ fn release_thread(process_pid: Pid, tid: Tid, code: i32) { let mut owner_data = owner_arc.lock(); release_thread_mappings(&mut owner_data, tls, &addr_space, tid) }; - // After the block: dropping waits for every other CPU, and the page-fault handler takes this same lock with IF clear. + // After the block: dropping waits for every other CPU, and the page-fault handler takes this same lock. drop(released); let guard = PROCESS_TABLE.lock(); diff --git a/kernel/src/scheduler.rs b/kernel/src/scheduler.rs index 1d6f1a3d19..ac4eae39e3 100644 --- a/kernel/src/scheduler.rs +++ b/kernel/src/scheduler.rs @@ -431,6 +431,8 @@ fn flush_kernel_timer_fires_to_trace() { #[track_caller] pub fn exit_current() -> ! { assert_baseline(BASELINE_TRAP); + // Masked into the pass, as `leave_user_if_due`'s exit masks into it. + crate::arch::cpu::disable_interrupts(); driver::pass(Dispose::Exit); unreachable!("exit_current: returned from the exit pass"); } diff --git a/kernel/src/shootdown.rs b/kernel/src/shootdown.rs index 4443e820f2..068f41b895 100644 --- a/kernel/src/shootdown.rs +++ b/kernel/src/shootdown.rs @@ -99,7 +99,7 @@ impl Shootdown { generation: Generation, flush: impl FnOnce(), ) -> bool { - // IF is masked here, so this CPU must serve itself or two initiators waiting on each other deadlock. + // An initiator inside an `IrqGuard`, a handler or the tick's pass takes no IPI, so this CPU must serve itself or two initiators waiting on each other deadlock. self.serve_if_owed(me, flush); // Order is the fix: serving first is what publishes the generation a concurrent sibling is waiting on. self.served(cpu, generation) diff --git a/kernel/src/sync.rs b/kernel/src/sync.rs index bfa85e8e85..78ba385be7 100644 --- a/kernel/src/sync.rs +++ b/kernel/src/sync.rs @@ -118,6 +118,20 @@ impl Lock { #[track_caller] pub fn lock(&self) -> LockGuard<'_, T> { + #[cfg(feature = "mask-windows")] + crate::windows::outside_a_handler("a `sync::Lock`"); + self.acquire() + } + + /// [`Lock::lock`] for an `IrqLock`, the one kind an interrupt handler may + /// take: the closed guard is its exemption from the handler witness. + #[track_caller] + pub fn lock_masked(&self, _closed: &crate::arch::IrqGuard) -> LockGuard<'_, T> { + self.acquire() + } + + #[track_caller] + fn acquire(&self) -> LockGuard<'_, T> { crate::preempt::disable(); let my_ticket = self.ticket.fetch_advance(Ordering::Relaxed); let mut spins = 0u64; @@ -137,8 +151,12 @@ impl Lock { )); } core::hint::spin_loop(); - // Polls TLB shootdowns: this spin runs with `IF` clear, so skipping - // it here can deadlock a shootdown initiator that holds a lock. + // Polls TLB shootdowns: a spinner inside an `IrqGuard`, an + // `IrqLock`, a handler or the tick's pass has `IF` clear and takes + // no IPI, and without this would deadlock an initiator that holds + // the lock. + // With `IF` set the IPI can land inside this poll's own serve, + // which `Shootdown::serve` survives. crate::arch::tlb::poll(); spins += 1; if spins == next_warn { @@ -159,7 +177,10 @@ impl Lock { LockGuard { lock: self } } + #[track_caller] pub fn try_lock(&self) -> Option> { + #[cfg(feature = "mask-windows")] + crate::windows::outside_a_handler("a `sync::Lock`"); crate::preempt::disable(); let current = self.now.load(ACQUIRED); match self.ticket.compare_advance(current, Ordering::Relaxed, Ordering::Relaxed) { diff --git a/kernel/src/syscall/debug.rs b/kernel/src/syscall/debug.rs index 600ebbe1e0..58716c55de 100644 --- a/kernel/src/syscall/debug.rs +++ b/kernel/src/syscall/debug.rs @@ -47,3 +47,27 @@ pub(super) mod canary { [WORDS[0].load(Ordering::Relaxed), WORDS[1].load(Ordering::Relaxed)] != VALUE } } + +/// `RING0_TIMER_IN_SYSCALL`: the timer's interrupt reaches this syscall's body, +/// which is the gate opening interrupts, and its fire re-arms one quantum. +pub(super) fn ring0_timer_in_syscall() -> u64 { + use toyos_abi::syscall::debug_action::{RING0_FIRE_NEVER, RING0_FIRE_OTHER_SPAN, RING0_FIRE_REARMED}; + const WITHIN_NS: u64 = 100_000; + const CEILING_NS: u64 = 100_000_000; + let fired = crate::arch::percpu::kernel_timer_fires(); + crate::arch::irqchip::arm_within(WITHIN_NS); + let armed = crate::arch::irqchip::comparator(); + let ends = crate::clock::nanos_since_boot() + CEILING_NS; + loop { + // The clock before the count, so a ceiling read past is one the fire had every chance to beat. + let now = crate::clock::nanos_since_boot(); + if crate::arch::percpu::kernel_timer_fires() != fired { + break; + } + if now > ends { + return RING0_FIRE_NEVER; + } + core::hint::spin_loop(); + } + if crate::arch::irqchip::rearmed_a_quantum(armed) { RING0_FIRE_REARMED } else { RING0_FIRE_OTHER_SPAN } +} diff --git a/kernel/src/syscall/dispatch.rs b/kernel/src/syscall/dispatch.rs index d2f3ef0c66..63ec04c6d0 100644 --- a/kernel/src/syscall/dispatch.rs +++ b/kernel/src/syscall/dispatch.rs @@ -21,7 +21,7 @@ use toyos_untrusted::Untrusted; use super::HANDLE_LEN; #[cfg(feature = "test-actuators")] -use super::debug::{canary, debug_heap_alloc, FATAL_HALT_NONCE, LOCK_ACROSS_SWITCH}; +use super::debug::{canary, debug_heap_alloc, ring0_timer_in_syscall, FATAL_HALT_NONCE, LOCK_ACROSS_SWITCH}; use super::device::{ holds_claim, sys_device_bar_map, sys_device_claim, sys_device_dma_alloc, sys_device_dma_map, sys_device_dma_unmap, @@ -606,6 +606,8 @@ pub(crate) fn syscall_dispatch(num: u64, a1: u64, a2: u64, a3: u64, a4: u64) -> // bound and its stale answer are the shipped paths. DA::COUNTERS_DEAF => crate::counters::deaf::stage(a2), DA::COUNTERS_HEAR => crate::counters::deaf::end(), + // An interrupt inside a syscall's body, which nothing a guest does puts there on demand. + DA::RING0_TIMER_IN_SYSCALL => ring0_timer_in_syscall(), _ => SyscallError::InvalidArgument.to_u64(), }, SYS_SCHED_INFO => match ctx.copy_out(UserAddr::new(a1), &sys_sched_info()) { diff --git a/kernel/src/syscall/vm.rs b/kernel/src/syscall/vm.rs index 9c6edf668e..8af3a3152a 100644 --- a/kernel/src/syscall/vm.rs +++ b/kernel/src/syscall/vm.rs @@ -10,7 +10,7 @@ //! //! A removed mapping's `Unmapped` drops outside `with_process_data`: the drop //! shoots down and waits, and a sibling thread can be spinning on that same -//! lock with `IF` clear. +//! lock. use crate::mm::policy::{CachePolicy, Prot}; use crate::vma::Occupancy; @@ -192,7 +192,7 @@ pub(super) fn sys_munmap(addr: u64, _size: u64) -> u64 { return SyscallError::NotFound.to_u64(); }; // Dropped here, outside the closure: the drop shoots down and waits, and a - // sibling can be spinning on the process-data lock with `IF` clear. + // sibling can be spinning on the process-data lock. drop(unmapped); 0 } diff --git a/kernel/src/usb_gate.rs b/kernel/src/usb_gate.rs index 10011be7f8..ac4b10fe98 100644 --- a/kernel/src/usb_gate.rs +++ b/kernel/src/usb_gate.rs @@ -51,13 +51,8 @@ pub fn sweep_under_load() { // boot deadline, polled from the timer entry, and a CPU that takes no // interrupt at all is a hard lockup ended half a bound earlier by a // different mechanism under this arm's name. - // - // Read before the `sti`, which is the one fact here about the caller rather - // than about this function. - let interrupts_were_on = crate::arch::cpu::interrupts_enabled(); crate::preempt::disable(); crate::arch::irqchip::arm_within(kernel::sched::fair::QUANTUM_NS); - crate::arch::cpu::enable_interrupts(); let mut buf = vec![0u8; WEDGE_CHUNK as usize * BLOCK]; let mut at = first; let mut stopped = false; @@ -76,13 +71,10 @@ pub fn sweep_under_load() { } // Put back on the one path out of here, because the caller goes on to drain // write-back, sync every filesystem, flush every disk and wait for the log - // to be durable, and none of that may run under a preempt count or an `IF` - // this left behind. Not `preempt::enable`: the request stays set and the - // caller's own next preemption point serves it, rather than a scheduler pass - // taken from inside the shutdown syscall. - if !interrupts_were_on { - crate::arch::cpu::disable_interrupts(); - } + // to be durable, and none of that may run under a preempt count this left + // behind. Not `preempt::enable`: the request stays set and the caller's own + // next preemption point serves it, rather than a scheduler pass taken from + // inside the shutdown syscall. crate::preempt::enable_no_resched(); } diff --git a/kernel/src/watch.rs b/kernel/src/watch.rs index 2c9ffab73a..42c2921156 100644 --- a/kernel/src/watch.rs +++ b/kernel/src/watch.rs @@ -83,8 +83,8 @@ mod masked { Self(Lock::new(value)) } - pub fn lock<'a>(&'a self, _closed: &'a IrqGuard) -> LockGuard<'a, T> { - self.0.lock() + pub fn lock<'a>(&'a self, closed: &'a IrqGuard) -> LockGuard<'a, T> { + self.0.lock_masked(closed) } } } diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index 3ffea02f6a..74f92ea567 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -25,8 +25,16 @@ //! //! 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; +//! +//! **The handler witness.** Every maskable interrupt's handler body is bracketed +//! by [`handler_entered`] and [`handler_leaving`] — the pass a tick or a kick +//! from user mode runs after it is outside — and [`outside_a_handler`] refuses +//! a `sync::Lock` taken inside one, but through an `IrqLock`: a handler that +//! takes one the context it interrupted holds spins forever. From +//! [`stand_down`], which every path that ends the machine calls before it takes +//! locks of its own, nothing is refused. + +use core::sync::atomic::{AtomicBool, AtomicU32}; use core::sync::atomic::Ordering::Relaxed; use kernel::sched::windows::{Unseen, Windows, HELD_NS}; @@ -51,9 +59,50 @@ fn on(transition: impl FnOnce(&Windows) -> Result<(), Unseen>) { fn refuse(unseen: Unseen) -> ! { let cpu = percpu::cpu_id(); CPUS[cpu as usize].stop(); + stand_down(); panic!("mask-windows: cpu{cpu} {unseen}"); } +/// How many handler bodies each CPU is inside: one at most, since a maskable +/// handler runs masked. +static IN_HANDLER: [AtomicU32; MAX_CPUS] = [const { AtomicU32::new(0) }; MAX_CPUS]; + +/// The machine is ending: the witness refuses nothing more. +static STOOD_DOWN: AtomicBool = AtomicBool::new(false); + +/// A maskable interrupt's handler body starts on this CPU. +pub fn handler_entered() { + if crate::log::PERCPU_READY.load(Relaxed) { + IN_HANDLER[percpu::cpu_id() as usize].fetch_add(1, Relaxed); + } +} + +/// That body ends. +pub fn handler_leaving() { + if crate::log::PERCPU_READY.load(Relaxed) { + IN_HANDLER[percpu::cpu_id() as usize].fetch_sub(1, Relaxed); + } +} + +/// `what` is about to be taken, which no handler body may do. +#[track_caller] +pub fn outside_a_handler(what: &str) { + if !crate::log::PERCPU_READY.load(Relaxed) || STOOD_DOWN.load(Relaxed) { + return; + } + let cpu = percpu::cpu_id(); + if IN_HANDLER[cpu as usize].load(Relaxed) != 0 { + CPUS[cpu as usize].stop(); + stand_down(); + panic!("mask-windows: cpu{cpu} took {what} inside an interrupt handler at {}", core::panic::Location::caller()); + } +} + +/// The machine is ending, on a path that may take any lock. +pub fn stand_down() { + STOOD_DOWN.store(true, Relaxed); +} + /// This CPU joins the scheduler, and is tracked from here. pub fn start_here() { // Masked from here whatever it stood with; the guard's drop opens them @@ -70,6 +119,7 @@ pub fn irqs_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() { + stand_down(); on(|w| { w.stop(); Ok(()) @@ -121,14 +171,15 @@ pub fn log_cpu(cpu: u32) { ); } -/// 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=…`. +/// The boot's first `SYS_EXIT`, with the preempt count its entry raised, +/// masks interrupts 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 closed = crate::arch::IrqGuard::close(); let from = cpu::counter(); let mut ns = 0; // In the nanoseconds it prints: a tick count that stands for `HELD_NS` can @@ -137,5 +188,6 @@ pub fn hold_once() { core::hint::spin_loop(); ns = crate::clock::nanos_of_ticks(cpu::counter() - from); } + drop(closed); crate::log!("windows: held cpu{} ns={ns}", percpu::cpu_id()); } diff --git a/src/bootlog.rs b/src/bootlog.rs index 34fbb3038c..9bb14da32d 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -43,17 +43,20 @@ pub const DEADLINE_ARMED: &str = "boot deadline: "; /// a boot merely slower than its bound, which is what makes that control one. pub const WEDGE_STAGED: &str = "wedge: staged, and only the boot deadline ends this machine"; -/// What the CPU that *stages* that wedge says about the state it arrived in, -/// also in `kernel/src/deadline.rs`. +/// What each CPU the wedge takes says about the state it arrived in, also in +/// `kernel/src/deadline.rs`: [`WEDGE_AWAKE`] with interrupts open, and +/// [`WEDGE_ARRIVED_DEAF`] with them masked. /// -/// **The one line that measures that control's own claim.** It arrives through -/// the shutdown syscall, and `arch::syscall` masks `IF` for the whole of a -/// syscall — so a wedge that inherited its state leaves exactly one CPU per boot -/// taking no interrupt at all, which is not a wedge but a hard lockup. A boot on -/// which no CPU says this is a boot whose wedge never reached the CPU that asked -/// for it. +/// **The lines that measure that control's own claim.** The CPU that stages it +/// arrives through the shutdown syscall, whose body runs with interrupts open, +/// so it must say [`WEDGE_AWAKE`] and no CPU may say [`WEDGE_ARRIVED_DEAF`]: a +/// syscall that kept them masked is one CPU per boot taking no interrupt at +/// all, which is not a wedge but a hard lockup. Every other CPU arrives from a +/// scheduler pass and is awake whatever the gate does, so the awake line is +/// read of the staging CPU alone. pub const WEDGE_ARRIVED_DEAF: &str = "arrived with interrupts off, through the syscall gate, and takes them again here"; +pub const WEDGE_AWAKE: &str = "arrived with interrupts on"; /// What the `usb-reset-under-load` arm says once it is streaming, and the three /// ways it says it is not, in `kernel/src/usb_gate.rs`. @@ -540,6 +543,7 @@ mod tests { ("kernel/src/deadline.rs", format!("\"{DEADLINE_ARMED}{{ms}} ms")), ("kernel/src/deadline.rs", format!("WEDGE_STAGED: &str = \"{WEDGE_STAGED}\"")), ("kernel/src/deadline.rs", format!("\"{WEDGE_ARRIVED_DEAF}\"")), + ("kernel/src/deadline.rs", format!("WEDGE_AWAKE: &str = \"{WEDGE_AWAKE}\"")), ("kernel/src/usb_gate.rs", format!("LOAD_RUNNING: &str = \"{USB_LOAD_RUNNING}\"")), ("kernel/src/usb_gate.rs", format!("LOAD_REFUSED: &str = \"{USB_LOAD_REFUSED}\"")), ("kernel/src/usb_gate.rs", format!("LOAD_STOPPED: &str = \"{USB_LOAD_STOPPED}\"")), diff --git a/tests/checks.rs b/tests/checks.rs index 39aee3dbae..266b4298d0 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -925,14 +925,22 @@ mod checks { }; let kernel = "[2026-09-29 10:33:28 0.000 cpu0 boot] panic console: armed 1920x1080 \ stride=1920 format=1 at 0x4000000000, write-combining\n"; - let wedge = "| [1.509 cpu0] wedge: staged, and only the boot deadline ends this machine: \ - every CPU stops taking scheduler passes from here\n\ - | [1.509 cpu0] wedge: cpu0 arrived with interrupts off, through the syscall \ - gate, and takes them again here\n\ - | [1.509 cpu1] wedge: cpu1 arrived with interrupts on\n"; + let staged = "| [1.509 cpu1] wedge: staged, and only the boot deadline ends this machine: \ + every CPU stops taking scheduler passes from here\n"; + let awake = |cpu: u32| format!("| [1.509 cpu{cpu}] wedge: cpu{cpu} arrived with interrupts on\n"); + let deaf = "| [1.509 cpu1] wedge: cpu1 arrived with interrupts off, through the syscall \ + gate, and takes them again here\n"; let judge = metal_judge("boot_deadline_ends_a_wedge"); - assert_eq!(judge(&[&readback("deadlinewedge", &wedged(wedge), kernel)]), Ok(())); + let wedge = format!("{staged}{}{}", awake(1), awake(0)); + assert_eq!(judge(&[&readback("deadlinewedge", &wedged(&wedge), kernel)]), Ok(())); assert!(judge(&[&readback("deadlinewedge", &wedged(""), kernel)]).is_err()); + // The staging CPU arrived deaf: the gate masked the syscall's body, and + // the others' awake lines say nothing of it. + let gated = format!("{staged}{deaf}{}", awake(0)); + assert!(judge(&[&readback("deadlinewedge", &wedged(&gated), kernel)]).is_err()); + // Awake, but not the CPU that staged it. + let elsewhere = format!("{staged}{}", awake(0)); + assert!(judge(&[&readback("deadlinewedge", &wedged(&elsewhere), kernel)]).is_err()); let sweep = "| [1.526 cpu0] usb-load: sweeping disk 0 from block 6569336 to 7507812, \ rewriting each run with the bytes just read from it, until this machine is \ diff --git a/tests/common/power.rs b/tests/common/power.rs index cc369b2179..aa88491911 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -302,6 +302,15 @@ pub fn usb_load_chain(after: &serial::Serial) -> Result<(), String> { Ok(()) } +/// The `cpuN` the bracket of `line`'s record names, before `needle`. +fn record_cpu<'a>(line: &'a str, needle: &str) -> Option<&'a str> { + line.split(needle) + .next()? + .split(|c: char| c.is_whitespace() || c == '[' || c == ']') + .filter(|word| word.strip_prefix("cpu").is_some_and(|n| !n.is_empty() && n.bytes().all(|b| b.is_ascii_digit()))) + .last() +} + /// The metal half of [`boot_deadline_ends_a_wedge`]: a T14 boot that wedged on /// purpose ended itself, and the pass after the reset read why off the page. /// @@ -314,12 +323,15 @@ pub fn deadline_wedge_chain(after: &serial::Serial) -> Result<(), String> { let said = after.must_say_after(bootlog::PREVIOUS_PANIC, bootlog::DEADLINE_EXPIRED)?.to_string(); // The control: the machine reached the staged wedge, and then never reached // the reset it was one statement away from. - after.must_say_after(bootlog::PREVIOUS_PANIC, bootlog::WEDGE_STAGED)?; - // And the CPU that asked for it took interrupts again: it comes through the - // syscall gate with `IF` masked, and one left deaf is what the lockup - // detector ends a machine for. On this machine the assertion has a counter - // behind it, which is what the guest's has not. - after.must_say_after(bootlog::PREVIOUS_PANIC, bootlog::WEDGE_ARRIVED_DEAF)?; + let staged = after.must_say_after(bootlog::PREVIOUS_PANIC, bootlog::WEDGE_STAGED)?; + // And the CPU that asked for it arrived through the syscall gate with + // interrupts open: one that arrived deaf is the gate masking a syscall's + // body. Keyed to that CPU, because every other one arrives awake from a + // pass whatever the gate does. + let cpu = record_cpu(staged, bootlog::WEDGE_STAGED) + .ok_or_else(|| format!("no cpu in the record that staged the wedge: {staged:?}"))?; + after.must_say_after(bootlog::PREVIOUS_PANIC, &format!("wedge: {cpu} {}", bootlog::WEDGE_AWAKE))?; + says_nothing_of(after, bootlog::WEDGE_ARRIVED_DEAF)?; says_nothing_of(after, bootlog::REBOOTING)?; // **The two bounds composing, on the one machine that has both.** This // wedge spins with `IF` set, so every CPU still takes its timer interrupt diff --git a/tests/latencycase/system.toml b/tests/latencycase/system.toml index 59994ad5a5..069b0a1e26 100644 --- a/tests/latencycase/system.toml +++ b/tests/latencycase/system.toml @@ -20,7 +20,8 @@ syscap = ["logread"] [programs.test-runner] receives = ["power"] args = ["test_rs_cyclictest", "test_rs_sched_stress", "reboot"] -syscap = ["rt", "dup"] +# `counters` for cyclictest's SMI reads either side of its run. +syscap = ["rt", "dup", "counters"] [programs.toybox] diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index a60790f2e2..757e1845b3 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -7,12 +7,23 @@ //! [`SPIN`] iterations on a thread per CPU begun at `idle1`. Each read's //! records follow a line with the clock after it and what the read took, a //! whole round each, none joining another's. +//! +//! **Then `loaded`: how late the round's kick reaches each CPU** while a thread +//! per CPU spawns a program that exits at once, which is the load Linux's +//! timer reading of this machine was taken under. A round's reader kicks every +//! other CPU and then stamps its own block, and each CPU stamps its block in +//! its kick handler, so a CPU's stamp less the round's earliest is how late +//! its kick handler ran, short by however long the earliest came after the +//! kicks. A round across which a CPU's SMI count moved is dropped, since an +//! SMI stops every CPU, and so is one with a CPU stale. +use std::process::Command; +use std::sync::atomic::{AtomicBool, Ordering}; use std::time::{Duration, Instant}; use toyos::endow::{Endowments, SYSCAP_LABEL}; use toyos::syscap::SysCap; -use toyos_abi::counters::{RawRecord, Record}; +use toyos_abi::counters::{Counter, RawRecord, Record}; use toyos_abi::syscall; /// The idle span: long enough that a CPU's busy fraction is its idle one and @@ -25,6 +36,88 @@ const IDLE: Duration = Duration::from_secs(1); /// the frequency. const SPIN: u64 = 4_000_000_000; +/// How long `loaded` samples rounds for: a share of the job list's bound +/// (`toyos_tco::JOB_BOUND_MS`) the reads before it leave. +const LOADED: Duration = Duration::from_secs(20); + +/// What this binary's own children are asked to do: exit at once. +const EXIT_AT_ONCE: &str = "exit-at-once"; + +/// Every CPU's records of one round. +fn round(cap: &SysCap) -> Vec { + let mut raw = vec![RawRecord::EMPTY; syscall::cpu_count() as usize]; + let n = cap.counters(&mut raw).expect("the estate's capability reads the counters"); + raw[..n].iter().map(|r| Record::decode(r).expect("a record that decodes")).collect() +} + +/// The nearest-rank `q` of an already-sorted sample. +fn rank(sorted: &[u64], q: f64) -> u64 { + sorted[((sorted.len() as f64 * q).ceil() as usize).clamp(1, sorted.len()) - 1] +} + +/// The `loaded` phase, in the module header's words. +fn loaded(cap: &SysCap) { + let cpus = syscall::cpu_count() as usize; + let stop = AtomicBool::new(false); + let mut late: Vec> = vec![Vec::new(); cpus]; + let (mut smi, mut stale) = (0u64, 0u64); + let (first, last) = std::thread::scope(|s| { + for _ in 0..cpus { + s.spawn(|| { + while !stop.load(Ordering::Relaxed) { + let status = Command::new("/system/bin/test_rs_counters_metal") + .arg(EXIT_AT_ONCE) + .status() + .expect("this binary spawns itself"); + assert!(status.success(), "a child that exits at once exited {status:?}"); + } + }); + } + let begun = Instant::now(); + let mut before = round(cap); + let first = (toyos_abi::clock::nanos_since_boot(), before.iter().filter_map(|r| r.get(Counter::Stamp)).max()); + let mut last = first; + while begun.elapsed() < LOADED { + let records = round(cap); + last = (toyos_abi::clock::nanos_since_boot(), records.iter().filter_map(|r| r.get(Counter::Stamp)).max()); + let moved = records.iter().zip(&before).any(|(r, b)| r.get(Counter::Smi) != b.get(Counter::Smi)); + if records.iter().any(|r| r.stale) { + stale += 1; + } else if moved { + smi += 1; + } else { + let stamps: Vec = records.iter().map(|r| r.get(Counter::Stamp).expect("a fresh record is stamped")).collect(); + let earliest = *stamps.iter().min().expect("a machine has a cpu"); + for (cpu, stamp) in stamps.iter().enumerate() { + late[cpu].push(stamp - earliest); + } + } + before = records; + } + stop.store(true, Ordering::Relaxed); + (first, last) + }); + assert!(!late[0].is_empty(), "every round was dropped: {smi} across an SMI, {stale} with a cpu stale"); + let (Some(from), Some(to)) = (first.1, last.1) else { panic!("a round carried no stamp") }; + // Stamp ticks per microsecond, off the same rounds. + let per_us = (to - from) as f64 / ((last.0 - first.0) as f64 / 1_000.0); + println!( + "counters_metal loaded: {} rounds kept, {smi} dropped across an SMI, {stale} with a cpu stale, \ + at {per_us:.0} stamp ticks per us", + late[0].len() + ); + for (cpu, sample) in late.iter_mut().enumerate() { + sample.sort_unstable(); + let us = |ticks: u64| ticks as f64 / per_us; + println!( + "counters_metal loaded: cpu{cpu} kick late p50={:.1}us p99={:.1}us max={:.1}us", + us(rank(sample, 0.5)), + us(rank(sample, 0.99)), + us(rank(sample, 1.0)), + ); + } +} + fn read(cap: &SysCap, phase: &str) { let mut raw = vec![RawRecord::EMPTY; syscall::cpu_count() as usize]; let asked = Instant::now(); @@ -38,6 +131,9 @@ fn read(cap: &SysCap, phase: &str) { } fn main() { + if std::env::args().nth(1).as_deref() == Some(EXIT_AT_ONCE) { + return; + } let cap: SysCap = Endowments::get().take(SYSCAP_LABEL).expect("test-runner endows a capability"); read(&cap, "idle0"); std::thread::sleep(IDLE); @@ -53,4 +149,5 @@ fn main() { } }); read(&cap, "spin"); + loaded(&cap); } diff --git a/tests/toyos-rust-tests/src/bin/cyclictest.rs b/tests/toyos-rust-tests/src/bin/cyclictest.rs index f443f525a2..a6d0b07ce7 100644 --- a/tests/toyos-rust-tests/src/bin/cyclictest.rs +++ b/tests/toyos-rust-tests/src/bin/cyclictest.rs @@ -27,11 +27,17 @@ //! `userland/metalprobe` spells the same contract for the device suite, and the //! sign is what separates the two halves of it there as here. Every percentile //! is on stdout as well, for the host that has a console to read it on. +//! +//! **Beside the distribution, when its worst wake was and each CPU's SMI count +//! either side of the run**, so a reader can say whether that wake waited out +//! the firmware: an SMI stops every CPU at once, and its count moves on all of +//! them alike. use std::process::exit; use toyos::endow::{Endowments, SYSCAP_LABEL}; use toyos::syscap::SysCap; +use toyos_abi::counters::{Counter, RawRecord, Record}; use toyos_abi::syscall; /// How often a wake is asked for. Ten thousand of these is two seconds of a @@ -58,6 +64,7 @@ enum Refusal { BandRefused = -2, /// The p99 is past the histogram's last bucket: a floor, not a measurement. PastTheHistogram = -3, + CountersRefused = -4, } fn refuse(why: Refusal, said: &str) -> ! { @@ -65,6 +72,26 @@ fn refuse(why: Refusal, said: &str) -> ! { exit(why as i32); } +/// When the counters were read, and each CPU's SMI count, `-` where its CPU +/// counts none. +fn smis(cap: &SysCap) -> (u64, String) { + let mut raw = vec![RawRecord::EMPTY; syscall::cpu_count() as usize]; + let read = match cap.counters(&mut raw) { + Ok(read) => read, + Err(e) => refuse(Refusal::CountersRefused, &format!("the counters read was refused: {e:?}")), + }; + let at = toyos_abi::clock::nanos_since_boot(); + let counts = raw[..read] + .iter() + .map(|r| match Record::decode(r).expect("the kernel wrote a record that decodes").get(Counter::Smi) { + Some(n) => n.to_string(), + None => "-".to_string(), + }) + .collect::>() + .join(","); + (at, counts) +} + fn main() { // **The band is the privilege and it is asked for by name.** A refusal is // loud rather than silently measuring the ordinary band: the two are @@ -84,10 +111,12 @@ fn main() { let mut histogram = vec![0u32; BUCKETS]; let mut overflow = 0u32; let mut worst = 0u64; + let mut worst_at = 0u64; for _ in 0..WARMUP { syscall::nanosleep(PERIOD_NS); } + let before = smis(&cap); // The origin for the whole run, taken after the warm-up so the warm-up's // own drift is in no later target. let start = toyos_abi::clock::nanos_since_boot(); @@ -101,14 +130,23 @@ fn main() { if let Some(remaining) = target.checked_sub(now).filter(|left| *left > 0) { syscall::nanosleep(remaining); } - let late_us = toyos_abi::clock::nanos_since_boot().saturating_sub(target) / 1_000; - worst = worst.max(late_us); + let woke = toyos_abi::clock::nanos_since_boot(); + let late_us = woke.saturating_sub(target) / 1_000; + if late_us > worst { + (worst, worst_at) = (late_us, woke); + } match usize::try_from(late_us).ok().filter(|us| *us < BUCKETS) { Some(bucket) => histogram[bucket] += 1, None => overflow += 1, } } + let after = smis(&cap); + println!( + "cyclictest: the worst wake was at {worst_at} ns; smi per cpu {} at {} ns and {} at {} ns", + before.1, before.0, after.1, after.0 + ); + // `None` where the sample wanted is in the overflow, which has no bucket to // name. let percentile = |want: usize| -> Option { diff --git a/tests/toyos-rust-tests/src/bin/ring0_timer_in_syscall.rs b/tests/toyos-rust-tests/src/bin/ring0_timer_in_syscall.rs new file mode 100644 index 0000000000..ec5f1c9198 --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/ring0_timer_in_syscall.rs @@ -0,0 +1,20 @@ +//! A timer interrupt lands inside a syscall's body, and its fire re-arms one +//! quantum and not the span just armed. +//! +//! **A guest on the test kernel**, because whether the CPU takes an interrupt +//! inside a syscall exists only on a running gate, and nothing a guest does +//! puts one there on demand. `SYS_DEBUG`'s `RING0_TIMER_IN_SYSCALL` arms this +//! CPU's timer for 100 µs and waits inside the syscall for the kernel's own +//! fire; the gate, the fire and its re-arm are the shipped paths. Nothing is +//! timed: a gate that kept interrupts masked answers that no fire came within +//! the actuator's ceiling. + +use toyos_abi::syscall::{self, debug_action}; + +fn main() { + let answer = syscall::debug(debug_action::RING0_TIMER_IN_SYSCALL); + assert_ne!(answer, debug_action::RING0_FIRE_NEVER, "no timer interrupt reached the syscall's body"); + assert_ne!(answer, debug_action::RING0_FIRE_OTHER_SPAN, "the fire inside the syscall re-armed another span than a quantum"); + assert_eq!(answer, debug_action::RING0_FIRE_REARMED, "an answer the actuator does not give"); + println!("ring0_timer_in_syscall: the timer interrupted the syscall's body and re-armed a quantum"); +} diff --git a/tests/toyos.rs b/tests/toyos.rs index 7fac3b6711..da9b8ffb1c 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -57,6 +57,9 @@ const ACTUATOR_TESTS: &[&str] = &[ // again, which is what a CPU silent past a read's bound is to the reader, // and nothing in a guest makes one on demand. "counters_silent", + // Action 26: the timer's interrupt inside a syscall's body, which only a + // running gate decides and nothing in a guest puts there on demand. + "ring0_timer_in_syscall", ]; /// What [`ACTUATOR_TESTS`] boots: the one kernel that carries `SYS_DEBUG`, with @@ -155,6 +158,9 @@ const DRIVEN_AND_SHARED: &[&str] = &[ // Its shared run is the x86-64 verdict; `virt_readonly_copyout` builds it // for AArch64 and runs it on that architecture's job case. "abuse_readonly_copyout", + // Its actuator-boot run is the x86-64 verdict; `virt_ring0_timer_in_syscall` + // builds it for AArch64 and runs it on that architecture's job case. + "ring0_timer_in_syscall", // Its shared run asserts every arm's kill; `crash_report_reads_no_kernel_memory` // reads what the kernel said of two of them. "fault_gates", @@ -193,6 +199,7 @@ const SCREEN_TESTS: &[(&str, qemu::Profile)] = &[ ("virt_unmap_touch", qemu::Profile::VirtEl2), ("virt_debug_refused", qemu::Profile::VirtEl2), ("virt_readonly_copyout", qemu::Profile::VirtEl2), + ("virt_ring0_timer_in_syscall", qemu::Profile::VirtEl2), ("virt_mask_windows", qemu::Profile::VirtEl2), ("virt_smp", qemu::Profile::VirtEl2), ("virt_el1_smp", qemu::Profile::VirtTcg), @@ -217,6 +224,10 @@ const MACHINE_TESTS: &[&str] = &[ // no way to turn it back on, so only a machine QEMU reports stopping can // be asked. `machine_soft_off_decoded` reads the T14's own decode. "machine_shutdown", + // A `mask-windows` kernel's bookkeeping on x86-64, where a syscall's body + // opens interrupts: `virt_mask_windows` reads AArch64's alone, and the + // T14's `mask_windows` row is in no CI. + "x86_mask_windows", ]; /// **The metal profile**: which registrations run on the ThinkPad T14, what @@ -1464,6 +1475,9 @@ fn check_colors( /// `test_rs_abuse_readonly_copyout`. const VIRT_COPYOUT: &str = "abuse_readonly_copyout"; +/// The same for its job `test_rs_ring0_timer_in_syscall`. +const VIRT_RING0_TIMER: &str = "ring0_timer_in_syscall"; + /// `tests/toyos-rust-tests`' binary that `tests/virtsmpcase` runs as its job /// `test_rs_counters_read`. const VIRT_COUNTERS_READ: &str = "counters_read"; @@ -1501,7 +1515,7 @@ fn virt_job(profile: qemu::Profile, job: &str, said: &str) -> Result<(), String> smp: 1, kernel_features: toyos_build::build::TEST_KERNEL, ready_marker: "control registers: SCTLR_EL1=", - extra_root_files: vec![suite_bin(profile.arch(), VIRT_COPYOUT)], + extra_root_files: vec![suite_bin(profile.arch(), VIRT_COPYOUT), suite_bin(profile.arch(), VIRT_RING0_TIMER)], ..Default::default() }, ); @@ -1573,6 +1587,38 @@ fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { mask_windows(&serial, VIRT_CPUS) } +/// The windows on x86-64: `tests/testcases` on a `mask-windows` kernel under +/// [`WINDOWS_LOAD`], judged on the whole console once the boot has said its +/// last word. Its verdict is bookkeeping and not a duration: an `IF` change no +/// hook saw, or a lock an interrupt handler took, panics the kernel. +fn x86_mask_windows(test_config: &Path) -> Result<(), String> { + let profile = qemu::Profile::Headless; + let herd = WINDOWS_LOAD.strip_prefix("test_rs_").expect("a suite binary's job name"); + let mut qemu = QemuInstance::boot_with_options( + test_config, + &[], + &[], + BootOptions { + profile, + kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL, + extra_root_files: vec![suite_bin(profile.arch(), herd)], + ..Default::default() + }, + ); + let mut serial = qemu.boot_log().to_string(); + writeln!(qemu.stdin_mut(), "run {WINDOWS_LOAD}").expect("write to QEMU stdin"); + qemu.flush_stdin(); + await_marker(&mut qemu, &mut serial, &format!("===TEST_END {WINDOWS_LOAD} "), "the windows load to end")?; + if !serial.contains(&format!("===TEST_END {WINDOWS_LOAD} exit=0===")) { + return Err(format!("{WINDOWS_LOAD} did not exit 0\nserial:\n{serial}")); + } + writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); + qemu.flush_stdin(); + // To the boot's last word, said after every census and its windows. + await_marker(&mut qemu, &mut serial, power::SHUTTING_DOWN, "the boot's last word")?; + mask_windows(&serial, BootOptions::default().smp) +} + /// Boot `tests/virtsmpcase` as `options` say. fn boot_virt_smp(options: BootOptions) -> QemuInstance { let config = compile::repo_root().join("tests/virtsmpcase/system.toml"); @@ -2157,6 +2203,11 @@ fn run_screen_test(name: &str, profile: qemu::Profile, test_config: &Path) -> Re "virt_readonly_copyout" => { virt_job(profile, &format!("test_rs_{VIRT_COPYOUT}"), "a syscall writes only where its caller could store") } + "virt_ring0_timer_in_syscall" => virt_job( + profile, + &format!("test_rs_{VIRT_RING0_TIMER}"), + "the timer interrupted the syscall's body and re-armed a quantum", + ), "virt_mask_windows" => virt_mask_windows(profile), "virt_irq_storm" => { // The CPU floods itself with SGIs until the timer has fired a @@ -2447,6 +2498,7 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> { "iommu_virtio_platform" => common::iommu::iommu_virtio_platform(test_config), "nested_nmi_is_loud" => faults::nested_nmi_is_loud(test_config), "machine_shutdown" => power::machine_shutdown(test_config), + "x86_mask_windows" => x86_mask_windows(test_config), other => Err(format!("unknown machine test {other}")), } } @@ -3274,7 +3326,9 @@ const SMI_SPAN_NS: u64 = 4_444_000_000; /// /// Read and not held, beside Linux's turbostat on the same machine /// (`tests/t14-linux/`): each CPU's idle busy fraction, its busy -/// frequency under the spin, and what one round cost its reader. +/// frequency under the spin, and what one round cost its reader; and beside +/// Linux's loaded timer reading (`issues/kernel/toyos-beats-linuxs-latency-on-the-t14.md`), +/// how late each CPU's kick handler ran under the `loaded` phase. fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { type Read<'a> = BTreeMap>; back.job_passed("test_rs_counters_metal")?; @@ -3360,6 +3414,10 @@ fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { let values: Vec = rows.filter(|r| r[0] == "-").filter_map(|r| r.get(at)?.parse().ok()).collect(); Ok(values.iter().fold((f64::MAX, f64::MIN), |(lo, hi), &v| (lo.min(v), hi.max(v)))) }; + log.must_say("counters_metal loaded: ")?; + for said in log.text().lines().filter(|l| l.contains("counters_metal loaded: ")) { + eprintln!(" [counters] {}", said.split("counters_metal ").nth(1).unwrap_or(said).trim()); + } let idle = linux(include_str!("t14-linux/turbostat-idle.txt"), "Busy%")?; let loaded = linux(include_str!("t14-linux/turbostat-loaded.txt"), "Bzy_MHz")?; eprintln!( @@ -3657,6 +3715,9 @@ fn tlb_shootdown_cost(log: &str, cpus: u32) -> Result<(u64, u64), String> { /// is the whole of what separates the two, and that contract is in the binary's /// own module header. fn wake_latency_recorded(boot: &metal::Readback) -> Result<(), String> { + for said in boot.log().text().lines().filter(|l| l.contains("cyclictest: ")) { + eprintln!(" [latency] {}", said.trim()); + } let code = boot.exit_code("test_rs_cyclictest")?; if code < 0 { return Err(format!( diff --git a/tests/virtjobcase/system.toml b/tests/virtjobcase/system.toml index 93fcb0a1b9..bc852a4360 100644 --- a/tests/virtjobcase/system.toml +++ b/tests/virtjobcase/system.toml @@ -1,7 +1,8 @@ -# One CPU and the AArch64 guest's jobs, each a kernelprobe applet or, last because -# a kernel it fails on rewrites the clock page every reader asserts on, the -# suite's `test_rs_abuse_readonly_copyout`, which the harness puts on ROOT; -# each job's line comes only if the kernel kept what that job asks about. +# One CPU and the AArch64 guest's jobs, each a kernelprobe applet or one of the +# suite's binaries the harness puts on ROOT — `test_rs_abuse_readonly_copyout` +# last, because a kernel it fails on rewrites the clock page every reader +# asserts on; each job's line comes only if the kernel kept what that job asks +# about. [boot] start = ["logkeeper", "test-runner"] @@ -13,7 +14,7 @@ syscap = ["logread"] receives = ["power"] # Four minutes from boot rather than one: every job here runs on an emulated # CPU, and a job past the bound reboots the guest with the job named. -args = ["--bound-ms=240000", "preempt", "fp_isolation", "first_entry", "unmap_touch", "debug_refused", "test_rs_abuse_readonly_copyout"] +args = ["--bound-ms=240000", "preempt", "fp_isolation", "first_entry", "unmap_touch", "debug_refused", "test_rs_ring0_timer_in_syscall", "test_rs_abuse_readonly_copyout"] [programs.kernelprobe] diff --git a/toyos-abi/src/syscall.rs b/toyos-abi/src/syscall.rs index d63e214f3c..3daf21e0a8 100644 --- a/toyos-abi/src/syscall.rs +++ b/toyos-abi/src/syscall.rs @@ -822,6 +822,14 @@ pub mod debug_action { pub const COUNTERS_DEAF: u64 = 24; /// Every CPU answers rounds again. pub const COUNTERS_HEAR: u64 = 25; + /// Arm this CPU's timer to fire within 100 µs and wait inside the syscall + /// for the kernel's own fire. Answers [`RING0_FIRE_REARMED`] once it fired + /// and re-armed a quantum, [`RING0_FIRE_NEVER`] if none came within + /// 100 ms, and [`RING0_FIRE_OTHER_SPAN`] if it re-armed something else. + pub const RING0_TIMER_IN_SYSCALL: u64 = 26; + pub const RING0_FIRE_REARMED: u64 = 0; + pub const RING0_FIRE_NEVER: u64 = 1; + pub const RING0_FIRE_OTHER_SPAN: u64 = 2; } /// Every kind of kernel object, in the order the kernel's own `kobject!` From 2b9697284384696d174643eb59d79f694f05da26 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 08:48:01 +0200 Subject: [PATCH 2/8] G1 on x86-64 runs as its own guest row The shared boots that also run test_rs_ring0_timer_in_syscall are the T14's alone, so x86_ring0_timer_in_syscall stages it on a guest of the actuator kernel, beside virt_ring0_timer_in_syscall. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- tests/toyos.rs | 55 +++++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 46 insertions(+), 9 deletions(-) diff --git a/tests/toyos.rs b/tests/toyos.rs index da9b8ffb1c..39bef7ebd0 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -158,8 +158,9 @@ const DRIVEN_AND_SHARED: &[&str] = &[ // Its shared run is the x86-64 verdict; `virt_readonly_copyout` builds it // for AArch64 and runs it on that architecture's job case. "abuse_readonly_copyout", - // Its actuator-boot run is the x86-64 verdict; `virt_ring0_timer_in_syscall` - // builds it for AArch64 and runs it on that architecture's job case. + // Its actuator-boot run is the T14's verdict; `x86_ring0_timer_in_syscall` + // and `virt_ring0_timer_in_syscall` drive it in guests of both + // architectures. "ring0_timer_in_syscall", // Its shared run asserts every arm's kill; `crash_report_reads_no_kernel_memory` // reads what the kernel said of two of them. @@ -228,6 +229,9 @@ const MACHINE_TESTS: &[&str] = &[ // opens interrupts: `virt_mask_windows` reads AArch64's alone, and the // T14's `mask_windows` row is in no CI. "x86_mask_windows", + // The timer's interrupt inside a syscall's body on x86-64: the shared + // boots that also run it are the T14's alone. + "x86_ring0_timer_in_syscall", ]; /// **The metal profile**: which registrations run on the ThinkPad T14, what @@ -1475,7 +1479,8 @@ fn check_colors( /// `test_rs_abuse_readonly_copyout`. const VIRT_COPYOUT: &str = "abuse_readonly_copyout"; -/// The same for its job `test_rs_ring0_timer_in_syscall`. +/// The same for its job `test_rs_ring0_timer_in_syscall`, which +/// `x86_ring0_timer_in_syscall` stages on x86-64. const VIRT_RING0_TIMER: &str = "ring0_timer_in_syscall"; /// `tests/toyos-rust-tests`' binary that `tests/virtsmpcase` runs as its job @@ -1606,12 +1611,7 @@ fn x86_mask_windows(test_config: &Path) -> Result<(), String> { }, ); let mut serial = qemu.boot_log().to_string(); - writeln!(qemu.stdin_mut(), "run {WINDOWS_LOAD}").expect("write to QEMU stdin"); - qemu.flush_stdin(); - await_marker(&mut qemu, &mut serial, &format!("===TEST_END {WINDOWS_LOAD} "), "the windows load to end")?; - if !serial.contains(&format!("===TEST_END {WINDOWS_LOAD} exit=0===")) { - return Err(format!("{WINDOWS_LOAD} did not exit 0\nserial:\n{serial}")); - } + run_job(&mut qemu, &mut serial, WINDOWS_LOAD)?; writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); qemu.flush_stdin(); // To the boot's last word, said after every census and its windows. @@ -1619,6 +1619,42 @@ fn x86_mask_windows(test_config: &Path) -> Result<(), String> { mask_windows(&serial, BootOptions::default().smp) } +/// `job` run on an x86-64 guest's runner, to its exit 0, everything the +/// console said meanwhile added to `serial`. +fn run_job(qemu: &mut QemuInstance, serial: &mut String, job: &str) -> Result<(), String> { + writeln!(qemu.stdin_mut(), "run {job}").expect("write to QEMU stdin"); + qemu.flush_stdin(); + await_marker(qemu, serial, &format!("===TEST_END {job} "), &format!("the job {job} to end"))?; + if !serial.contains(&format!("===TEST_END {job} exit=0===")) { + return Err(format!("{job} did not exit 0\nserial:\n{serial}")); + } + Ok(()) +} + +/// `test_rs_ring0_timer_in_syscall` on an x86-64 guest of the kernel that +/// carries `SYS_DEBUG`, where the binary itself is the verdict. +fn x86_ring0_timer_in_syscall(test_config: &Path) -> Result<(), String> { + let profile = qemu::Profile::Headless; + let mut qemu = QemuInstance::boot_with_options( + test_config, + &[], + &[], + BootOptions { + profile, + kernel_features: ACTUATOR_KERNEL, + extra_root_files: vec![suite_bin(profile.arch(), VIRT_RING0_TIMER)], + ..Default::default() + }, + ); + let mut serial = qemu.boot_log().to_string(); + run_job(&mut qemu, &mut serial, &format!("test_rs_{VIRT_RING0_TIMER}"))?; + match serial.lines().find(|l| l.contains("ring0_timer_in_syscall: ")) { + Some(said) => eprintln!(" [x86] {}", said.trim()), + None => return Err(format!("the binary said nothing\nserial:\n{serial}")), + } + Ok(()) +} + /// Boot `tests/virtsmpcase` as `options` say. fn boot_virt_smp(options: BootOptions) -> QemuInstance { let config = compile::repo_root().join("tests/virtsmpcase/system.toml"); @@ -2499,6 +2535,7 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> { "nested_nmi_is_loud" => faults::nested_nmi_is_loud(test_config), "machine_shutdown" => power::machine_shutdown(test_config), "x86_mask_windows" => x86_mask_windows(test_config), + "x86_ring0_timer_in_syscall" => x86_ring0_timer_in_syscall(test_config), other => Err(format!("unknown machine test {other}")), } } From 7c550fa1ffb1e9f3dab74919ef1a6d5fce4083fe Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 09:12:44 +0200 Subject: [PATCH 3/8] The actuator counts fires after it arms, not before A fire landing between the count read and the arm re-armed a quantum, which the arm then shortened to 100 us, and the loop judged that comparator as the fire's: virt_ring0_timer_in_syscall answered "another span" once in a whole-suite run on a host at load 44-59 on 14 cores. A probe that waits for a fire inside that window reds both architectures every time; one that waits for a fire between the arm and the count read is green on both. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- kernel/src/syscall/debug.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/kernel/src/syscall/debug.rs b/kernel/src/syscall/debug.rs index 58716c55de..666adfc316 100644 --- a/kernel/src/syscall/debug.rs +++ b/kernel/src/syscall/debug.rs @@ -54,9 +54,10 @@ pub(super) fn ring0_timer_in_syscall() -> u64 { use toyos_abi::syscall::debug_action::{RING0_FIRE_NEVER, RING0_FIRE_OTHER_SPAN, RING0_FIRE_REARMED}; const WITHIN_NS: u64 = 100_000; const CEILING_NS: u64 = 100_000_000; - let fired = crate::arch::percpu::kernel_timer_fires(); crate::arch::irqchip::arm_within(WITHIN_NS); let armed = crate::arch::irqchip::comparator(); + // Counted after the arm, so every fire the count sees found this arm or a later one. + let fired = crate::arch::percpu::kernel_timer_fires(); let ends = crate::clock::nanos_since_boot() + CEILING_NS; loop { // The clock before the count, so a ceiling read past is one the fire had every chance to beat. From f89e731282fca5b52d3f034ff60e68fdb622db11 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 09:22:36 +0200 Subject: [PATCH 4/8] File: a muted screen test pays its ceiling before any boot has measured the host screen_panic_muted red once at 7c550fa1f on the dev host at load 80 on 14 cores, its deadline fixed at 1x before any guest of the run had booted; the same run measured 1.52x by its end. Off this branch's task, so filed and not fixed. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...g-before-any-boot-has-measured-the-host.md | 28 +++++++++++++++++++ 1 file changed, 28 insertions(+) create mode 100644 issues/build/a-muted-screen-test-pays-its-ceiling-before-any-boot-has-measured-the-host.md diff --git a/issues/build/a-muted-screen-test-pays-its-ceiling-before-any-boot-has-measured-the-host.md b/issues/build/a-muted-screen-test-pays-its-ceiling-before-any-boot-has-measured-the-host.md new file mode 100644 index 0000000000..4fda2fc7da --- /dev/null +++ b/issues/build/a-muted-screen-test-pays-its-ceiling-before-any-boot-has-measured-the-host.md @@ -0,0 +1,28 @@ +--- +status: open +kind: tooling +opened: 2026-10-04 +--- + +# A muted screen test pays its ceiling before any boot has measured the host + +`QemuInstance::screendump_while` (`tests/common/qemu.rs`) fixes its deadline +once, at its start, through `budget_smp`, whose host factor is the run's +fastest boot so far (`host_scale`). A muted guest reaches no ready marker, so +its own boot never feeds that factor, and a muted test that starts before any +other guest of the run has booted pays its ceiling at 1×, however loaded the +host is. + +Seen once, on the dev host at load averages 80.26, 74.24 and 66.53 (14 +cores), in a whole `cargo test --test toyos-build` run at `7c550fa1f` on +`wt/toyos-irqon`: `screen_panic_muted` was one of the twelve tests the run +started at 07:17:52, its kernel built at 07:18:20, and it was red at 07:18:51, +before any test of the run had passed, with `"PANIC:" not on +screen of a guest with no serial port at all`. The decoded screen held only +the kernel's first three lines, all stamped 0.000. The same run ended with +`fastest boot 2162 ms against the reference 1424 ms — liveness ceilings paid +at 1.52x`. The whole run at `2b9697284`, at 1.01x, had it green. + +**Exit**: a muted screen test's wait is bounded by the guest's progress or by a +host factor measured before its deadline is fixed, and a muted test run first +on a loaded host is green. From 8c27453b3a494b5dd154ed798a4ec9fd28d7f039 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 09:46:13 +0200 Subject: [PATCH 5/8] The wedge judge reads the staging CPU with next_back clippy's double_ended_iterator_last refused `.last()` in record_cpu, the one red step of `--ci host` at f89e73128. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- tests/common/power.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/common/power.rs b/tests/common/power.rs index aa88491911..2ded9cee9d 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -308,7 +308,7 @@ fn record_cpu<'a>(line: &'a str, needle: &str) -> Option<&'a str> { .next()? .split(|c: char| c.is_whitespace() || c == '[' || c == ']') .filter(|word| word.strip_prefix("cpu").is_some_and(|n| !n.is_empty() && n.bytes().all(|b| b.is_ascii_digit()))) - .last() + .next_back() } /// The metal half of [`boot_deadline_ends_a_wedge`]: a T14 boot that wedged on From a57d2395c2cdc70f683ff96828e50c23319a4c04 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 09:52:31 +0200 Subject: [PATCH 6/8] The wedge judge finds the staging CPU with rfind clippy's manual_rfind refused filter(..).next_back(), the one red step of `--ci host` at 8c27453b3. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- tests/common/power.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/tests/common/power.rs b/tests/common/power.rs index 2ded9cee9d..e2a690c2bd 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -307,8 +307,7 @@ fn record_cpu<'a>(line: &'a str, needle: &str) -> Option<&'a str> { line.split(needle) .next()? .split(|c: char| c.is_whitespace() || c == '[' || c == ']') - .filter(|word| word.strip_prefix("cpu").is_some_and(|n| !n.is_empty() && n.bytes().all(|b| b.is_ascii_digit()))) - .next_back() + .rfind(|word| word.strip_prefix("cpu").is_some_and(|n| !n.is_empty() && n.bytes().all(|b| b.is_ascii_digit()))) } /// The metal half of [`boot_deadline_ends_a_wedge`]: a T14 boot that wedged on From edd0fd90f3139c620e69533479d9c790b2d9c1b2 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 13:17:02 +0200 Subject: [PATCH 7/8] Answer review round 1: the seal names the spin, the records carry the T14's readings MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The boot deadline's seal now writes one line per CPU, ` cpuN pc= +`, resolved by the kernel against its own symbols through `symbols::At`, which moves out of `hardlockup` so both seals spell a pc one way. `deadline_wedge_chain` requires the staging CPU's line to name `kernel::deadline::this_cpu`, which is never inlined so the name holds; `src/bootlog.rs` pins the line's form and the function. Before this nothing read the pc list, and passing the saved `rax` instead of the frame's `rip` stayed green (review round 1). `KERNEL_PC` is indexed by CPU id, not skipped on a miss. The records the review names carry #716's T14 readings (comment 5979107466): - `syscall-preemption-is-incidental.md` records base and head herd windows, and its exit reads the preemption-off window, the defect its title names: the orchestrator's amendment. - The toybox-spawn and PCI-claim files are renamed: the head refutes "interrupts off" in both slugs, and each carries its table. The walk file records the 63 µs bound at N = 256. - `no-program-measures-toyos-against-linux-on-one-machine.md` names what `counters_metal`'s `loaded` phase reads and what it does not. `QUANTUM_NS`'s restated "Ten" is deleted. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...-in-the-machine-can-read-the-trace-ring.md | 4 +-- ...ures-toyos-against-linux-on-one-machine.md | 8 ++++++ ...alk-by-the-threads-it-parks-on-one-ring.md | 10 ++++++- .../syscall-preemption-is-incidental.md | 26 +++++++++++++++---- ...ds-1-4-ms-of-preemption-off-on-the-t14.md} | 20 ++++++++++---- ...-lacks-holds-preemption-off-for-3-8-ms.md} | 21 ++++++++++++--- kernel/pure/sched/cpu.rs | 2 -- kernel/src/deadline.rs | 15 ++++++----- kernel/src/hardlockup/mod.rs | 19 +------------- kernel/src/symbols.rs | 16 +++++++++++- src/bootlog.rs | 14 ++++++++++ tests/checks.rs | 23 ++++++++++++---- tests/common/power.rs | 6 +++++ 13 files changed, 134 insertions(+), 50 deletions(-) rename issues/kernel/{the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md => the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-preemption-off-on-the-t14.md} (72%) rename issues/kernel/{the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md => the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-preemption-off-for-3-8-ms.md} (60%) diff --git a/issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md b/issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md index e88fc27e2c..b092e85240 100644 --- a/issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md +++ b/issues/diagnostics/nothing-in-the-machine-can-read-the-trace-ring.md @@ -38,9 +38,9 @@ anything more is built on it. trace. A system call held past the threshold in a shipped-configuration kernel reads back from the trace with its number and its program. A window's record names its opener by address, which - `issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md` + `issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-preemption-off-on-the-t14.md` and - `issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md` + `issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-preemption-off-for-3-8-ms.md` need. **Ruled** (owner, 2026-10-04), on when these steps start, **"Both in diff --git a/issues/hardware/no-program-measures-toyos-against-linux-on-one-machine.md b/issues/hardware/no-program-measures-toyos-against-linux-on-one-machine.md index 9e57c354f4..4c71197baa 100644 --- a/issues/hardware/no-program-measures-toyos-against-linux-on-one-machine.md +++ b/issues/hardware/no-program-measures-toyos-against-linux-on-one-machine.md @@ -21,3 +21,11 @@ two sides' IDs match or either side's changed across the window. **Mutation**, each red: a pair on one CPU passes; only the readings before the window compared, so a sibling that moved onto the initiator's CPU inside it passes. **Oracle**: Linux. + +What stands nearest is `counters_metal`'s `loaded` phase +(`tests/toyos-rust-tests/src/bin/counters_metal.rs`), the one lateness reading +the shipped kernel gives under load, and it is not this program's timer +lateness: it reads how late each CPU's kick handler ran after a round's +kicks, measured against the round's earliest stamp and so short by however +late that one was, once a round rather than at 1 kHz, on ToyOS alone, and it +holds no figure. 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 a001e0ac70..507e248542 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 @@ -44,7 +44,7 @@ span, and `649-r5/3-idle-halt-counted`) ran it with N = 256 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`), +(`issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-preemption-off-on-the-t14.md`), and the other seven read 257646 to 364953 in that boot. The three at `0aa8d4c88` (comment 5960575031, readbacks `649-r6/1-head`, @@ -67,6 +67,14 @@ machine's own events reached, and which boot carried one 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). +Those readings were the whole masked syscall, not the walk. With a syscall's +body open to interrupts, #716's six head boots of the same load at the same N +(comment 5979107466; readbacks `irqon/metal/head/mask_windows/runN` and +`irqon/metal/head-full`) read the longest `irqs_off_ns` in the herd's report +at 60479, 62947, 56462, 57842, 58396 and 59488, and every CPU between 41469 +and 62947 (`windowscase/kernel.log:424` to `:438`). That bounds the walk at +N = 256 from above at 63 µs; it says nothing of how the walk grows with N. + **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 size the diff --git a/issues/kernel/syscall-preemption-is-incidental.md b/issues/kernel/syscall-preemption-is-incidental.md index ea62968e88..bf2c619822 100644 --- a/issues/kernel/syscall-preemption-is-incidental.md +++ b/issues/kernel/syscall-preemption-is-incidental.md @@ -32,11 +32,27 @@ assumes. Owner: `issues/kernel/toyos-beats-linuxs-latency-on-the-t14.md`, whose second step is syscalls running with interrupts on (owner, 2026-10-03). -**Exit**, on the T14: the longest interrupts-off window the `mask_windows` row -reads under its load (`herd irqs_off_ns=`, printed by `windows_on_metal` in -`tests/toyos.rs`) is no longer than 131 µs, the track's ruled bar: a masked -window makes a timer's interrupt late by at most its own length. The row +The T14 read the step at #716 (comment 5979107466; readbacks +`irqon/metal/{base,head}/mask_windows/runN` and `irqon/metal/head-full`), +five `mask_windows` boots an arm, interleaved, and the head's full profile +once, `windows_on_metal`'s `herd` line: + +| arm | `irqs_off_ns` | `preempt_off_ns` | +|---|---|---| +| base, main at `d47b383cf` | 18863127, 1185364, 1084719, 1265962, 4703201 | 18862957, 1185277, 1065082, 1265899, 4703058 | +| head, images at `f89e73128` | 60479, 62947, 56462, 57842, 58396; 59488 | 1175425, 4711060, 4702163, 4714590, 9806929; 10784336 | + +The interrupts-off window is under 131 µs on every head boot; the +preemption-off window is not on any. The three head readings of 4.70 to +4.71 ms are an SMI's window by reading, no SMI count being read in that boot; +nothing names the 9.8 and 10.8 ms ones. + +**Exit**, on the T14: the longest preemption-off window the `mask_windows` row +reads under its load (`herd preempt_off_ns=`, printed by `windows_on_metal` in +`tests/toyos.rs`) is no longer than 131 µs, the track's ruled bar. The row cannot read it before step 1: a `mask-windows` kernel charges each of the firmware's 4.5 ms SMIs (`issues/hardware/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md`) -to whatever window it lands in. +to whatever window it lands in. This exit is the orchestrator's amendment at +#716's first review: it read the interrupts-off window, which step 2 shortened +while the defect this file names, preemption off for a whole syscall, stood. 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-preemption-off-on-the-t14.md similarity index 72% rename from issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md rename to issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-preemption-off-on-the-t14.md index f02c3cd2d2..897445e01f 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-preemption-off-on-the-t14.md @@ -4,7 +4,7 @@ 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 +# The CPU that spawns a toybox applet reads 1.4 ms of 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 @@ -45,10 +45,20 @@ else, `pwd`'s and `echo`'s. cpu7's line in each By reading, not measured: it is `SYS_SPAWN`, which ran with interrupts masked from entry to exit like every syscall then, and whose own record reads `total=1ms` for each of these applets. A report carries a span and no -address, so nothing names it. A syscall's body now runs with interrupts open -(`issues/kernel/syscall-preemption-is-incidental.md`) and preemption off, so -by reading the section leaves `irqs_off_ns` and stays in `preempt_off_ns`; -no T14 boot has read it since. +address, so nothing names it. + +A syscall's body now runs with interrupts open and preemption off +(`issues/kernel/syscall-preemption-is-incidental.md`), and the section left +`irqs_off_ns` and stayed in `preempt_off_ns`. #716's interleaved +`mask_windows` boots (comment 5979107466; readbacks +`irqon/metal/{base,head}/mask_windows/runN` and `irqon/metal/head-full`) ran +`pwd` alone of the applets, spawned from cpu7 on every boot; cpu7's line in +its report (`windowscase/kernel.log:396`, `:397` in `head-full`): + +| arm | `irqs_off_ns` | `preempt_off_ns` | +|---|---|---| +| base, main at `d47b383cf` | 1429697, 1334122, 1460438, 1385896, 1373747 | 1429402, 1333862, 1460269, 1385648, 1373471 | +| head, images at `f89e73128` | 1146, 1178, 1136, 1781, 1058; 1155 | 1317184, 1508859, 1463782, 1494243, 1511276; 1481928 | **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 diff --git a/issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md b/issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-preemption-off-for-3-8-ms.md similarity index 60% rename from issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md rename to issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-preemption-off-for-3-8-ms.md index bbcc7e524a..0a6ebe4abe 100644 --- a/issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md +++ b/issues/kernel/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-preemption-off-for-3-8-ms.md @@ -4,7 +4,7 @@ kind: defect opened: 2026-10-02 --- -# init's claim of a PCI function the T14 lacks holds interrupts off for 3.8 ms +# init's claim of a PCI function the T14 lacks holds preemption off for 3.8 ms On LENOVO 20W0003AMZ, BIOS N34ET71W (1.71), one boot of `main` at `c59e09ed6` with a throwaway instrument that names a window's opener and samples its CPU @@ -16,9 +16,22 @@ is in `PciDevice::is_id` under `pcidev::claim`. By reading, the claim reads the vendor ID of each of the 24 functions the kernel enumerated (`kernel/src/pcidev/mod.rs`); nothing has said what it spends 3.8 ms on. -A syscall's body now runs with interrupts open -(`issues/kernel/syscall-preemption-is-incidental.md`), so by reading this -window has left `irqs_off_ns`; no T14 boot has read it since. +A syscall's body now runs with interrupts open and preemption off +(`issues/kernel/syscall-preemption-is-incidental.md`). #716's interleaved +`mask_windows` boots (comment 5979107466; readbacks +`irqon/metal/{base,head}/mask_windows/runN` and `irqon/metal/head-full`) each +made this claim (`supervisor: diskserver: no pci:1b36:0010 on this machine`) +before the first job's report, which spans it and the partition claims below. +cpu0's line there: + +| arm | `irqs_off_ns` | `preempt_off_ns` | +|---|---|---| +| base, main at `d47b383cf` | 6592629, 6565352, 6491279, 6614740, 6509061 | 6592463, 6565169, 6491091, 6614595, 6508897 | +| head, images at `f89e73128` | 3061, 10315, 14214, 15492, 3510; 15409 | 6550562, 6517919, 6632892, 6549746, 6619444; 5706681 | + +On the head no CPU but the one `hold_once` held reads more than 44537 ns of +interrupts off in that report, which bounds every window inside the claim +from above; no reading separates the claim's own windows from the rest. Before the first job's exit cpu0 also carries init's partition claims, 6.0 and 6.6 ms in that boot (`issues/hardware/xhci-waits-are-spins.md`), and the diff --git a/kernel/pure/sched/cpu.rs b/kernel/pure/sched/cpu.rs index c55146863c..e4035747df 100644 --- a/kernel/pure/sched/cpu.rs +++ b/kernel/pure/sched/cpu.rs @@ -705,8 +705,6 @@ pub const PUSH_THRESHOLD: u32 = 2; /// How long a CPU may owe a pass and still be chosen as a target. /// -/// Ten [`QUANTUM_NS`]. -/// /// **The direction of error is chosen.** Refusing a CPU that was only slow puts /// one task elsewhere; accepting one that has stopped puts the task where /// nothing ever picks it up. diff --git a/kernel/src/deadline.rs b/kernel/src/deadline.rs index 3476a0e166..975d21de27 100644 --- a/kernel/src/deadline.rs +++ b/kernel/src/deadline.rs @@ -213,20 +213,19 @@ static KERNEL_PC: [AtomicU64; MAX_CPUS] = [const { AtomicU64::new(0) }; MAX_CPUS pub extern "C" fn poll_in_kernel(pc: u64) { let at = AT_TSC.load(Relaxed); if at != 0 { - if let Some(slot) = KERNEL_PC.get(crate::arch::percpu::cpu_id() as usize) { - slot.store(pc, Relaxed); - } + KERNEL_PC[crate::arch::percpu::cpu_id() as usize].store(pc, Relaxed); } past(at) } -/// ` cpuN=` for each online CPU, out of [`KERNEL_PC`]. +/// A line ` cpuN pc= +` for each online CPU, out of +/// [`KERNEL_PC`]; the harness reads the symbol (`src/bootlog.rs`). struct KernelPcs; impl core::fmt::Display for KernelPcs { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { for (cpu, pc) in KERNEL_PC.iter().enumerate().take(crate::smp::cpu_count() as usize) { - write!(f, " cpu{cpu}={:#x}", pc.load(Relaxed))?; + writeln!(f, " cpu{cpu} pc={}", crate::symbols::At(pc.load(Relaxed)))?; } Ok(()) } @@ -247,8 +246,8 @@ fn expire() -> ! { #[cfg(feature = "mask-windows")] crate::windows::stand_down(); crate::drivers::panic_console::seal_wedge(format_args!( - "{EXPIRED}: a bound of {} ms, reached at {} ms, with this machine in `{}`, each CPU's \ - timer last finding the kernel at{KernelPcs}. The tail of the log ring follows — which \ + "{EXPIRED}: a bound of {} ms, reached at {} ms, with this machine in `{}`. Where each \ + CPU's timer last found the kernel:\n{KernelPcs}The tail of the log ring follows — which \ is what nothing was draining.\n", BOUND_MS.load(Relaxed), crate::clock::nanos_since_boot() / 1_000_000, @@ -300,7 +299,9 @@ pub fn wedge_if_staged() { #[cfg(feature = "boot-actuators")] static STAGED: AtomicBool = AtomicBool::new(false); +// Never inlined: the seal names the spin by this symbol (`src/bootlog.rs`). #[cfg(feature = "boot-actuators")] +#[inline(never)] fn this_cpu() -> ! { // Preemption off, `IF` on and a one-shot armed: the shape a device // operation on this machine already runs in, so what the deadline has to diff --git a/kernel/src/hardlockup/mod.rs b/kernel/src/hardlockup/mod.rs index 3b2e518d8f..30b541879a 100644 --- a/kernel/src/hardlockup/mod.rs +++ b/kernel/src/hardlockup/mod.rs @@ -62,6 +62,7 @@ use core::sync::atomic::{AtomicBool, AtomicU64, Ordering::{Acquire, Relaxed, Rel use crate::arch::{cpu, percpu, pmu, trap}; use crate::smp; use crate::sched::MAX_CPUS; +use crate::symbols::At; /// The negative control, in a file of its own because it says what it staged /// and nothing here may say anything. @@ -368,24 +369,6 @@ impl fmt::Display for Waiting { } } -/// Where a `pc` is, spelled without saying a word: `symbols::resolve_kernel` -/// writes a log record, which is the one thing this path may not do. -struct At(u64); - -impl fmt::Display for At { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - write!(f, "{:#018x}", self.0)?; - match crate::symbols::kernel_symbol(self.0) { - None => Ok(()), - Some((name, offset)) => write!( - f, - " {}+{offset:#x}", - toyos_symbols::symbol_text(rustc_demangle::demangle(name)), - ), - } - } -} - /// What the machine looked like from the CPU that ended it. struct Report { me: usize, diff --git a/kernel/src/symbols.rs b/kernel/src/symbols.rs index f6756cf16d..803b847cc1 100644 --- a/kernel/src/symbols.rs +++ b/kernel/src/symbols.rs @@ -188,7 +188,21 @@ pub fn kernel_symbol(addr: u64) -> Option<(&'static str, u64)> { table.resolve(addr) } -fn log_kernel(addr: u64, lookup: impl FnOnce(&SymbolTable) -> Option<(&str, u64)>) -> Option { +/// Where a kernel `pc` is, spelled without saying a word: [`resolve_kernel`] +/// writes a log record, which an NMI or a seal may not. +pub struct At(pub u64); + +impl core::fmt::Display for At { + fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { + write!(f, "{:#018x}", self.0)?; + match kernel_symbol(self.0) { + None => Ok(()), + Some((name, offset)) => write!(f, " {}+{offset:#x}", symbol_text(rustc_demangle::demangle(name))), + } + } +} + +fn log_kernel(addr: u64,lookup: impl FnOnce(&SymbolTable) -> Option<(&str, u64)>) -> Option { let ptr = KERNEL_SYMS.load(Ordering::Acquire); if ptr.is_null() { log!(" {:#x}", addr); diff --git a/src/bootlog.rs b/src/bootlog.rs index 9bb14da32d..e1dea2990c 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -58,6 +58,15 @@ pub const WEDGE_ARRIVED_DEAF: &str = "arrived with interrupts off, through the syscall gate, and takes them again here"; pub const WEDGE_AWAKE: &str = "arrived with interrupts on"; +/// What the deadline's seal says before a CPU's last kernel `pc`, after its +/// `cpuN`, in `kernel/src/deadline.rs`. +pub const SEAL_PC: &str = " pc="; + +/// The function the wedge spins in, in `kernel/src/deadline.rs`, as the seal's +/// `pc` line names it: the staging CPU's line naming anything else is a seal +/// that names the wrong instruction. +pub const WEDGE_SPIN: &str = "kernel::deadline::this_cpu+"; + /// What the `usb-reset-under-load` arm says once it is streaming, and the three /// ways it says it is not, in `kernel/src/usb_gate.rs`. /// @@ -544,6 +553,11 @@ mod tests { ("kernel/src/deadline.rs", format!("WEDGE_STAGED: &str = \"{WEDGE_STAGED}\"")), ("kernel/src/deadline.rs", format!("\"{WEDGE_ARRIVED_DEAF}\"")), ("kernel/src/deadline.rs", format!("WEDGE_AWAKE: &str = \"{WEDGE_AWAKE}\"")), + ("kernel/src/deadline.rs", format!("\" cpu{{cpu}}{SEAL_PC}{{}}\"")), + ( + "kernel/src/deadline.rs", + format!("fn {}() -> !", WEDGE_SPIN.trim_end_matches('+').rsplit("::").next().expect("a path")), + ), ("kernel/src/usb_gate.rs", format!("LOAD_RUNNING: &str = \"{USB_LOAD_RUNNING}\"")), ("kernel/src/usb_gate.rs", format!("LOAD_REFUSED: &str = \"{USB_LOAD_REFUSED}\"")), ("kernel/src/usb_gate.rs", format!("LOAD_STOPPED: &str = \"{USB_LOAD_STOPPED}\"")), diff --git a/tests/checks.rs b/tests/checks.rs index a286057b75..04f50c4bd1 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -928,8 +928,8 @@ mod checks { Previous boot's panic: the last boot read WEDGED, so a bound of its own ended it \ and this chain ends here\n\ | the boot deadline expired: a bound of 120000 ms, reached at 120061 ms, with this \ - machine in `complete`. The tail of the log ring follows ... which is what nothing \ - was draining.\n\ + machine in `complete`. Where each CPU's timer last found the kernel:\n\ + | The tail of the log ring follows ... which is what nothing was draining.\n\ | usb-quiesce: no barrier was taken, so this reset is not the shutdown's\n{tail}\ Loader log: the last boot is accounted for, so this pass resets the machine\n", bootlog::SEPARATOR @@ -943,16 +943,29 @@ mod checks { let deaf = "| [1.509 cpu1] wedge: cpu1 arrived with interrupts off, through the syscall \ gate, and takes them again here\n"; let judge = metal_judge("boot_deadline_ends_a_wedge"); - let wedge = format!("{staged}{}{}", awake(1), awake(0)); + // The seal's line for each CPU, cpu1's being `staging`. + let spin = "kernel::deadline::this_cpu+0x42"; + let pcs = |staging: &str| format!("| cpu0 pc=0xffff80006051b0b2 {spin}\n| cpu1 pc={staging}\n"); + let inside = pcs(&format!("0xffff80006051b0b2 {spin}")); + let wedge = format!("{staged}{}{}{inside}", awake(1), awake(0)); assert_eq!(judge(&[&readback("deadlinewedge", &wedged(&wedge), kernel)]), Ok(())); assert!(judge(&[&readback("deadlinewedge", &wedged(""), kernel)]).is_err()); // The staging CPU arrived deaf: the gate masked the syscall's body, and // the others' awake lines say nothing of it. - let gated = format!("{staged}{deaf}{}", awake(0)); + let gated = format!("{staged}{deaf}{}{inside}", awake(0)); assert!(judge(&[&readback("deadlinewedge", &wedged(&gated), kernel)]).is_err()); // Awake, but not the CPU that staged it. - let elsewhere = format!("{staged}{}", awake(0)); + let elsewhere = format!("{staged}{}{inside}", awake(0)); assert!(judge(&[&readback("deadlinewedge", &wedged(&elsewhere), kernel)]).is_err()); + // The seal puts the staging CPU somewhere else, or at no symbol: the + // entry handed the record a word that is not the interrupted `rip`. + for staging in ["0xffff8000605490fe >::lock+0xee", "0x0000000000000003"] { + let misplaced = format!("{staged}{}{}{}", awake(1), awake(0), pcs(staging)); + assert!(judge(&[&readback("deadlinewedge", &wedged(&misplaced), kernel)]).is_err()); + } + // No line for the staging CPU. + let unnamed = format!("{staged}{}{}| cpu0 pc=0xffff80006051b0b2 {spin}\n", awake(1), awake(0)); + assert!(judge(&[&readback("deadlinewedge", &wedged(&unnamed), kernel)]).is_err()); let sweep = "| [1.526 cpu0] usb-load: sweeping disk 0 from block 6569336 to 7507812, \ rewriting each run with the bytes just read from it, until this machine is \ diff --git a/tests/common/power.rs b/tests/common/power.rs index e2a690c2bd..e38d1713de 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -331,6 +331,12 @@ pub fn deadline_wedge_chain(after: &serial::Serial) -> Result<(), String> { .ok_or_else(|| format!("no cpu in the record that staged the wedge: {staged:?}"))?; after.must_say_after(bootlog::PREVIOUS_PANIC, &format!("wedge: {cpu} {}", bootlog::WEDGE_AWAKE))?; says_nothing_of(after, bootlog::WEDGE_ARRIVED_DEAF)?; + // And the seal names where that CPU stood: its timer's last kernel frame is + // inside the spin, resolved by the kernel against its own symbols. + let pc = after.must_say_after(bootlog::PREVIOUS_PANIC, &format!("{cpu}{}", bootlog::SEAL_PC))?; + if !pc.contains(bootlog::WEDGE_SPIN) { + return Err(format!("the seal puts {cpu} outside the wedge's spin `{}`: {pc:?}", bootlog::WEDGE_SPIN)); + } says_nothing_of(after, bootlog::REBOOTING)?; // **The two bounds composing, on the one machine that has both.** This // wedge spins with `IF` set, so every CPU still takes its timer interrupt From 4cc58717ec54bc50fb8ec3b602054c35e5fd991c Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 13:58:54 +0200 Subject: [PATCH 8/8] Answer review round 3: the x86 guest rows go, the T14 holds both behaviours `x86_mask_windows` and `x86_ring0_timer_in_syscall` are cut with their MACHINE_TESTS entries and `run_job`: the T14's `mask_windows` row runs the same judge on an x86 `mask-windows` kernel under the same load, and its actuator boot runs `test_rs_ring0_timer_in_syscall`. The AArch64 rows stay, AArch64 having no metal. `deadline::poll` loses its doc, which described the Ring 0 call site `poll_in_kernel` now owns; `symbols::log_kernel`'s stray unformatted signature is reverted. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- kernel/src/deadline.rs | 6 ---- kernel/src/symbols.rs | 2 +- tests/toyos.rs | 80 ++---------------------------------------- 3 files changed, 4 insertions(+), 84 deletions(-) diff --git a/kernel/src/deadline.rs b/kernel/src/deadline.rs index 975d21de27..ff284ecea4 100644 --- a/kernel/src/deadline.rs +++ b/kernel/src/deadline.rs @@ -184,12 +184,6 @@ pub fn start() { log!("{}", crate::hardlockup::start(ms)); } -/// Whether this machine's bound has passed; the timer interrupt entry's, in -/// both rings, and nothing else's. -/// -/// **One relaxed load in the callee on the unarmed path.** The Ring 0 call site -/// pays a caller-saved prologue on every tick of every CPU armed or not, and -/// that cost is the entry's rather than this function's. pub fn poll() { past(AT_TSC.load(Relaxed)) } diff --git a/kernel/src/symbols.rs b/kernel/src/symbols.rs index 803b847cc1..10d2a09bf0 100644 --- a/kernel/src/symbols.rs +++ b/kernel/src/symbols.rs @@ -202,7 +202,7 @@ impl core::fmt::Display for At { } } -fn log_kernel(addr: u64,lookup: impl FnOnce(&SymbolTable) -> Option<(&str, u64)>) -> Option { +fn log_kernel(addr: u64, lookup: impl FnOnce(&SymbolTable) -> Option<(&str, u64)>) -> Option { let ptr = KERNEL_SYMS.load(Ordering::Acquire); if ptr.is_null() { log!(" {:#x}", addr); diff --git a/tests/toyos.rs b/tests/toyos.rs index 07fbfced20..e21737532d 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -169,9 +169,8 @@ const DRIVEN_AND_SHARED: &[&str] = &[ // Its shared run is the x86-64 verdict; `virt_readonly_copyout` builds it // for AArch64 and runs it on that architecture's job case. "abuse_readonly_copyout", - // Its actuator-boot run is the T14's verdict; `x86_ring0_timer_in_syscall` - // and `virt_ring0_timer_in_syscall` drive it in guests of both - // architectures. + // Its actuator-boot run is the T14's verdict; `virt_ring0_timer_in_syscall` + // builds it for AArch64 and runs it on that architecture's job case. "ring0_timer_in_syscall", // Its shared run asserts every arm's kill; `crash_report_reads_no_kernel_memory` // reads what the kernel said of two of them. @@ -236,13 +235,6 @@ const MACHINE_TESTS: &[&str] = &[ // no way to turn it back on, so only a machine QEMU reports stopping can // be asked. `machine_soft_off_decoded` reads the T14's own decode. "machine_shutdown", - // A `mask-windows` kernel's bookkeeping on x86-64, where a syscall's body - // opens interrupts: `virt_mask_windows` reads AArch64's alone, and the - // T14's `mask_windows` row is in no CI. - "x86_mask_windows", - // The timer's interrupt inside a syscall's body on x86-64: the shared - // boots that also run it are the T14's alone. - "x86_ring0_timer_in_syscall", ]; /// **The metal profile**: which registrations run on the ThinkPad T14, what @@ -1537,8 +1529,7 @@ fn check_colors( /// `test_rs_abuse_readonly_copyout`. const VIRT_COPYOUT: &str = "abuse_readonly_copyout"; -/// The same for its job `test_rs_ring0_timer_in_syscall`, which -/// `x86_ring0_timer_in_syscall` stages on x86-64. +/// The same for its job `test_rs_ring0_timer_in_syscall`. const VIRT_RING0_TIMER: &str = "ring0_timer_in_syscall"; /// `tests/toyos-rust-tests`' binary that `tests/virtsmpcase` runs as its job @@ -1657,69 +1648,6 @@ fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { mask_windows(&serial, VIRT_CPUS) } -/// The windows on x86-64: `tests/testcases` on a `mask-windows` kernel under -/// [`WINDOWS_LOAD`], judged on the whole console once the boot has said its -/// last word. Its verdict is bookkeeping and not a duration: an `IF` change no -/// hook saw, or a lock an interrupt handler took, panics the kernel. -fn x86_mask_windows(test_config: &Path) -> Result<(), String> { - let profile = qemu::Profile::Headless; - let herd = WINDOWS_LOAD.strip_prefix("test_rs_").expect("a suite binary's job name"); - let mut qemu = QemuInstance::boot_with_options( - test_config, - &[], - &[], - BootOptions { - profile, - kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL, - extra_root_files: vec![suite_bin(profile.arch(), herd)], - ..Default::default() - }, - ); - let mut serial = qemu.boot_log().to_string(); - run_job(&mut qemu, &mut serial, WINDOWS_LOAD)?; - writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); - qemu.flush_stdin(); - // To the boot's last word, said after every census and its windows. - await_marker(&mut qemu, &mut serial, power::SHUTTING_DOWN, "the boot's last word")?; - mask_windows(&serial, BootOptions::default().smp) -} - -/// `job` run on an x86-64 guest's runner, to its exit 0, everything the -/// console said meanwhile added to `serial`. -fn run_job(qemu: &mut QemuInstance, serial: &mut String, job: &str) -> Result<(), String> { - writeln!(qemu.stdin_mut(), "run {job}").expect("write to QEMU stdin"); - qemu.flush_stdin(); - await_marker(qemu, serial, &format!("===TEST_END {job} "), &format!("the job {job} to end"))?; - if !serial.contains(&format!("===TEST_END {job} exit=0===")) { - return Err(format!("{job} did not exit 0\nserial:\n{serial}")); - } - Ok(()) -} - -/// `test_rs_ring0_timer_in_syscall` on an x86-64 guest of the kernel that -/// carries `SYS_DEBUG`, where the binary itself is the verdict. -fn x86_ring0_timer_in_syscall(test_config: &Path) -> Result<(), String> { - let profile = qemu::Profile::Headless; - let mut qemu = QemuInstance::boot_with_options( - test_config, - &[], - &[], - BootOptions { - profile, - kernel_features: ACTUATOR_KERNEL, - extra_root_files: vec![suite_bin(profile.arch(), VIRT_RING0_TIMER)], - ..Default::default() - }, - ); - let mut serial = qemu.boot_log().to_string(); - run_job(&mut qemu, &mut serial, &format!("test_rs_{VIRT_RING0_TIMER}"))?; - match serial.lines().find(|l| l.contains("ring0_timer_in_syscall: ")) { - Some(said) => eprintln!(" [x86] {}", said.trim()), - None => return Err(format!("the binary said nothing\nserial:\n{serial}")), - } - Ok(()) -} - /// Boot `tests/virtsmpcase` as `options` say. fn boot_virt_smp(options: BootOptions) -> QemuInstance { let config = compile::repo_root().join("tests/virtsmpcase/system.toml"); @@ -2602,8 +2530,6 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> { "iommu_virtio_platform" => common::iommu::iommu_virtio_platform(test_config), "nested_nmi_is_loud" => faults::nested_nmi_is_loud(test_config), "machine_shutdown" => power::machine_shutdown(test_config), - "x86_mask_windows" => x86_mask_windows(test_config), - "x86_ring0_timer_in_syscall" => x86_ring0_timer_in_syscall(test_config), other => Err(format!("unknown machine test {other}")), } }