diff --git a/issues/a-muted-screen-test-pays-its-ceiling-before-any-boot-has-measured-the-host.md b/issues/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/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. diff --git a/issues/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md b/issues/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md index e788e40d0d..05a50b7054 100644 --- a/issues/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md +++ b/issues/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/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 @@ -45,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/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md`), +(`issues/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`, @@ -68,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/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md b/issues/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md index 7df19d99df..40f0c4a4f4 100644 --- a/issues/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md +++ b/issues/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/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/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/a-tls-block-is-zeroed-twice-with-interrupts-masked.md b/issues/a-tls-block-is-zeroed-twice-with-preemption-off.md similarity index 74% rename from issues/a-tls-block-is-zeroed-twice-with-interrupts-masked.md rename to issues/a-tls-block-is-zeroed-twice-with-preemption-off.md index 0aa58e0398..734bb6cdcc 100644 --- a/issues/a-tls-block-is-zeroed-twice-with-interrupts-masked.md +++ b/issues/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/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/no-program-measures-toyos-against-linux-on-one-machine.md b/issues/no-program-measures-toyos-against-linux-on-one-machine.md index 9e57c354f4..4c71197baa 100644 --- a/issues/no-program-measures-toyos-against-linux-on-one-machine.md +++ b/issues/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/nothing-in-the-machine-can-read-the-trace-ring.md b/issues/nothing-in-the-machine-can-read-the-trace-ring.md index ab51252be6..cfd72e56c3 100644 --- a/issues/nothing-in-the-machine-can-read-the-trace-ring.md +++ b/issues/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/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md` + `issues/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-preemption-off-on-the-t14.md` and - `issues/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md` + `issues/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/syscall-preemption-is-incidental.md b/issues/syscall-preemption-is-incidental.md index 2605cf1007..72d0a89d41 100644 --- a/issues/syscall-preemption-is-incidental.md +++ b/issues/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/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, @@ -41,11 +32,27 @@ assumes. Owner: `issues/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 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/xhci-waits-are-spins.md`, "On the T14". +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/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md`) +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/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md b/issues/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-preemption-off-on-the-t14.md similarity index 69% rename from issues/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md rename to issues/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-preemption-off-on-the-t14.md index 3c929c14ad..bda12e557a 100644 --- a/issues/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md +++ b/issues/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 @@ -42,12 +42,24 @@ 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/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. +A syscall's body now runs with interrupts open and preemption off +(`issues/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 this file is replaced by the bound it is held to and the derivation of it. diff --git a/issues/the-lock-spins-shootdown-poll-says-if-is-clear-and-two-callers-spin-with-it-set.md b/issues/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/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/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md b/issues/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-preemption-off-for-3-8-ms.md similarity index 59% rename from issues/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md rename to issues/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-preemption-off-for-3-8-ms.md index 3e1f2c8da8..f1fc100411 100644 --- a/issues/the-supervisors-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md +++ b/issues/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,6 +16,23 @@ 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 and preemption off +(`issues/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/xhci-waits-are-spins.md`), and the `mask-windows` kernel (`kernel/src/windows.rs`) prints each CPU's longest diff --git a/issues/xhci-waits-are-spins.md b/issues/xhci-waits-are-spins.md index c5069042ab..fcfd563d8a 100644 --- a/issues/xhci-waits-are-spins.md +++ b/issues/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/syscall-preemption-is-incidental.md`): a partition claim's +preemption off from entry to exit and, since the gate opens them, interrupts +on (`issues/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/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/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 b9dc57451a..57d6e77a21 100644 --- a/kernel/pure/sched/cpu.rs +++ b/kernel/pure/sched/cpu.rs @@ -705,10 +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`], 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. -/// /// **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/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 5bdfdf2bea..ddc510ba10 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, @@ -637,7 +637,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..ff284ecea4 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 @@ -182,23 +184,47 @@ 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. -/// -/// `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 { + KERNEL_PC[crate::arch::percpu::cpu_id() as usize].store(pc, Relaxed); + } + past(at) +} + +/// 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) { + writeln!(f, " cpu{cpu} pc={}", crate::symbols::At(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 +237,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 `{}`. 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, phase(), @@ -264,18 +293,18 @@ 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 // 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 +325,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/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/main.rs b/kernel/src/main.rs index 03b288f025..a17035677e 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/symbols.rs b/kernel/src/symbols.rs index f6756cf16d..10d2a09bf0 100644 --- a/kernel/src/symbols.rs +++ b/kernel/src/symbols.rs @@ -188,6 +188,20 @@ pub fn kernel_symbol(addr: u64) -> Option<(&'static str, u64)> { table.resolve(addr) } +/// 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() { 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..666adfc316 100644 --- a/kernel/src/syscall/debug.rs +++ b/kernel/src/syscall/debug.rs @@ -47,3 +47,28 @@ 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; + 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. + 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 0e09231f77..9fe3c50a9b 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, @@ -625,6 +625,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 d5da317fe5..1a414c8ebc 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..e1dea2990c 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -43,17 +43,29 @@ 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 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`. @@ -540,6 +552,12 @@ 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/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 48610f8bc8..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 @@ -937,14 +937,35 @@ 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(())); + // 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}{}{inside}", awake(0)); + assert!(judge(&[&readback("deadlinewedge", &wedged(&gated), kernel)]).is_err()); + // Awake, but not the CPU that staged it. + 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 cc369b2179..e38d1713de 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -302,6 +302,14 @@ 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 == ']') + .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 /// purpose ended itself, and the pass after the reset read why off the page. /// @@ -314,12 +322,21 @@ 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)?; + // 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 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 25c449955d..cbead411bd 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 @@ -166,6 +169,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 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. "fault_gates", @@ -204,6 +210,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), @@ -1522,6 +1529,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"; @@ -1559,7 +1569,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() }, ); @@ -2225,6 +2235,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 @@ -3368,7 +3383,9 @@ const SMI_SPAN_NS: u64 = 4_444_000_000; /// same span of load (`tests/t14-linux/turbostat-loaded.txt`). /// /// Read and not held, beside Linux's turbostat: each CPU's idle busy -/// fraction, and what one round cost its reader. +/// fraction, and what one round cost its reader; and beside Linux's loaded +/// timer reading (`issues/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")?; @@ -3471,6 +3488,10 @@ fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { let at = header.iter().position(|c| *c == column).ok_or_else(|| format!("turbostat read no {column}"))?; Ok(rows.filter(|r| r[0] == "-").filter_map(|r| r.get(at)?.parse().ok()).collect()) }; + 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 range = |values: &[f64]| values.iter().fold((f64::MAX, f64::MIN), |(lo, hi), &v| (lo.min(v), hi.max(v))); let idle = range(&linux(include_str!("t14-linux/turbostat-idle.txt"), "Busy%")?); let loaded_rows = linux(include_str!("t14-linux/turbostat-loaded.txt"), "Bzy_MHz")?; @@ -3783,6 +3804,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 ca999369b4..a72f1508f1 100644 --- a/toyos-abi/src/syscall.rs +++ b/toyos-abi/src/syscall.rs @@ -831,6 +831,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!`