diff --git a/issues/build/the-control-registers-verdicts-doc-comment-sits-on-the-census-verdict.md b/issues/build/the-control-registers-verdicts-doc-comment-sits-on-the-census-verdict.md new file mode 100644 index 00000000000..6c3765ace81 --- /dev/null +++ b/issues/build/the-control-registers-verdicts-doc-comment-sits-on-the-census-verdict.md @@ -0,0 +1,18 @@ +--- +status: open +kind: tooling +opened: 2026-10-01 +--- + +# The control registers verdict's doc comment sits on the census verdict + +In `tests/toyos.rs`, the doc block that starts "Every CPU's `CR0` and `CR4`, +against what a CPU running this kernel must hold" runs straight into +"The interrupt census adds up, …". Both paragraphs render as the doc of +`irq_census`. `control_regs`, which the first block describes, has no doc +comment. Nothing checks that a doc comment names the item it is attached to, +so rustdoc and a reader both credit the census verdict with the +control-register rules. + +**Exit:** the block sits on `control_regs`, and `irq_census` carries only its +own doc. diff --git a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md index b38d2a9496f..f20f0f83ec1 100644 --- a/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md +++ b/issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md @@ -31,11 +31,47 @@ holder, decides how long a CPU runs with interrupts masked: registrations sweep them four at a time. Nothing caps N: a thread costs its process a 128 KiB kernel stack -(`kernel/src/process.rs`) and no count. Before #634 every one of these -walks ran with interrupts open, under preemption off. By reading, not -measured: no instrument in the tree reads an interrupts-off window. - -**Exit**: step 2's interrupts-off window, read on the T14 while one process -parks 256 threads in `submit` on one ring and a sibling thread completes into -it, is no longer at step 1's head than at stage 6's first commit under the -same load. +(`kernel/src/process.rs`) and no count. The first walk starts in +`SYS_INBOX_SUBMIT`, and a syscall runs with interrupts masked from entry to +exit (`issues/kernel/syscall-preemption-is-incidental.md`), with #634 and +without it: #634 did not mask it, and reverting #634 does not shorten it. +The second runs in the device's handler since #634. + +How long the second is has not been read. The first has, at one size: the +three T14 boots of #649 at `8b73eba69` (comment 5959415453, readbacks +`649-r5/1-head`, `649-r5/2-report-halved`, whose kernel prints half of every +span, and `649-r5/3-idle-halt-counted`) ran it with N = 256 +(`test_rs_ring_park_herd`) and read it from the herd's own report, which +spans the runner's spawn of the herd as well. The longest `irqs_off_ns` on +any CPU there is 1032292 (`windowscase/kernel.log:428`), 2 × 519358 (`:426`) +and 1175943 (`:430`). The third is cpu7's, the CPU that spawned the herd +(`issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md`), +and the other seven read 257646 to 364953 in that boot. + +The three at `0aa8d4c88` (comment 5960575031, readbacks `649-r6/1-head`, +`649-r6/2-report-halved` and `649-r6/3-idle-halt-counted`, the same two +mutated kernels) read the same report of the same load at 1980239 +(`windowscase/kernel.log:430`), 2 × 5075290 (`:422`) and 4725822 (`:416`): + +- 1980239 is cpu7's, which spawned the herd (`:395`). The other seven read + 969922 to 1044783. +- 2 × 5075290 is one of eight: every CPU reads 2 × 5014552 to 2 × 5075290 + (`:416` to `:430`), beside `tlb: shootdowns=282 wait=131633us max=10038us` + (`:431`). It is the first reading of + `issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md`. +- 4725822 is cpu0's. The other seven read 544283 to 1018355. + +So one size reads 1.03 to 10.15 ms over six boots, and which boot carried +one of the machine's own events decides a single reading. None of the six +took an interrupt a handler #634 changed serves +(`userdev=0 sound=0 dmafault=0 hda=0` on every CPU). + +**Exit**: the interrupts-off window step 2's instrument reads on the T14 +under N threads parked in `submit` on one ring, a sibling thread completing +into it, does not grow with N: read at two sizes on one kernel, each size the +median of at least five boots, each boot from the load's own report, with +the tail reported beside it. `ring_park_herd`'s sibling waits on the kernel's +roster, which is itself a masked walk over every thread of the machine (3,619 +to 4,111 `SYS_SYSINFO` calls a run in #649's fourteen T14 boots, and 768 to +847 ms of syscall wall in a run of 0.9 s), so that reading has to tell the +two walks apart. diff --git a/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md b/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md new file mode 100644 index 00000000000..19ebc5402e4 --- /dev/null +++ b/issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md @@ -0,0 +1,58 @@ +--- +status: open +kind: defect +opened: 2026-10-02 +--- + +# cpu0 holds interrupts and preemption off for 6.5 ms on the T14 + +Read by the `mask-windows` kernel (`kernel/src/windows.rs`) on LENOVO +20W0003AMZ, BIOS N34ET71W (1.71), in the eight `mask_windows` boots of #649 +at `72f16e39a`: four as that head stands and four with stage 6 step 1 (#634) +reverted on it. Each boot printed one report, at `test_rs_ring_park_herd`'s +exit, so a line is its CPU's longest window from the moment it joined the +scheduler to that exit. + +cpu0's line, in the seven boots where no longer window covers it: + +| boot | `irqs_off_ns` | `preempt_off_ns` | +|---|---|---| +| 1, reverted | 6551791 | 6551707 | +| 2 | 6540754 | 6540671 | +| 3, reverted | 6549549 | 6549484 | +| 5, reverted | 6540326 | 6540262 | +| 6 | 6589053 | 6588992 | +| 7, reverted | 6590095 | 6590031 | +| 8 | 6587342 | 6587281 | + +- The two kinds differ by 61 to 84 ns in every row, so one section holds + both. +- It is cpu0's alone. In the six of those boots where no CPU carries a + longer one, the other seven CPUs' interrupts-off lines read 251,452 to + 4,720,498 ns. +- It is there with step 1 and without it. +- In all eight logs cpu0 says `sched: cpu=0 ready=0 … current=None trips=1` + at 1.155 or 1.156 s, as the CPUs join the scheduler, and nothing more + before init's first line at 1.161 or 1.162 s. + +The fourth boot's cpu0 reads 9644415 and 9643939, the event +`issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md` +records. + +Nothing names what opens it. A report carries a span and no address, and one +report a boot cannot say whether the window recurs. What will: the record +keeping, beside each CPU's longest span, the address its opening hook was +called from, printed in the report and resolved through the kernel's symbols. + +It opens before the boot's first job ends. The three boots of #649 at +`8b73eba69` (comment 5959415453, readbacks `649-r5/1-head`, +`649-r5/2-report-halved`, whose kernel prints half of every span, and +`649-r5/3-idle-halt-counted`) print a report at each of four exits. cpu0's +`irqs_off_ns` in the first, at `test_rs_idle_span`'s exit 1.746 s into the +boot (`windowscase/kernel.log:348` in each), reads 6533222, 2 × 3273547 and +6508165. In the three reports after it cpu0 reads at most 943904, 2 × 472938 +and 345229. + +**Exit**: the section that opens the window is named by that reading on the +T14, and cpu0's longest window there no longer includes it, or this file is +replaced by the bound the section is held to and the derivation of it. diff --git a/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md b/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md new file mode 100644 index 00000000000..8d70322a2f2 --- /dev/null +++ b/issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md @@ -0,0 +1,94 @@ +--- +status: open +kind: defect +opened: 2026-10-02 +--- + +# Some T14 boots carry an interrupts-off window of 9 ms or more + +Read by the `mask-windows` kernel (`kernel/src/windows.rs`) on LENOVO +20W0003AMZ, BIOS N34ET71W (1.71), in the eight `mask_windows` boots of #649 +at `72f16e39a`: four as that head stands and four with stage 6 step 1 (#634) +reverted on it, one job each, `test_rs_ring_park_herd`. The longest window +that recurs in every boot is cpu0's 6.5 ms +(`issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.md`). +Three readings are longer, each in some boots and not in others, on both +arms: + +- **Every CPU at once, the fourth boot** (step 1 in). The herd's report: + + | CPU | `irqs_off_ns` | `preempt_off_ns` | + |---|---|---| + | cpu0 | 9644415 | 9643939 | + | cpu1 | 9603617 | 9588515 | + | cpu2 | 9627971 | 9625674 | + | cpu3 | 9641999 | 9620791 | + | cpu4 | 9651846 | 9635137 | + | cpu5 | 9623545 | 9612295 | + | cpu6 | 9624969 | 9621345 | + | cpu7 | 9614836 | 9614716 | + + The same report's shootdown line reads + `tlb: shootdowns=280 wait=125911us max=9575us`, where the other seven + boots read at most `wait=49119us` and at most `max=1421us`, and cpu0's + census reads `nmi=2`, where the other seven read `nmi=1`. +- **One CPU, the seventh boot** (step 1 reverted). cpu7 reads 9260193 and + 9260124. cpu0 reads its 6590095, the other six 920,455 to 1,404,001, and + the shootdown line `max=1386us`. +- **One CPU, after the herd's report, in four boots of the eight.** The stop + prints a report too, of which the black box keeps the lines of cpu2 to + cpu7. In it one CPU reads + + | boot | CPU | `irqs_off_ns` | `preempt_off_ns` | + |---|---|---|---| + | 1, reverted | cpu7 | 10677997 | 10677829 | + | 2 | cpu7 | 11267384 | 11267320 | + | 5, reverted | cpu2 | 10214820 | 10214656 | + | 6 | cpu7 | 10874427 | 10874364 | + + and in the other four cpu7 reads 1,424,134 to 1,532,702 ns and no kept + line more. What that report spans is the herd's teardown, which its own + report precedes, the spawn of `reboot` on cpu7 and the stop. + +By reading, not measured: every CPU waiting out one CPU's masked window +inside a shootdown would read as the fourth boot does. + +Nothing names what opens any of them. A report carries a span and no address, +and no time: eight equal spans are not shown to be one event. What will: the +record keeping, beside each CPU's longest span, the address its opening hook +was called from and the counter it closed at, printed in the report. + +The third reading falls on the `reboot` and stop side of the herd's +teardown. The three boots of #649 at `8b73eba69` (comment 5959415453, +readbacks `649-r5/1-head`, `649-r5/2-report-halved`, whose kernel prints half +of every span, and `649-r5/3-idle-halt-counted`) took a report at `echo`'s +exit, after the herd's and before `reboot` was spawned. Its longest +`irqs_off_ns` is cpu7's in each: 1499808, 2 × 748872 and 1479558 +(`windowscase/kernel.log:456`). The stop's report after it, in the six lines +the black box keeps, reads cpu7 11522834 and cpu4 11645411 in the first boot +(`649-r5/1-head/windowscase/loader.log:57`, `:63`), and at most cpu7's +2 × 3799327 in the second and cpu7's 1305656 in the third. + +The three boots at `0aa8d4c88` (comment 5960575031, readbacks +`649-r6/1-head`, `649-r6/2-report-halved` and `649-r6/3-idle-halt-counted`, +the same two mutated kernels) print a report at three exits, `idle_span`'s, +`pwd`'s and the herd's, and at the stop: + +- **The first reading recurred, inside the herd's own report**, which opens + at `pwd`'s exit. In `2-report-halved` every CPU reads 2 × 5014552 to + 2 × 5075290 (`windowscase/kernel.log:416` to `:430`), beside + `tlb: shootdowns=282 wait=131633us max=10038us` (`:431`): the shootdown's + `max` is beside it again, 9575us then and 10038us now, and cpu0's second + NMI is not: `nmi=1` (`:415`). That is two boots of #649's fourteen. +- **One CPU, before the first job's exit.** cpu7's line of the first report, + `idle_span`'s (`:362`), reads 11492028 in `1-head`, 2 × 1308074 in + `2-report-halved` and 8456658 in `3-idle-halt-counted`, beside + `max=1655us`, `max=1451us` and `max=1353us` (`:363`). The same line read + 2327848, 2 × 1831727 and 3630933 at `8b73eba69`. +- **Nothing after the herd's report.** The stop's report, in the six lines + the black box keeps, reads at most cpu7's 1396887, 2 × 758960 and 1470910 + (`windowscase/loader.log:57`). + +**Exit**: each of the three, and the one-CPU reading before the first job's +exit, is named by that reading on the T14, and is removed, or this file is +replaced by the bound it is held to and the derivation of it. diff --git a/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md b/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md new file mode 100644 index 00000000000..6dd9368537b --- /dev/null +++ b/issues/kernel/the-cpu-that-spawns-a-toybox-applet-reads-1-4-ms-of-interrupts-and-preemption-off-on-the-t14.md @@ -0,0 +1,53 @@ +--- +status: open +kind: defect +opened: 2026-10-02 +--- + +# The CPU that spawns a toybox applet reads 1.4 ms of interrupts and preemption off on the T14 + +Read by the `mask-windows` kernel (`kernel/src/windows.rs`) on LENOVO +20W0003AMZ, BIOS N34ET71W (1.71), in the three `mask_windows` boots of #649 +at `8b73eba69` (comment 5959415453, readbacks `649-r5/1-head`, +`649-r5/2-report-halved`, whose kernel prints half of every span, and +`649-r5/3-idle-halt-counted`, whose kernel counts the idle halt as a +preemption-off window). + +test-runner spawned every job from cpu7: each `spawn:` record of a job is +cpu7's. Two reports a boot span the spawn of a toybox applet and of nothing +else, `pwd`'s and `echo`'s. cpu7's line in each +(`windowscase/kernel.log:388` and `:456`): + +| boot | report | `irqs_off_ns` | `preempt_off_ns` | +|---|---|---|---| +| `1-head` | `pwd`'s | 1408843 | 1408557 | +| `1-head` | `echo`'s | 1499808 | 1499590 | +| `2-report-halved` | `pwd`'s | 2 × 737408 | 2 × 737277 | +| `2-report-halved` | `echo`'s | 2 × 748872 | 2 × 748704 | +| `3-idle-halt-counted` | `pwd`'s | 1379642 | 536504022, a halt | +| `3-idle-halt-counted` | `echo`'s | 1479558 | 1479398 | + +- The two kinds differ by 160 to 336 ns in the five rows that have both, so + one section holds both. +- No other CPU reads as much in `echo`'s report: 947018 at most. +- It is the floor under a load's reading on that CPU. A load's own report + spans the runner's spawn of it, and in the herd's cpu7 reads 1019488, + 2 × 514392 and 1175943, the last the longest line of its report by three + times. +- It is not all that line reads. In the three boots at `0aa8d4c88` (comment + 5960575031, readbacks `649-r6/1-head`, `649-r6/2-report-halved` and + `649-r6/3-idle-halt-counted`, the same two mutated kernels) `pwd`'s report + reads cpu7 at 1511452, 2 × 740441 and 1360995 + (`windowscase/kernel.log:388`), and the herd's reads it at 1980239 in + `1-head` (`:430`): 468787 past that boot's applet spawn, which the spawn + does not account for and nothing names. + +By reading, not measured: it is `SYS_SPAWN`, which runs with interrupts +masked from entry to exit like every syscall +(`issues/kernel/syscall-preemption-is-incidental.md`), and whose own record +reads `total=1ms` for each of these applets. A report carries a span and no +address, so nothing names it. + +**Exit**: the section is named on the T14 by the address its opening hook was +called from, and the spawning CPU's longest window no longer includes it, or +this file is replaced by the bound it is held to and the derivation of it. diff --git a/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md b/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md index 065269837c1..60ae398449a 100644 --- a/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md +++ b/issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md @@ -148,8 +148,9 @@ times: device's `Watch` and ends its interrupt; the thread waiting on that watch does the work, and no step creates a kernel thread. `irq_ring`, the driver list in `drain_irqs` and the idle loop's device checks are gone by step 5. - Each step measures the kernel's lines, and from step 2 the longest - interrupts-off and preemption-off windows, against stage 6's first commit. + Each step measures the kernel's lines against stage 6's first commit, and + the longest interrupts-off and preemption-off windows against the readings + step 2's exit puts in the tree, by that exit's rule. Steps 3 and 4 do not land alone: they land with #592's i8042 stage and with usbd. 1. **Interrupts post.** A post is legal in a handler: the watches a handler @@ -167,12 +168,23 @@ times: 2. **The windows, measured**: the longest interrupts-off and preemption-off windows per CPU, reported beside the IRQ census and fed by each architecture's masking primitives and entries, the number the ARM - track's stage 4 owes as well. Applied to stage 6's first commit for - the baseline. **Exit**: both windows read on the T14, which is x86 - metal, at stage 6's start and at step 1's head, and neither is longer - at step 1's head than at the start, under the load - `issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md` - names as well. + track's stage 4 owes as well. Built: the `mask-windows` kernel and the + T14's `mask_windows` row. The exit's first half is met: the instrument + reads back a window of known length on the T14, which is x86 metal, and + the row's judge refuses a boot that reads it back shorter than it was + held or at more than twice that. **Exit**, open: neither window is + longer with step 1 than + with it reverted on the tree that carries the instrument, the patch + posted on #649 being what reverted means. That comparison is the median + of at least five interleaved boots an arm, each read from the load's own + report with a report taken as the load starts, against a tolerance + stated before measuring, the reverted arm's own spread, with the tail + reported beside it, under a load in which a handler step 1 changed posts + into a watch that reaches a ring with parked threads + (`issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md`'s + second bullet). `ring_park_herd` is not that load: its walks start in + `SYS_INBOX_SUBMIT`, which runs with interrupts masked on both arms, and + it reaches no handler step 1 changed. 3. **The i8042's thread is ps2server's** (#592's i8042 stage): `irq_ring`'s `I8042`, `keyboard_controller::service` and the idle loop's `verdict_due` go with the kernel's driver. **Exit**: that stage's. @@ -185,7 +197,7 @@ times: report on the panel and holding it there, a device the pass reaches (owner, 2026-09-30). **Exit**: `drain_irqs` and the idle loop's device checks are gone, both windows are measured against - stage 6's start, and the exits of + step 2's readings by its rule, and the exits of `issues/kernel/an-irq-watchs-freeing-cancel-compiles-in-a-handler.md` and `issues/kernel/nothing-fails-when-a-devices-release-or-close-stops-answering-its-polls.md` diff --git a/kernel/Cargo.toml b/kernel/Cargo.toml index 38bf47fef07..c4b2f45b0f3 100644 --- a/kernel/Cargo.toml +++ b/kernel/Cargo.toml @@ -129,6 +129,12 @@ debug-wait = [] # Not a boot parameter, and the one that could not be: it forwards to a # dependency's cargo feature, which no runtime value can reach. sched-check = ["toyos-sched/check"] +# The longest interrupts-off and preemption-off window each CPU closed since the +# last report, printed beside the IRQ census (`src/windows.rs`). Its own build +# because it reads the counter at every masking transition and every preempt +# count crossing zero, on every entry and exit: a kernel being measured for +# anything else must not carry it. +mask-windows = [] # The stray-write tripwire on the per-CPU `CpuSched` record: a shadow copy of its # bytes, taken when the driver's exclusive region is left and compared when it is # next entered, so a word that changed while nothing was allowed to change it is diff --git a/kernel/src/arch/aarch64/cpu.rs b/kernel/src/arch/aarch64/cpu.rs index 31e5fceb94a..b87c5044638 100644 --- a/kernel/src/arch/aarch64/cpu.rs +++ b/kernel/src/arch/aarch64/cpu.rs @@ -67,14 +67,24 @@ pub unsafe fn write_thread_pointer(tp: u64) { /// Unmask interrupts on this CPU: `DAIF.I` and `DAIF.F`. pub fn enable_interrupts() { + #[cfg(feature = "mask-windows")] + if !interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: writes two `DAIF` bits; a compiler barrier, so no access moves across it. unsafe { asm!("msr daifclr, #3", options(nostack)) }; } /// Mask interrupts on this CPU. pub fn disable_interrupts() { + #[cfg(feature = "mask-windows")] + let were_open = interrupts_enabled(); // SAFETY: writes two `DAIF` bits; a compiler barrier, so no access moves across it. unsafe { asm!("msr daifset, #3", options(nostack)) }; + #[cfg(feature = "mask-windows")] + if were_open { + crate::windows::irqs_masked(); + } } /// Whether this CPU takes interrupts: `DAIF.I` clear. diff --git a/kernel/src/arch/aarch64/hw.rs b/kernel/src/arch/aarch64/hw.rs index eefe2fe72f0..0109c8d5230 100644 --- a/kernel/src/arch/aarch64/hw.rs +++ b/kernel/src/arch/aarch64/hw.rs @@ -13,6 +13,12 @@ use crate::sched::payload::{KernelCtx, KernelPayload}; /// `WFI` whatever `DAIF` says (Arm ARM K.a, D1.6.2), so a wake that lands /// between the decision and the wait is taken right after it, not slept through. pub fn halt() { + // Before the `WFI`: what it waits for is taken the moment it unmasks, so + // the wait is no window. + #[cfg(feature = "mask-windows")] + if !cpu::interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: waits for an interrupt and unmasks `I` and `F`; touches no memory. unsafe { core::arch::asm!("wfi", "msr daifclr, #3", "isb", options(nomem, nostack)) }; } @@ -64,6 +70,10 @@ impl Hw for KernelHw { unsafe fn switch(&self, token: RunToken) { let save = token.save_ptr(); let restore = token.restore_ptr(); + // Every context is saved masked, so `context_switch`'s `msr daif` + // never unmasks; the resumed context's own guard puts back what it had. + #[cfg(feature = "mask-windows")] + let _masked = crate::arch::IrqGuard::close(); // SAFETY: `save`/`restore` are live Box-backed contexts from // `SchedPass::finish`, freed only by a later pass. unsafe { diff --git a/kernel/src/arch/aarch64/mod.rs b/kernel/src/arch/aarch64/mod.rs index 9440620def7..824f53c8550 100644 --- a/kernel/src/arch/aarch64/mod.rs +++ b/kernel/src/arch/aarch64/mod.rs @@ -70,12 +70,21 @@ impl IrqGuard { unsafe { core::arch::asm!("mrs {saved}, daif", "msr daifset, #3", saved = out(reg) daif); } + #[cfg(feature = "mask-windows")] + if trap::frame_interrupts_enabled(daif) { + crate::windows::irqs_masked(); + } Self { daif, _not_send_sync: core::marker::PhantomData } } } impl Drop for IrqGuard { fn drop(&mut self) { + // Only where the restore opens them. + #[cfg(feature = "mask-windows")] + if trap::frame_interrupts_enabled(self.daif) && !cpu::interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: the word `close` read out of `DAIF` on this CPU (the guard is // `!Send`), restored whole. unsafe { diff --git a/kernel/src/arch/aarch64/percpu.rs b/kernel/src/arch/aarch64/percpu.rs index 5b09993be14..0e962409dd8 100644 --- a/kernel/src/arch/aarch64/percpu.rs +++ b/kernel/src/arch/aarch64/percpu.rs @@ -266,17 +266,25 @@ pub fn preempt_count() -> u32 { #[inline] pub fn set_preempt_count(value: u32) { + #[cfg(feature = "mask-windows")] + let old = preempt_count(); this().preempt_count.store(value, Relaxed); + #[cfg(feature = "mask-windows")] + crate::windows::preempt_set(old, value); } /// One increment, atomic against an interrupt on this CPU. #[inline] pub fn preempt_count_up() { this().preempt_count.fetch_add(1, Relaxed); + #[cfg(feature = "mask-windows")] + crate::windows::preempt_raised(); } #[inline] pub fn preempt_count_down() { + #[cfg(feature = "mask-windows")] + crate::windows::preempt_lowering(); this().preempt_count.fetch_sub(1, Relaxed); } diff --git a/kernel/src/arch/aarch64/trap.rs b/kernel/src/arch/aarch64/trap.rs index 9b541ac07bb..04caa6b0f89 100644 --- a/kernel/src/arch/aarch64/trap.rs +++ b/kernel/src/arch/aarch64/trap.rs @@ -91,13 +91,26 @@ fn class_name(esr: u64) -> &'static str { /// The Rust half of every vector entry. Returns to the entry, which restores /// the frame and returns from the exception; everything fatal diverges. extern "C" fn dispatch(frame: &mut Frame, entry: u64) { + // Each returning entry found interrupts open, an IRQ because only then is + // one taken and EL0 because it never masks them, and taking it masked + // them; `exit_to_user` opens them for EL0, and the `ERET` for EL1. match entry { - EL1_IRQ => irq(false), + EL1_IRQ => { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); + irq(false); + #[cfg(feature = "mask-windows")] + crate::windows::irqs_unmasking(); + } EL0_SYNC => { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); el0_sync(frame); crate::scheduler::exit_to_user(); } EL0_IRQ => { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); irq(true); crate::scheduler::exit_to_user(); } diff --git a/kernel/src/arch/x86_64/cpu.rs b/kernel/src/arch/x86_64/cpu.rs index 1c489efeffc..0c08e730458 100644 --- a/kernel/src/arch/x86_64/cpu.rs +++ b/kernel/src/arch/x86_64/cpu.rs @@ -259,6 +259,10 @@ pub unsafe fn ltr(selector: u16) { /// `sti`; not a drop-in for a caller whose `cli`/`sti` also needs the compiler barrier a bare `asm!` carries. #[inline] pub fn enable_interrupts() { + #[cfg(feature = "mask-windows")] + if !interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: one RFLAGS bit, no memory, matching the options declared above. unsafe { asm!("sti", options(nomem, nostack)); @@ -271,7 +275,7 @@ pub fn enable_interrupts() { /// or `cli` runs, so nothing may branch on it to decide whether to mask; what it /// is for is a site that has to *say* which state it inherited, which is a fact /// about its caller rather than about the instruction after it. -#[cfg(feature = "boot-actuators")] +#[cfg(any(feature = "boot-actuators", feature = "mask-windows"))] pub fn interrupts_enabled() -> bool { let rflags: u64; // SAFETY: balanced push/pop leaves rsp unchanged; the pair uses the stack, so no nomem. @@ -284,10 +288,16 @@ pub fn interrupts_enabled() -> bool { /// `cli`, with [`enable_interrupts`]'s caveat about the missing barrier. #[inline] pub fn disable_interrupts() { + #[cfg(feature = "mask-windows")] + let were_open = interrupts_enabled(); // SAFETY: enable_interrupts's argument; masking interrupts is a latency bug, not a soundness one. unsafe { asm!("cli", options(nomem, nostack)); } + #[cfg(feature = "mask-windows")] + if were_open { + crate::windows::irqs_masked(); + } } /// The kernel's own FS base, not `rd/wrfsbase` (`control_regs::CR4_FORBIDDEN`). diff --git a/kernel/src/arch/x86_64/hw.rs b/kernel/src/arch/x86_64/hw.rs index 2ee6f21def3..50ed0a04970 100644 --- a/kernel/src/arch/x86_64/hw.rs +++ b/kernel/src/arch/x86_64/hw.rs @@ -13,6 +13,10 @@ use crate::sched::payload::{KernelCtx, KernelPayload}; /// `sti; hlt`, the atomic enable-and-wait pair: a wake landing between the two is not lost. pub fn halt() { + #[cfg(feature = "mask-windows")] + if !cpu::interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: enables interrupts and waits for one; touches no memory. unsafe { asm!("sti; hlt", options(nomem, nostack)); } } @@ -280,6 +284,10 @@ impl Hw for KernelHw { unsafe fn switch(&self, token: RunToken) { let save = token.save_ptr(); let restore = token.restore_ptr(); + // Every context is saved masked, so `context_switch`'s `popfq` never + // moves `IF`; the resumed context's own guard puts back what it had. + #[cfg(feature = "mask-windows")] + let _masked = crate::arch::IrqGuard::close(); // SAFETY: `save`/`restore` are live Box-backed contexts from `SchedPass::finish`, freed only by a later pass; `incoming.thread_pointer` is this kernel's own canonical value for the thread being installed. unsafe { (*save).thread_pointer = cpu::read_fs_base(); diff --git a/kernel/src/arch/x86_64/idt/device_irq.rs b/kernel/src/arch/x86_64/idt/device_irq.rs index b3b1fa07742..4b7db10bd7e 100644 --- a/kernel/src/arch/x86_64/idt/device_irq.rs +++ b/kernel/src/arch/x86_64/idt/device_irq.rs @@ -28,8 +28,14 @@ macro_rules! device_irq_entry { // Ring 0 entry has unknown rsp alignment; align via the rbp save. "mov rbp, rsp", "and rsp, -16", + #[cfg(feature = "mask-windows")] + "call {windows_entered}", // No user-state save around this call: kernel code is soft-float and never touches it. "call {handler}", + #[cfg(feature = "mask-windows")] + "mov rdi, [rbp + 88]", + #[cfg(feature = "mask-windows")] + "call {windows_leaving}", "mov rsp, rbp", "lock sub dword ptr gs:[{preempt_count}], 1", "test dword ptr [rsp + 88], 3", // CS = 10 GPRs + RIP above @@ -53,9 +59,31 @@ macro_rules! device_irq_entry { handler = sym $handler, exit_to_user = sym crate::arch::idt::kernel_exit_to_user_check, preempt_count = const $crate::arch::percpu::OFF_PREEMPT_COUNT, + #[cfg(feature = "mask-windows")] + windows_entered = sym super::device_irq::windows_entered, + #[cfg(feature = "mask-windows")] + windows_leaving = sym super::device_irq::windows_leaving, ); } }; } pub(crate) use device_irq_entry; + +/// The gate masked interrupts, which a maskable vector finds open (SDM Vol. 3A +/// §6.8.1), and the stub raised the preempt count by one. +#[cfg(feature = "mask-windows")] +pub(super) extern "sysv64" fn windows_entered() { + crate::windows::irqs_masked(); + crate::windows::preempt_raised(); +} + +/// The stub lowers the count next, with the frame's `cs`; its `iretq` opens +/// interrupts on a return to Ring 0, and `exit_to_user` on one to Ring 3. +#[cfg(feature = "mask-windows")] +pub(super) extern "sysv64" fn windows_leaving(cs: u64) { + crate::windows::preempt_lowering(); + if !toyos_userbound::Ring::of_cs(cs).is_user() { + crate::windows::irqs_unmasking(); + } +} diff --git a/kernel/src/arch/x86_64/idt/mod.rs b/kernel/src/arch/x86_64/idt/mod.rs index e94a6462cbb..c7f63b30495 100644 --- a/kernel/src/arch/x86_64/idt/mod.rs +++ b/kernel/src/arch/x86_64/idt/mod.rs @@ -362,12 +362,35 @@ extern "sysv64" fn trap_dispatch(frame: *mut TrapFrame) { Vector::DoubleFault => exceptions::double_fault_handler(frame), Vector::MachineCheck => exceptions::machine_check_handler(frame), Vector::PageFault => { + #[cfg(feature = "mask-windows")] + windows_entered(frame); cpu::enable_interrupts(); exceptions::page_fault_handler(frame); cpu::disable_interrupts(); + // Only a Ring 3 fault comes back: `common_entry` lowers the count + // next, and `exit_to_user` opens interrupts. + #[cfg(feature = "mask-windows")] + crate::windows::preempt_lowering(); } - _ => exceptions::exception_handler(frame), + _ => { + #[cfg(feature = "mask-windows")] + windows_entered(frame); + exceptions::exception_handler(frame) + } + } +} + +/// A Ring 3 frame had interrupts open, the gate masked them, and +/// `common_entry` raised the preempt count by one. A Ring 0 frame ends the +/// machine: its CPU's record stops first, so no hook from here on refuses in +/// place of the fault's report. +#[cfg(feature = "mask-windows")] +fn windows_entered(frame: &TrapFrame) { + if !toyos_userbound::Ring::of_cs(frame.cs).is_user() { + crate::windows::stop_here(); } + crate::windows::irqs_masked(); + crate::windows::preempt_raised(); } /// This CPU's state as the black box records it, read out of the frame the stub diff --git a/kernel/src/arch/x86_64/idt/spurious.rs b/kernel/src/arch/x86_64/idt/spurious.rs index 06fdd73d23a..7c066325620 100644 --- a/kernel/src/arch/x86_64/idt/spurious.rs +++ b/kernel/src/arch/x86_64/idt/spurious.rs @@ -51,11 +51,16 @@ pub(super) extern "sysv64" fn spurious_entry() { } /// Counts one delivery and acknowledges it if the ISR bit shows it needed one. +/// Its `iretq` returns to either ring with interrupts open, as the vector found them. extern "sysv64" fn took() { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); crate::arch::percpu::irq_took!(Spurious); if apic::in_service(SPURIOUS_VECTOR) { apic::eoi(); } + #[cfg(feature = "mask-windows")] + crate::windows::irqs_unmasking(); } /// Raises the spurious vector on this CPU and verifies the handler ran and diff --git a/kernel/src/arch/x86_64/idt/timer.rs b/kernel/src/arch/x86_64/idt/timer.rs index 574e4a68713..1ce8cb24fba 100644 --- a/kernel/src/arch/x86_64/idt/timer.rs +++ b/kernel/src/arch/x86_64/idt/timer.rs @@ -76,7 +76,10 @@ pub(super) extern "sysv64" fn timer_entry() { "pop rcx", "pop rax", "iretq", + #[cfg(not(feature = "mask-windows"))] deadline = sym crate::deadline::poll, + #[cfg(feature = "mask-windows")] + deadline = sym ring0_tick, handler = sym timer_handler, exit_to_user = sym crate::arch::idt::kernel_exit_to_user_check, armed_ticks = const crate::arch::percpu::OFF_LAST_ARMED_TICKS, @@ -89,7 +92,19 @@ pub(super) extern "sysv64" fn timer_entry() { ); } +/// The Ring 0 branch's Rust half under `mask-windows`: it interrupted a CPU +/// with interrupts open, and its `iretq` opens them again. +#[cfg(feature = "mask-windows")] +extern "sysv64" fn ring0_tick() { + crate::windows::irqs_masked(); + crate::deadline::poll(); + crate::windows::irqs_unmasking(); +} + extern "sysv64" fn timer_handler() { + // From Ring 3, so interrupts were open; `exit_to_user` opens them again. + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); crate::arch::percpu::irq_took!(Timer); // Before anything that can take a lock: a CPU running userland is the other // half of the coverage the Ring 0 branch above gives a CPU holding one. diff --git a/kernel/src/arch/x86_64/idt/tlb.rs b/kernel/src/arch/x86_64/idt/tlb.rs index fa5a147aa24..17551416d73 100644 --- a/kernel/src/arch/x86_64/idt/tlb.rs +++ b/kernel/src/arch/x86_64/idt/tlb.rs @@ -18,12 +18,22 @@ pub(super) extern "sysv64" fn tlb_flush_entry() { "lock add dword ptr gs:[{preempt_count}], 1", "mov rbp, rsp", "and rsp, -16", + #[cfg(feature = "mask-windows")] + "call {windows_entered}", "call {flush}", "mov rsp, rbp", "mov ecx, 0x80B", "xor eax, eax", "xor edx, edx", "wrmsr", + #[cfg(feature = "mask-windows")] + "mov rdi, [rsp + 88]", + #[cfg(feature = "mask-windows")] + "and rsp, -16", + #[cfg(feature = "mask-windows")] + "call {windows_leaving}", + #[cfg(feature = "mask-windows")] + "mov rsp, rbp", "lock sub dword ptr gs:[{preempt_count}], 1", // Only this branch can context-switch; user state is saved and restored around it alone. "test dword ptr [rsp + 88], 3", @@ -47,6 +57,10 @@ pub(super) extern "sysv64" fn tlb_flush_entry() { flush = sym flush, exit_to_user = sym crate::arch::idt::kernel_exit_to_user_check, preempt_count = const crate::arch::percpu::OFF_PREEMPT_COUNT, + #[cfg(feature = "mask-windows")] + windows_entered = sym super::device_irq::windows_entered, + #[cfg(feature = "mask-windows")] + windows_leaving = sym super::device_irq::windows_leaving, ); } diff --git a/kernel/src/arch/x86_64/idt/unclaimed.rs b/kernel/src/arch/x86_64/idt/unclaimed.rs index 9ca9f4b6dcf..49c47f60ebb 100644 --- a/kernel/src/arch/x86_64/idt/unclaimed.rs +++ b/kernel/src/arch/x86_64/idt/unclaimed.rs @@ -56,7 +56,10 @@ pub(super) extern "sysv64" fn unclaimed_entry() { } /// Counts the delivery, remembers the vector, and EOIs only if the ISR needs one. +/// Its `iretq` returns to either ring with interrupts open, as the vector found them. extern "sysv64" fn took() { + #[cfg(feature = "mask-windows")] + crate::windows::irqs_masked(); crate::arch::percpu::irq_took!(Unclaimed); match apic::in_service_highest() { Some(vector) => { @@ -67,6 +70,8 @@ extern "sysv64" fn took() { NO_ISR.fetch_add(1, Ordering::Relaxed); } } + #[cfg(feature = "mask-windows")] + crate::windows::irqs_unmasking(); } /// Whether `vector` has been taken through this gate. diff --git a/kernel/src/arch/x86_64/mod.rs b/kernel/src/arch/x86_64/mod.rs index 2521b6e7c53..5d9a48a9a47 100644 --- a/kernel/src/arch/x86_64/mod.rs +++ b/kernel/src/arch/x86_64/mod.rs @@ -70,12 +70,21 @@ impl IrqGuard { unsafe { core::arch::asm!("pushfq", "pop {saved}", "cli", saved = out(reg) rflags); } + #[cfg(feature = "mask-windows")] + if idt::frame_interrupts_enabled(rflags) { + crate::windows::irqs_masked(); + } Self { rflags, _not_send_sync: core::marker::PhantomData } } } impl Drop for IrqGuard { fn drop(&mut self) { + // Only where the restore opens them. + #[cfg(feature = "mask-windows")] + if idt::frame_interrupts_enabled(self.rflags) && !cpu::interrupts_enabled() { + crate::windows::irqs_unmasking(); + } // SAFETY: the word `close` read out of RFLAGS on this CPU (the guard is // `!Send`), restored whole. unsafe { diff --git a/kernel/src/arch/x86_64/percpu.rs b/kernel/src/arch/x86_64/percpu.rs index 113329f0cc6..3cd57d6ddcf 100644 --- a/kernel/src/arch/x86_64/percpu.rs +++ b/kernel/src/arch/x86_64/percpu.rs @@ -751,18 +751,26 @@ pub fn preempt_count() -> u32 { #[inline] pub fn set_preempt_count(value: u32) { + #[cfg(feature = "mask-windows")] + let old = preempt_count(); gs::write_u32::(value); + #[cfg(feature = "mask-windows")] + crate::windows::preempt_set(old, value); } /// One increment, atomic against an interrupt on this CPU. #[inline] pub fn preempt_count_up() { gs::lock_inc_u32::(); + #[cfg(feature = "mask-windows")] + crate::windows::preempt_raised(); } /// One decrement, atomic against an interrupt on this CPU. #[inline] pub fn preempt_count_down() { + #[cfg(feature = "mask-windows")] + crate::windows::preempt_lowering(); gs::lock_dec_u32::(); } diff --git a/kernel/src/arch/x86_64/syscall.rs b/kernel/src/arch/x86_64/syscall.rs index 594cce52cd9..e48bd3f503e 100644 --- a/kernel/src/arch/x86_64/syscall.rs +++ b/kernel/src/arch/x86_64/syscall.rs @@ -101,10 +101,19 @@ extern "sysv64" fn syscall_entry() { /// The syscall bracket: the entry's diagnostic stores stay readable only while [`percpu::in_syscall`] is true. extern "sysv64" fn syscall_handler(num: u64, a1: u64, a2: u64, _: u64, a3: u64, a4: u64) -> u64 { + // `IA32_FMASK` masked interrupts, and the entry raised the preempt count by one. + #[cfg(feature = "mask-windows")] + { + crate::windows::irqs_masked(); + crate::windows::preempt_raised(); + } #[cfg(feature = "df-witness")] cpu::df_witness("syscall_handler"); percpu::enter_syscall(); let out = syscall_dispatch(num, a1, a2, a3, a4); percpu::leave_syscall(); + // The entry lowers it by one next; `exit_to_user` opens interrupts. + #[cfg(feature = "mask-windows")] + crate::windows::preempt_lowering(); out } diff --git a/kernel/src/hw.rs b/kernel/src/hw.rs index 0490865005b..c40c8af0242 100644 --- a/kernel/src/hw.rs +++ b/kernel/src/hw.rs @@ -78,7 +78,11 @@ impl Machine for KernelHw { if crate::actuator::diag_tick() { irqchip::arm_within(DIAG_TICK_NS); } + #[cfg(feature = "mask-windows")] + crate::windows::halting(); self.halt(); + #[cfg(feature = "mask-windows")] + crate::windows::woken(); // **A CPU that is executing has a one-shot armed, and this is where // that becomes true again.** `TimerPlan::Stop` left this one at zero // before the halt above and only a pass reaching `apply_timer` arms diff --git a/kernel/src/irq_census.rs b/kernel/src/irq_census.rs index 6187df24d8f..be637d91d3b 100644 --- a/kernel/src/irq_census.rs +++ b/kernel/src/irq_census.rs @@ -133,6 +133,7 @@ pub fn taken_here() -> u64 { } /// Logs one `irq: cpuN total=… =…` line per online CPU; counts are cumulative since boot. +/// A `mask-windows` kernel follows each with that CPU's `windows:` line. /// Allocates nothing, takes no lock, touches no device. pub fn log_census() { for cpu in 0..crate::smp::cpu_count() { @@ -142,5 +143,7 @@ pub fn log_census() { counts[TOTAL], Fields(&counts[TOTAL + 1..]) ); + #[cfg(feature = "mask-windows")] + crate::windows::log_cpu(cpu); } } diff --git a/kernel/src/main.rs b/kernel/src/main.rs index 50d97683110..345998351bd 100644 --- a/kernel/src/main.rs +++ b/kernel/src/main.rs @@ -71,6 +71,8 @@ mod hw; mod iommu; mod preempt; mod irq_census; +#[cfg(feature = "mask-windows")] +mod windows; mod irq_ring; mod trace; mod time; diff --git a/kernel/src/sched/driver.rs b/kernel/src/sched/driver.rs index f6d0ad5f94b..800611f60c5 100644 --- a/kernel/src/sched/driver.rs +++ b/kernel/src/sched/driver.rs @@ -529,6 +529,8 @@ pub fn pass(dispose: Dispose) { }; disposed.finish() }); + #[cfg(feature = "mask-windows")] + crate::windows::scheduled(); charge_cpu_time(now); with_cpu(|cpu| { if let Some(current) = cpu.running() { @@ -600,6 +602,8 @@ pub fn pass_block(ticket: Ticket, deadline: Option) { Commit::Killed => (pass.dispose_none().finish(), false), } }); + #[cfg(feature = "mask-windows")] + crate::windows::scheduled(); charge_cpu_time(now); with_cpu(|cpu| { if let Some(current) = cpu.running() { @@ -671,6 +675,8 @@ fn drain_irqs(entered: super::dump::Entered) { /// Leave the current stack for this CPU's idle stack and never come back. pub fn enter_idle_loop() -> ! { + #[cfg(feature = "mask-windows")] + crate::windows::start_here(); percpu::set_current_tid(None); percpu::set_current_pid(None); // SAFETY: `set_kernel_stack` requires the caller be the CPU its GS base belongs to — true here, on that CPU, after its base was set. diff --git a/kernel/src/scheduler.rs b/kernel/src/scheduler.rs index 7e59c4fe273..07e9c4ae1a4 100644 --- a/kernel/src/scheduler.rs +++ b/kernel/src/scheduler.rs @@ -404,6 +404,10 @@ pub fn exit_to_user() { leave_user_if_due(); // `do_preempt` owns clearing `need_resched`; this function never clears it itself. if !crate::preempt::need_resched() { + // Every caller's next unmask is the return to user mode, or a + // kernel thread's first. + #[cfg(feature = "mask-windows")] + crate::windows::irqs_unmasking(); return; } assert!(!in_schedule_self(), "exit-to-user inside a scheduler pass"); diff --git a/kernel/src/syscall/proc.rs b/kernel/src/syscall/proc.rs index c54120404ca..b366965170a 100644 --- a/kernel/src/syscall/proc.rs +++ b/kernel/src/syscall/proc.rs @@ -24,6 +24,8 @@ pub(super) fn sys_thread_exit(code: i32) -> u64 { } pub(super) fn sys_exit(code: i32) -> u64 { + #[cfg(feature = "mask-windows")] + crate::windows::hold_once(); process::exit(code); } diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs new file mode 100644 index 00000000000..2b7e5eef161 --- /dev/null +++ b/kernel/src/windows.rs @@ -0,0 +1,141 @@ +//! Each CPU's [`toyos_sched::windows::Windows`], fed where this CPU's +//! interrupts and preempt count change, and printed beside the IRQ census as +//! `windows: cpuN irqs_off_ns=… preempt_off_ns=…` (`mask-windows` builds only). +//! +//! Each architecture calls [`irqs_masked`] and [`irqs_unmasking`] from every +//! instruction that changes whether it takes a maskable interrupt: its +//! masking primitives, the halt, every entry (a gate, `SYSCALL` or an +//! exception masks) and every return (`scheduler::exit_to_user`'s end for a +//! return to user mode, the entry's own hook for a return to the kernel). +//! Every maskable interrupt is also held to what the hardware says it +//! interrupted: one is delivered only with interrupts open. A context switch +//! changes nothing: this build switches inside an `IrqGuard`, so every saved +//! context holds interrupts masked. An NMI is not a window: nothing masks it, +//! and it runs no hook. [`preempt_raised`] and [`preempt_lowering`] follow the +//! preempt count's accessors and the entries that move it inline. +//! +//! The hooks that change `IF` run with interrupts masked; a preempt hook may +//! run with them open, since an interrupt cannot move the count across zero +//! between it and the count it follows or precedes. A transition the record +//! refuses panics, after the CPU stops being tracked so the panic's own +//! masking finds nothing to check; an exception the kernel itself took stops +//! it too ([`stop_here`]), so the fault's report is the one that is read. A CPU +//! is tracked from [`start_here`], where it joins the scheduler, and a window +//! is reported by the report after it closes. +//! +//! Once a boot, [`hold_once`] keeps both windows open for a span it reads off +//! the counter and prints, which a later report of that CPU reads back. + +use core::sync::atomic::AtomicBool; +use core::sync::atomic::Ordering::Relaxed; + +use toyos_sched::windows::{Unseen, Windows, HELD_NS}; + +use crate::arch::{cpu, percpu}; +use crate::sched::MAX_CPUS; + +static CPUS: [Windows; MAX_CPUS] = [const { Windows::new() }; MAX_CPUS]; + +/// This CPU's record, once there is a per-CPU block to say which CPU this is. +fn on(transition: impl FnOnce(&Windows) -> Result<(), Unseen>) { + if !crate::log::PERCPU_READY.load(Relaxed) { + return; + } + if let Err(unseen) = transition(&CPUS[percpu::cpu_id() as usize]) { + refuse(unseen); + } +} + +#[cold] +#[inline(never)] +fn refuse(unseen: Unseen) -> ! { + let cpu = percpu::cpu_id(); + CPUS[cpu as usize].stop(); + panic!("mask-windows: cpu{cpu} {unseen}"); +} + +/// 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 + // again, through its hook, if it found them open. + let _masked = crate::arch::IrqGuard::close(); + CPUS[percpu::cpu_id() as usize].start(crate::preempt::count(), cpu::counter()); +} + +/// Interrupts were open and this CPU has just masked them. +pub fn irqs_masked() { + on(|w| w.masked(cpu::counter)); +} + +/// This CPU took an exception in the kernel, which ends the machine: nothing +/// more of it is tracked or checked. +pub fn stop_here() { + on(|w| { + w.stop(); + Ok(()) + }); +} + +/// Interrupts are masked and this CPU is about to open them. +pub fn irqs_unmasking() { + on(|w| w.unmasking(cpu::counter)); +} + +/// The preempt count has just been raised by one. +pub fn preempt_raised() { + on(|w| w.raised(crate::preempt::count(), cpu::counter)); +} + +/// The preempt count is about to be lowered by one. +pub fn preempt_lowering() { + on(|w| w.lowering(crate::preempt::count(), cpu::counter)); +} + +/// The preempt count was just set from `old` to `new` whole. +pub fn preempt_set(old: u32, new: u32) { + on(|w| w.set(old, new, cpu::counter)); +} + +/// A scheduler pass has decided what runs here. +pub fn scheduled() { + on(|w| w.scheduled(cpu::counter)); +} + +/// This CPU halts inside a pass. +pub fn halting() { + on(|w| w.halting(cpu::counter)); +} + +/// The halt has ended, still inside its pass. +pub fn woken() { + on(|w| w.woken(cpu::counter)); +} + +/// `cpu`'s line, taking its longest windows so the next report starts from none. +pub fn log_cpu(cpu: u32) { + let (irqs, preempt) = CPUS[cpu as usize].take(); + crate::log!( + "windows: cpu{cpu} irqs_off_ns={} preempt_off_ns={}", + crate::clock::nanos_of_ticks(irqs), + crate::clock::nanos_of_ticks(preempt), + ); +} + +/// The boot's first `SYS_EXIT`, which its entry left with interrupts masked +/// and the preempt count raised, stays there for [`HELD_NS`] by this CPU's +/// counter and says how long that was: `windows: held cpuN ns=…`. +pub fn hold_once() { + static HELD: AtomicBool = AtomicBool::new(false); + if HELD.swap(true, Relaxed) { + return; + } + let from = cpu::counter(); + let mut ns = 0; + // In the nanoseconds it prints: a tick count that stands for `HELD_NS` can + // convert back to one less. + while ns < HELD_NS { + core::hint::spin_loop(); + ns = crate::clock::nanos_of_ticks(cpu::counter() - from); + } + crate::log!("windows: held cpu{} ns={ns}", percpu::cpu_id()); +} diff --git a/src/build.rs b/src/build.rs index 34429b4adf7..6536f543ee7 100644 --- a/src/build.rs +++ b/src/build.rs @@ -1330,8 +1330,12 @@ fn declared_kernel_features(root: &Path) -> Vec { pub const TEST_KERNEL: &[&str] = &["boot-actuators", "test-actuators"]; /// Kernel builds the ordinary test suite is allowed to make. -pub const TEST_SUITE_KERNEL_BUILDS: [&str; 2] = - ["", "boot-actuators,test-actuators"]; +pub const TEST_SUITE_KERNEL_BUILDS: [&str; 3] = + ["", "boot-actuators,test-actuators", MASK_WINDOWS_KERNEL[0]]; + +/// The shipping kernel with the windows' instrument and nothing else, for +/// [`SCHED_CHECK_KERNEL`]'s reason: one spelling, so one build. +pub const MASK_WINDOWS_KERNEL: &[&str] = &["mask-windows"]; /// The scheduler core's own asserts, compiled in: `toyos-sched/check`. /// @@ -2644,6 +2648,7 @@ mod tests { "lock-acquire-off", "log-commit-release-off", "loom", + "mask-windows", // `heap-lockspin`'s other arm: the same visit to the pass path, // for the same span, without the allocator's lock. "pass-spin", diff --git a/src/clippy.rs b/src/clippy.rs index 692afa971ff..a158825af6f 100644 --- a/src/clippy.rs +++ b/src/clippy.rs @@ -39,12 +39,13 @@ struct Shape { const INSTRUMENTS: &str = "debug-wait,sched-check,sched-tripwire,heap-tripwire,heap-sweep,\ pass-spin,stack-witness,switch-witness,switch-witness-mutate-frame,\ switch-witness-mutate-rsp,df-witness,df-witness-mutate,\ - entry-df-unclean"; + entry-df-unclean,mask-windows"; /// [`INSTRUMENTS`] less the direction-flag three, which are x86-64's alone. const AARCH64_INSTRUMENTS: &str = "debug-wait,sched-check,sched-tripwire,heap-tripwire,heap-sweep,\ pass-spin,stack-witness,switch-witness,\ - switch-witness-mutate-frame,switch-witness-mutate-rsp"; + switch-witness-mutate-frame,switch-witness-mutate-rsp,\ + mask-windows"; const UNCONTROLLED: &[&str] = &["toyos-pcid/counting-allocator", "toyos-sched/tripwire"]; diff --git a/tests/checks.rs b/tests/checks.rs index 279907652b1..fbc4f576194 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -396,6 +396,88 @@ mod checks { Ok(()) } + /// [`mask_windows`] and `irqcensus::windows_under` against captures no + /// boot has to produce: two CPUs and the T14 row's three exits, a report + /// each, with cpu1 holding at the first. + #[test] + fn mask_windows_verdict() -> Result<(), String> { + use common::irqcensus::{windows_under, Measured}; + let census = |cpu: u32| { + format!( + "[kernel 0.1 cpu0] irq: cpu{cpu} total=0 timer=0 xhci=0 userdev=0 sound=0 i8042=0 \ + dmafault=0 hda=0 tlb=0 nmi=0 spurious=0 unclaimed=0\n" + ) + }; + let windows = |cpu: u32, (irqs, preempt): (u64, u64)| { + format!("[kernel 0.1 cpu0] windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}\n") + }; + let report = |cpu0: (u64, u64), cpu1: (u64, u64)| [census(0), windows(0, cpu0), census(1), windows(1, cpu1)].concat(); + let exit = |name: &str| format!("[kernel 0.1 cpu0] exit: {name} pid=9 code=0 cpu=1ms\n"); + let held_ns = toyos_sched::windows::HELD_NS; + let hold = format!("[kernel 0.1 cpu1] windows: held cpu1 ns={}\n", held_ns + 7); + // Since each CPU joined: longer on cpu0 than anything under the load. + let first = [report((6_500_000, 6_400_000), (900, 800)), exit("test_rs_idle_span")].concat(); + let read_back = (held_ns + 400, held_ns + 300); + let opening = [report((100, 100), read_back), exit("pwd")].concat(); + let own = [report((3_000_000, 1_100_000), (700_000, 600_000)), exit(WINDOWS_LOAD)].concat(); + let good = [hold.as_str(), &first, &opening, &own].concat(); + let exited = windows_load_exited(); + + mask_windows(&good, 2).map_err(|e| format!("the good capture was refused: {e}"))?; + let unpaired = |what: &str, capture: &str, says: &str| match mask_windows(capture, 2) { + Ok(()) => Err(format!("{what} was accepted")), + Err(e) if e.contains(says) => Ok(()), + Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")), + }; + unpaired("a census without its windows", &good.replace(&windows(0, (100, 100)), ""), "went out without")?; + unpaired("a CPU that closed no window", &report((0, 7), (3, 4)), "closed no window")?; + unpaired("one CPU of two", &[census(0), windows(0, (5, 7))].concat(), "1 of 2")?; + unpaired("a field missing", &good.replace(" preempt_off_ns=100", ""), "fields")?; + + let read = windows_under(&good, 2, &exited)?; + let want = Measured { held: read_back, load: (3_000_000, 1_100_000) }; + if read != want { + return Err(format!("the good capture read {read:?}, and the hold's and the load's reports say {want:?}")); + } + let refused = |what: &str, capture: &str, says: &str| match windows_under(capture, 2, &exited) { + Ok(read) => Err(format!("{what} was read as {read:?}")), + Err(e) if e.contains(says) => Ok(()), + Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")), + }; + refused("a load's report with none before it", &[hold.as_str(), &own].concat(), "the boot's first")?; + refused("a load that never ended", &good.replace(&exit(WINDOWS_LOAD), ""), "never ended")?; + refused("no hold", &good.replace(&hold, ""), "held no window of known length")?; + refused("a second hold", &[hold.as_str(), &good].concat(), "a second hold")?; + refused("a hold cut short", &good.replace(&hold, "[kernel 0.1 cpu1] windows: held cpu1 ns=1000\n"), "the kernel owes")?; + refused( + "an interrupts-off window read back at half", + &good.replace(&windows(1, read_back), &windows(1, (read_back.0 / 2, read_back.1))), + "shorter than it was held", + )?; + refused( + "a preemption-off window read back at half", + &good.replace(&windows(1, read_back), &windows(1, (read_back.0, read_back.1 / 2))), + "shorter than it was held", + )?; + refused( + "an interrupts-off window read back at ten times", + &good.replace(&windows(1, read_back), &windows(1, (read_back.0 * 10, read_back.1))), + "past the ceiling", + )?; + refused( + "a preemption-off window read back at ten times", + &good.replace(&windows(1, read_back), &windows(1, (read_back.0, read_back.1 * 10))), + "past the ceiling", + )?; + refused( + "a hold the load's own report reads back", + &[first.as_str(), &opening, &hold, &own].concat(), + "reported nothing between", + )?; + refused("a report that skips a CPU", &good.replace(&windows(0, (3_000_000, 1_100_000)), ""), "names cpu1 at place 0")?; + Ok(()) + } + /// What the declaration itself has to be, before any of it means anything. /// Which shared-boot binaries need `SYS_DEBUG`, asked of their source. /// diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index e7a65d4740e..d317a468056 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -1,4 +1,5 @@ -//! The kernel's interrupt census, read back on the host. +//! The kernel's interrupt census, and the windows a `mask-windows` kernel +//! prints beside it, read back on the host. //! //! The guest prints `irq: cpuN total=… timer=… …` per online CPU whenever a //! process exits, on `SYS_SHUTDOWN` and on the blocked-task dump @@ -98,6 +99,194 @@ impl Census { } } +/// One CPU's longest interrupts-off and preemption-off windows since the report +/// before, out of the line a `mask-windows` kernel prints beside that CPU's +/// census (`kernel/src/windows.rs`). +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct Windows { + pub cpu: u32, + pub irqs_off_ns: u64, + pub preempt_off_ns: u64, +} + +impl Windows { + /// One line, or why it is not one; anything before `windows: cpu` is ignored. + pub fn parse(line: &str) -> Option> { + let rest = line.split("windows: cpu").nth(1)?; + let fields: Vec<&str> = rest.split_whitespace().collect(); + let value = |at: usize, name: &str| -> Result { + fields + .get(at) + .and_then(|f| f.strip_prefix(name)) + .and_then(|v| v.parse().ok()) + .ok_or_else(|| format!("no `{name}` field at {at} in {rest:?}")) + }; + let parsed = (|| { + if fields.len() != 3 { + return Err(format!("{} fields, want 3, in {rest:?}", fields.len())); + } + let cpu = fields[0].parse().map_err(|_| format!("unreadable cpu number in {rest:?}"))?; + Ok(Self { cpu, irqs_off_ns: value(1, "irqs_off_ns=")?, preempt_off_ns: value(2, "preempt_off_ns=")? }) + })(); + Some(parsed) + } +} + +/// The line a `mask-windows` kernel prints once a boot, where it held both of +/// cpuK's windows for a span read off that CPU's counter +/// (`kernel/src/windows.rs`): `windows: held cpuK ns=`. +const HELD: &str = "windows: held cpu"; + +fn held(line: &str) -> Option> { + let rest = line.split(HELD).nth(1)?; + let parsed = match rest.split_whitespace().collect::>().as_slice() { + [cpu, ns] => cpu.parse().ok().zip(ns.strip_prefix("ns=").and_then(|ns| ns.parse().ok())), + _ => None, + }; + Some(parsed.ok_or_else(|| format!("unreadable held line {rest:?}"))) +} + +/// The judge of every `mask-windows` boot, and it judges no duration: each +/// census line has its CPU's windows line beside it, and each CPU closed both +/// kinds of window at some point of the boot. Answers each CPU's longest +/// windows over the whole capture. +pub fn windows(capture: &str) -> Result, String> { + let mut censuses: BTreeMap = BTreeMap::new(); + let mut reports: Vec = Vec::new(); + for line in capture.lines() { + if let Some(census) = Census::parse(line) { + *censuses.entry(census.map_err(|why| format!("{why}\nline: {line}"))?.cpu).or_default() += 1; + } else if let Some(report) = Windows::parse(line) { + reports.push(report.map_err(|why| format!("{why}\nline: {line}"))?); + } + } + if censuses.is_empty() { + return Err(format!("no `irq: cpu` census in the capture:\n{capture}")); + } + let mut beside: BTreeMap = BTreeMap::new(); + for report in &reports { + *beside.entry(report.cpu).or_default() += 1; + } + if beside != censuses { + return Err(format!( + "census lines per cpu {censuses:?} and windows lines per cpu {beside:?}: a census \ + went out without its windows, or windows without their census" + )); + } + let mut longest: BTreeMap = BTreeMap::new(); + for report in &reports { + let most = longest.entry(report.cpu).or_insert(Windows { irqs_off_ns: 0, preempt_off_ns: 0, ..*report }); + most.irqs_off_ns = most.irqs_off_ns.max(report.irqs_off_ns); + most.preempt_off_ns = most.preempt_off_ns.max(report.preempt_off_ns); + } + for most in longest.values() { + if most.irqs_off_ns == 0 || most.preempt_off_ns == 0 { + return Err(format!( + "cpu{} closed no window of one kind in the whole boot, and every CPU masks and \ + passes: {most:?}", + most.cpu + )); + } + } + Ok(longest) +} + +/// What a machine's boot read, each the longest interrupts-off and +/// preemption-off window in nanoseconds. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub struct Measured { + /// What the holding CPU reported between its hold and the load's start. + pub held: (u64, u64), + /// What any CPU closed in the load's own report. + pub load: (u64, u64), +} + +/// The durations a machine's boot is judged by, read from the reports of +/// `cpus` CPUs before the record `load_exited` heads, the load's exit. +/// +/// **The load's reading is its own report alone.** A report carries what +/// closed since the report before, and the load's exit prints one before it +/// tears the process down. So that report spans the teardown of the job +/// before, the runner's spawn of the load and the load up to its exit, and it +/// is refused unless a report before it emptied every CPU's record. +/// +/// **A window of known length is read back.** The kernel held both of one +/// CPU's windows for the span its held line states: that CPU's reports from +/// there to the load's start carry a window of each kind no shorter, and none +/// past `metaltimings::ceiling` of it. +pub fn windows_under(capture: &str, cpus: u32, load_exited: &str) -> Result { + let mut reports: Vec<(usize, Vec)> = Vec::new(); + let mut open: Vec = Vec::new(); + let mut hold: Option<(usize, u32, u64)> = None; + let mut exited: Option = None; + for (at, line) in capture.lines().enumerate() { + if let Some(report) = Windows::parse(line) { + let report = report.map_err(|why| format!("{why}\nline: {line}"))?; + if report.cpu as usize != open.len() { + return Err(format!("a report of {cpus} CPUs names cpu{} at place {}\nline: {line}", report.cpu, open.len())); + } + open.push(report); + if open.len() == cpus as usize { + reports.push((at, std::mem::take(&mut open))); + } + } else if let Some(said) = held(line) { + let (cpu, ns) = said.map_err(|why| format!("{why}\nline: {line}"))?; + if hold.replace((at, cpu, ns)).is_some() { + return Err(format!("a second hold, and the kernel holds once a boot\nline: {line}")); + } + } else if exited.is_none() && line.contains(load_exited) { + exited = Some(at); + } + } + let exited = exited.ok_or_else(|| format!("no `{load_exited}` record: the load never ended"))?; + let own = reports + .iter() + .rposition(|(at, _)| *at < exited) + .ok_or_else(|| format!("no report before `{load_exited}`: the load's exit printed none"))?; + if own == 0 { + return Err("the load's report is the boot's first: none was taken as the load started, so it \ + carries every window since each CPU joined" + .to_string()); + } + let longest = |lines: &mut dyn Iterator| { + lines.fold((0, 0), |(irqs, preempt), w| (irqs.max(w.irqs_off_ns), preempt.max(w.preempt_off_ns))) + }; + + let (hold_at, cpu, ns) = + hold.ok_or_else(|| format!("no `{HELD}` line: this kernel held no window of known length"))?; + if ns < toyos_sched::windows::HELD_NS { + return Err(format!("cpu{cpu} held its windows for {ns} ns, and the kernel owes {}", toyos_sched::windows::HELD_NS)); + } + let mut read_back = reports[..own] + .iter() + .filter(|(at, _)| *at > hold_at) + .filter_map(|(_, report)| report.get(cpu as usize)) + .peekable(); + if read_back.peek().is_none() { + return Err(format!( + "cpu{cpu} reported nothing between its hold and the load's own report, so the load's \ + reading carries the hold" + )); + } + let held = longest(&mut read_back); + let read = format!( + "cpu{cpu} held both windows for {ns} ns, and its reports before the load's read back \ + irqs_off_ns={} preempt_off_ns={}", + held.0, held.1 + ); + if held.0 < ns || held.1 < ns { + return Err(format!("{read}: a window was reported shorter than it was held")); + } + let ceiling = toyos_build::metaltimings::ceiling(ns); + if held.0 > ceiling || held.1 > ceiling { + return Err(format!( + "{read}, past the ceiling of {ceiling}: a window was reported at more than twice what was held" + )); + } + let load = longest(&mut reports[own].1.iter()); + Ok(Measured { held, load }) +} + /// The newest census each CPU of each guest printed, keyed by the boot's own /// sequence number. /// diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 50d349afe0a..4abf78d6323 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -153,10 +153,12 @@ pub fn boot_census() -> (u32, u32, Vec) { /// /// `""` is what an image ships. [`toyos_build::build::TEST_KERNEL`] is every /// actuator compiled in, armed by boot parameter. An entry here is a decision -/// to pay a kernel build per suite run forever. Interactive debug mode is -/// separate: it builds [`toyos_build::build::DEBUG_KERNEL_BUILD`] and returns -/// before the suite. -pub const DECLARED_KERNEL_BUILDS: [&str; 2] = +/// to pay a kernel build per suite run forever. +/// [`toyos_build::build::MASK_WINDOWS_KERNEL`] made it: its hooks sit on every +/// entry and masking primitive, where a parameter would be a branch on the path +/// they measure. Interactive debug mode is separate: it builds +/// [`toyos_build::build::DEBUG_KERNEL_BUILD`] and returns before the suite. +pub const DECLARED_KERNEL_BUILDS: [&str; 3] = toyos_build::build::TEST_SUITE_KERNEL_BUILDS; /// How many guests the run may have up at once. diff --git a/tests/metal/lenovo-20w0003amz.toml b/tests/metal/lenovo-20w0003amz.toml index 501e12cc8cc..38f0210185c 100644 --- a/tests/metal/lenovo-20w0003amz.toml +++ b/tests/metal/lenovo-20w0003amz.toml @@ -73,6 +73,9 @@ bios = "N34ET71W (1.71 )" "boot.usbload.complete_ms" = 1165 "boot.usbload.panel_max_us" = 3837 "boot.usbload.panel_us" = 21428 +"boot.windowscase.complete_ms" = 1152 +"boot.windowscase.panel_max_us" = 3825 +"boot.windowscase.panel_us" = 21453 "latency.p99_us" = 16 "tlb.latencycase.p50_ns" = 2194 "tlb.latencycase.p99_ns" = 3740 diff --git a/tests/toyos-rust-tests/src/bin/idle_span.rs b/tests/toyos-rust-tests/src/bin/idle_span.rs new file mode 100644 index 00000000000..058e681fdb6 --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/idle_span.rs @@ -0,0 +1,16 @@ +//! **The machine idles for a span nothing can mistake for work**, and this +//! process's exit is the boot's first. It asserts nothing: `mask_windows` +//! reads what a `mask-windows` kernel reports of the CPU that slept through +//! it, whose halt is no preemption-off window. + +use std::thread::sleep; +use std::time::Duration; + +/// Five times what the record's ceiling allows the window the kernel holds at +/// this exit (`toyos_sched::windows::HELD_NS`, doubled), so a halt counted as +/// a window is past it. +const SPAN: Duration = Duration::from_millis(500); + +fn main() { + sleep(SPAN); +} diff --git a/tests/toyos-rust-tests/src/bin/ring_park_herd.rs b/tests/toyos-rust-tests/src/bin/ring_park_herd.rs new file mode 100644 index 00000000000..1a609b84e2c --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/ring_park_herd.rs @@ -0,0 +1,114 @@ +//! **One process parks 256 threads in `submit` on one ring, and a sibling +//! thread completes into it.** +//! +//! A ring's own watch sits behind a lock that masks interrupts, so every +//! completion notifies all 256 registrations with interrupts masked, and each +//! woken thread re-registers under that lock and parks again: the load +//! `issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md` +//! names, which `mask_windows` reads the windows under. +//! +//! The sibling is this program's main thread. Each round it completes one +//! `OP_NOP` and takes the completion back, so the count the parked threads +//! wait for never reaches two, and it posts the next only once the kernel's +//! roster shows every one of them parked again. Two completions left standing +//! end the run. + +use std::sync::atomic::{AtomicU32, Ordering}; +use std::thread; + +use toyos::endow::{Endowments, SYSCAP_LABEL}; +use toyos::syscap::SysCap; +use toyos_abi::inbox::{RingHeader, Submission, COMPLETION_RING_OFF, OP_NOP, SUBMISSIONS_OFF, SUBMISSION_RING_OFF}; +use toyos_abi::syscall; +use toyos_abi::RawHandle; + +#[path = "../roster.rs"] +mod roster; + +const PARKED: usize = 256; + +/// Completions each parked thread is woken by and parks again after. +const ROUNDS: u64 = 64; + +/// The fewest the ring takes: the sibling never has more than two in it. +const DEPTH: u32 = 2; + +/// What every parked thread waits for, and what the sibling leaves only at the end. +const ENDING: u32 = 2; + +/// The ring's page, as `toyos::poller` reaches it: one atomic word or one +/// whole entry at a time, since the kernel writes it too. +struct Ring { + handle: RawHandle, + base: *mut u8, +} + +// SAFETY: the page stays mapped until the handle closes, after every thread is joined. +unsafe impl Sync for Ring {} + +impl Ring { + fn word(&self, ring_off: u64, field_off: usize) -> &AtomicU32 { + // SAFETY: inside the inbox page, 4-aligned; an atomic is sound over memory the kernel also writes. + unsafe { AtomicU32::from_ptr(self.base.add(ring_off as usize + field_off) as *mut u32) } + } + + /// One `OP_NOP`, handed to the kernel, which completes it at once. + fn complete_one(&self, token: u64) { + let tail = self.word(SUBMISSION_RING_OFF, core::mem::offset_of!(RingHeader, tail)); + let at = tail.load(Ordering::Relaxed); + let entry = Submission { op: OP_NOP, token, ..Submission::default() }; + // SAFETY: the slot `at` masks to is inside the page's submission array, which only this thread writes. + unsafe { + (self.base.add( + SUBMISSIONS_OFF as usize + (at & (DEPTH - 1)) as usize * core::mem::size_of::(), + ) as *mut Submission) + .write(entry); + } + tail.store(at.wrapping_add(1), Ordering::Release); + syscall::inbox_submit(self.handle, 1, 0, 0).expect("the sibling's submit"); + } + + /// Take the oldest completion back, so the count falls. + fn consume_one(&self) { + let head = self.word(COMPLETION_RING_OFF, core::mem::offset_of!(RingHeader, head)); + head.fetch_add(1, Ordering::Release); + } +} + +fn main() { + let cap: SysCap = Endowments::get() + .take(SYSCAP_LABEL) + .expect("test-runner endows every binary it spawns a system capability"); + // SAFETY: the page is read only through `Ring`, and the handle closes after every thread is joined. + let (handle, base) = unsafe { syscall::inbox_setup(DEPTH) }.expect("the ring"); + let ring = Ring { handle, base }; + + let parked_all = || { + roster::my_threads(&cap) + .iter() + .filter(|&&(is_thread, state)| is_thread && state == roster::BLOCKED) + .count() + == PARKED + }; + + thread::scope(|s| { + for _ in 0..PARKED { + s.spawn(|| { + let answered = syscall::inbox_submit(ring.handle, 0, ENDING, u64::MAX) + .expect("a parked thread's submit"); + assert!(answered >= ENDING, "a parked thread returned with {answered} completions"); + }); + } + roster::await_true(parked_all); + for round in 0..ROUNDS { + ring.complete_one(round); + ring.consume_one(); + roster::await_true(parked_all); + } + for token in 0..u64::from(ENDING) { + ring.complete_one(ROUNDS + token); + } + }); + syscall::close(handle); + println!("ring_park_herd: {PARKED} threads parked in submit on one ring, woken by {ROUNDS} completions"); +} diff --git a/tests/toyos-rust-tests/src/roster.rs b/tests/toyos-rust-tests/src/roster.rs index cbd5612e11d..4c59182836f 100644 --- a/tests/toyos-rust-tests/src/roster.rs +++ b/tests/toyos-rust-tests/src/roster.rs @@ -33,9 +33,13 @@ pub fn my_threads(cap: &SysCap) -> Vec<(bool, u8)> { pub fn threads_of(cap: &SysCap, pid: u32) -> Vec<(bool, u8)> { const HEADER: usize = toyos::system::SYSINFO_HEADER_SIZE; const ENTRY: usize = toyos::system::SYSINFO_ENTRY_SIZE; - let mut buf = vec![0u8; HEADER + ENTRY * 256]; + const ENTRIES: usize = 1024; + let mut buf = vec![0u8; HEADER + ENTRY * ENTRIES]; let n = cap.roster(&mut buf); assert!((HEADER..=buf.len()).contains(&n), "sysinfo answered {n}"); + // Past the buffer the roster is cut short, and a thread cut off is one never found. + let live = toyos_abi::syscall::SysinfoHeader::decode(buf[..HEADER].try_into().unwrap()).entries; + assert!(live as usize <= ENTRIES, "the machine has {live} threads and the roster holds {ENTRIES}"); (HEADER..) .step_by(ENTRY) .take_while(|pos| pos + ENTRY <= n) diff --git a/tests/toyos.rs b/tests/toyos.rs index 7fb33c083ca..9081943e0fa 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -73,6 +73,13 @@ const RUST_SKIP: &[&str] = &[ // is read off the clock around the syscall. The `tlb_shootdown_waits` // metal row runs it on the T14. "tlb_shootdown_waits", + // Its product is the windows a `mask-windows` kernel reports under it, and + // its 256 threads' stacks would crowd every member after it in one boot. + // The `mask_windows` metal row runs it. + "ring_park_herd", + // It asserts nothing: it is half a second of an idle machine, which the + // same row reads the windows across. + "idle_span", // The C corpus's comparator: a helper reached through one symlink per case, // never a test of its own. `shared_metal` stages every name on this list. "ccheck", @@ -154,6 +161,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_mask_windows", qemu::Profile::VirtEl2), ("virt_smp", qemu::Profile::VirtEl2), ("virt_el1_smp", qemu::Profile::VirtTcg), ("virt_failed_ap_leaves_no_hole", qemu::Profile::VirtEl2), @@ -238,6 +246,12 @@ const METAL: &[(&str, metal::Metal)] = &[ judge: |b| irq_census(b[0].kernel().text()), }, ), + ( + // The windows on the machine that owes them: every CPU reported beside + // its census, and a held window read back. + "mask_windows", + metal::Metal { arms: WINDOWSCASE, judge: |b| windows_on_metal(b[0]) }, + ), ( "mkdir_cap", metal::Metal { @@ -647,6 +661,28 @@ const TESTCASES_READDIR: &[metal::Arm] = const JOBCASE: &[metal::Arm] = &[metal::once("jobcase", "tests/jobcase", &[], &[])]; +/// The shipping kernel with the windows' instrument and nothing else, so what +/// it reads is that kernel under the herd. Three exits, a report each: +/// `idle_span`'s is the boot's first, where the kernel holds; `pwd`'s reads the +/// hold back and empties every record; the herd's is the herd's reading. +const WINDOWSCASE: &[metal::Arm] = &[metal::Arm { + features: toyos_build::build::MASK_WINDOWS_KERNEL, + ..metal::once( + "windowscase", + "tests/testcases", + &[], + &["test_rs_idle_span", "pwd", WINDOWS_LOAD], + ) +}]; + +/// The load `mask_windows` reads the windows under. +const WINDOWS_LOAD: &str = "test_rs_ring_park_herd"; + +/// The head of the kernel's record of [`WINDOWS_LOAD`]'s exit. +fn windows_load_exited() -> String { + format!("{}{} pid=", toyos_build::bootlog::EXIT, toyos_build::bootlog::recorded_name(WINDOWS_LOAD)) +} + /// A `logd` that leaves soundd's ring unread until the job says the tone played. const LOGSTALLCASE: &[metal::Arm] = &[metal::once("logstallcase", "tests/logstallcase", &[], &["test_rs_soundd_log_stall"])]; @@ -1352,6 +1388,22 @@ fn virt_job(profile: qemu::Profile, job: &str, said: &str) -> Result<(), String> judge_virt_job(&mut qemu, job, said).map(drop) } +/// A `mask-windows` boot's windows: `common::irqcensus::windows`'s verdict, +/// with `cpus` CPUs reporting. +fn mask_windows(capture: &str, cpus: u32) -> Result<(), String> { + let longest = common::irqcensus::windows(capture)?; + if longest.len() != cpus as usize { + return Err(format!("{} of {cpus} CPUs reported windows: {longest:?}", longest.len())); + } + for most in longest.values() { + eprintln!( + " [windows] cpu{} irqs_off_ns={} preempt_off_ns={}", + most.cpu, most.irqs_off_ns, most.preempt_off_ns + ); + } + Ok(()) +} + /// Wait for `job`'s end on a guest booted with it, and judge it: it ends with /// exit 0, having said `said`. Answers everything the PL011 carried. fn judge_virt_job(qemu: &mut QemuInstance, job: &str, said: &str) -> Result { @@ -1384,6 +1436,19 @@ const UNMAP_TOUCH_SAID: &str = /// The CPUs `virt_smp` boots. const VIRT_CPUS: u32 = 8; +/// The windows on AArch64: `tests/virtsmpcase` on [`VIRT_CPUS`] CPUs of a +/// `mask-windows` kernel, whose every hook checks the state it finds, judged +/// once the case's job `unmap_touch` has ended. +fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { + let mut qemu = boot_virt_smp(BootOptions { + profile, + smp: VIRT_CPUS, + kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL, + ..Default::default() + }); + mask_windows(&judge_virt_job(&mut qemu, "unmap_touch", UNMAP_TOUCH_SAID)?, VIRT_CPUS) +} + /// Boot `tests/virtsmpcase` as `options` say. fn boot_virt_smp(options: BootOptions) -> QemuInstance { let config = compile::repo_root().join("tests/virtsmpcase/system.toml"); @@ -1961,6 +2026,7 @@ 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_mask_windows" => virt_mask_windows(profile), "virt_irq_storm" => { // The CPU floods itself with SGIs until the timer has fired a // thousand times through the flood, then waits for every SGI it @@ -2421,6 +2487,22 @@ fn irq_census(capture: &str) -> Result<(), String> { Ok(()) } +/// The T14's windows: [`mask_windows`]' verdict with every CPU reporting, and +/// `common::irqcensus::windows_under`'s. Its durations are printed and none is +/// recorded: one boot's longest window is no baseline for the next. +fn windows_on_metal(boot: &metal::Readback) -> Result<(), String> { + boot.job_passed(WINDOWS_LOAD)?; + let kernel = boot.kernel(); + let cpus = boot.cpus()?; + mask_windows(kernel.text(), cpus)?; + let read = common::irqcensus::windows_under(kernel.text(), cpus, &windows_load_exited())?; + eprintln!( + " [windows] held irqs_off_ns={} preempt_off_ns={}; herd irqs_off_ns={} preempt_off_ns={}", + read.held.0, read.held.1, read.load.0, read.load.1 + ); + Ok(()) +} + fn pci_cap_selftest(log: &str) -> Result<(), String> { if let Some(bad) = log.lines().find(|l| l.contains("pci cap selftest FAILED")) { return Err(format!("{bad}\n{log}")); diff --git a/toyos-sched/loom/src/lib.rs b/toyos-sched/loom/src/lib.rs index d3b6762d873..82044dd7e76 100644 --- a/toyos-sched/loom/src/lib.rs +++ b/toyos-sched/loom/src/lib.rs @@ -49,5 +49,7 @@ pub mod task; pub mod timer; #[path = "../../src/watch.rs"] pub mod watch; +#[path = "../../src/windows.rs"] +pub mod windows; pub mod model; diff --git a/toyos-sched/src/lib.rs b/toyos-sched/src/lib.rs index 9f5032d2b87..ce70a84c921 100644 --- a/toyos-sched/src/lib.rs +++ b/toyos-sched/src/lib.rs @@ -28,3 +28,4 @@ pub mod sync; pub mod task; pub mod timer; pub mod watch; +pub mod windows; diff --git a/toyos-sched/src/windows.rs b/toyos-sched/src/windows.rs new file mode 100644 index 00000000000..8c80caffb45 --- /dev/null +++ b/toyos-sched/src/windows.rs @@ -0,0 +1,346 @@ +//! One CPU's longest interrupts-off and preemption-off windows since its last +//! report: the record the kernel's `mask-windows` build keeps per CPU, feeds +//! at every transition, and prints beside the IRQ census. +//! +//! **An interrupts-off window** runs from the instant a CPU stops taking +//! maskable interrupts to the instant it takes them again: [`Windows::masked`] +//! follows the one and [`Windows::unmasking`] precedes the other. +//! +//! **A preemption-off window** runs while the CPU's preempt count is above +//! zero. A scheduler pass ends it and starts the next ([`Windows::scheduled`]), +//! because a pass is where a waiting thread gets the CPU, and the idle halt +//! inside a pass is no window ([`Windows::halting`], [`Windows::woken`]), +//! because a wake ends it. [`Windows::raised`] follows every raise of the count +//! by one and [`Windows::lowering`] precedes every lowering by one; each acts +//! only on a crossing of zero. +//! +//! **Every transition is checked against the state it finds**, and one that +//! could not have followed it is [`Unseen`]: a transition before it that +//! nothing reported. The record is written by its CPU alone and a take +//! empties it from any. Nothing here reads a clock: `now` is the caller's +//! counter, read only by a transition that needs it. + +use core::fmt; + +use crate::sync::{AtomicU64, Ordering}; + +/// A CPU that has not joined the scheduler, or that stopped being tracked: +/// every transition is accepted and records nothing. +const UNTRACKED: u64 = u64::MAX; + +/// How long the kernel holds both windows, once a boot, for a report to read +/// back: more than twice any window a boot closes by itself, so no other +/// window stands in for it, whole or halved. +pub const HELD_NS: u64 = 50_000_000; + +/// One CPU's windows. The counter is never zero once firmware has run, so a +/// stamp of zero is no open window. +pub struct Windows { + /// [`UNTRACKED`], 0 while interrupts are open, else the counter at which they were masked. + irqs_off: AtomicU64, + /// 0 while the preempt count is zero or the CPU halts inside a pass, else + /// the counter at which the count left zero or a pass or a wake last ran. + preempt_off: AtomicU64, + irqs_longest: AtomicU64, + preempt_longest: AtomicU64, +} + +/// A transition the record says could not have happened, named by the one +/// before it that nothing reported. +#[derive(Clone, Copy, PartialEq, Eq, Debug)] +pub enum Unseen { + /// Masked, with a window open. + AnUnmask, + /// Unmasking, with no window open. + AMask, + /// The count left zero, or a halt ended, with a window open. + ALowering, + /// The count returned to zero, a pass ran or a halt began, with no window open. + ARaise, +} + +impl fmt::Display for Unseen { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.write_str(match self { + Unseen::AnUnmask => "masked interrupts with a window open: an unmask reached no hook", + Unseen::AMask => "found interrupts masked with no window open: a mask reached no hook", + Unseen::ALowering => { + "left a preempt count of zero with a window open: a lowering reached no hook" + } + Unseen::ARaise => { + "found the preempt count raised with no window open: a raise reached no hook" + } + }) + } +} + +impl Windows { + /// No `Default` beside it, for `fair::Frontier::new`'s reason: every + /// record is a `static`, which only a `const fn` can build. + #[cfg(not(feature = "loom"))] + #[allow(clippy::new_without_default)] + pub const fn new() -> Self { + Self { + irqs_off: AtomicU64::new(UNTRACKED), + preempt_off: AtomicU64::new(0), + irqs_longest: AtomicU64::new(0), + preempt_longest: AtomicU64::new(0), + } + } + + // Loom's atomics have no const constructor, so this arm alone drops `const`. + #[cfg(feature = "loom")] + #[allow(clippy::new_without_default)] + pub fn new() -> Self { + Self { + irqs_off: AtomicU64::new(UNTRACKED), + preempt_off: AtomicU64::new(0), + irqs_longest: AtomicU64::new(0), + preempt_longest: AtomicU64::new(0), + } + } + + fn tracked(&self) -> bool { + self.irqs_off.load(Ordering::Relaxed) != UNTRACKED + } + + fn record(longest: &AtomicU64, since: u64, now: u64) { + let span = now.saturating_sub(since); + if span > longest.load(Ordering::Relaxed) { + longest.fetch_max(span, Ordering::Relaxed); + } + } + + /// The CPU joins the scheduler with interrupts masked and its preempt + /// count at `count`, and is tracked from here. + pub fn start(&self, count: u32, now: u64) { + self.preempt_off.store(if count == 0 { 0 } else { now }, Ordering::Relaxed); + self.irqs_off.store(now, Ordering::Relaxed); + } + + /// Nothing more is tracked or checked: what a caller does before it + /// reports an [`Unseen`], so its own masking finds nothing to check. + pub fn stop(&self) { + self.irqs_off.store(UNTRACKED, Ordering::Relaxed); + } + + /// Interrupts were open and have just been masked. + pub fn masked(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + match self.irqs_off.load(Ordering::Relaxed) { + UNTRACKED => Ok(()), + 0 => { + self.irqs_off.store(now(), Ordering::Relaxed); + Ok(()) + } + _ => Err(Unseen::AnUnmask), + } + } + + /// Interrupts are masked and about to be opened. + pub fn unmasking(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + match self.irqs_off.load(Ordering::Relaxed) { + UNTRACKED => Ok(()), + 0 => Err(Unseen::AMask), + since => { + Self::record(&self.irqs_longest, since, now()); + self.irqs_off.store(0, Ordering::Relaxed); + Ok(()) + } + } + } + + /// The preempt count has just been raised by one, to `count`. + pub fn raised(&self, count: u32, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if count != 1 || !self.tracked() { + return Ok(()); + } + self.open_preempt(now) + } + + /// The preempt count, at `count`, is about to be lowered by one. + pub fn lowering(&self, count: u32, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if count != 1 || !self.tracked() { + return Ok(()); + } + self.close_preempt(now()) + } + + /// The preempt count has just been set from `old` to `new` whole. + pub fn set(&self, old: u32, new: u32, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if !self.tracked() { + return Ok(()); + } + match (old, new) { + (0, 0) => Ok(()), + (0, _) => self.open_preempt(now), + (_, 0) => self.close_preempt(now()), + _ => Ok(()), + } + } + + /// A scheduler pass has decided what runs here: the window it ran in + /// ends, and the next starts, since the count is still raised. + pub fn scheduled(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if !self.tracked() { + return Ok(()); + } + let now = now(); + self.close_preempt(now)?; + self.preempt_off.store(now, Ordering::Relaxed); + Ok(()) + } + + /// The CPU halts inside a pass, waiting for whatever runs next. + pub fn halting(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if !self.tracked() { + return Ok(()); + } + self.close_preempt(now()) + } + + /// The halt [`Windows::halting`] began has ended, still inside its pass. + pub fn woken(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if !self.tracked() { + return Ok(()); + } + self.open_preempt(now) + } + + fn open_preempt(&self, now: impl FnOnce() -> u64) -> Result<(), Unseen> { + if self.preempt_off.load(Ordering::Relaxed) != 0 { + return Err(Unseen::ALowering); + } + self.preempt_off.store(now(), Ordering::Relaxed); + Ok(()) + } + + fn close_preempt(&self, now: u64) -> Result<(), Unseen> { + match self.preempt_off.load(Ordering::Relaxed) { + 0 => Err(Unseen::ARaise), + since => { + Self::record(&self.preempt_longest, since, now); + self.preempt_off.store(0, Ordering::Relaxed); + Ok(()) + } + } + } + + /// The longest interrupts-off and preemption-off windows closed since the + /// last take, in counter ticks; the next take starts from none. + pub fn take(&self) -> (u64, u64) { + ( + self.irqs_longest.swap(0, Ordering::Relaxed), + self.preempt_longest.swap(0, Ordering::Relaxed), + ) + } +} + +#[cfg(test)] +mod tests { + use super::{Unseen, Windows}; + + /// A record tracked from `at` with interrupts open and the count at zero, + /// as a CPU stands once its start's guard has let go. + fn open_at(at: u64) -> Windows { + let w = Windows::new(); + w.start(0, at); + w.unmasking(|| at).unwrap(); + w.take(); + w + } + + #[test] + fn an_interrupts_off_window_is_mask_to_unmask_and_the_longest_is_taken_once() { + let w = open_at(1); + w.masked(|| 10).unwrap(); + w.unmasking(|| 25).unwrap(); + w.masked(|| 30).unwrap(); + w.unmasking(|| 34).unwrap(); + assert_eq!(w.take(), (15, 0)); + assert_eq!(w.take(), (0, 0), "a take starts the next report from none"); + } + + #[test] + fn only_a_crossing_of_zero_opens_or_closes_a_preemption_off_window() { + let w = open_at(1); + w.raised(1, || 10).unwrap(); + w.raised(2, || panic!("a raise past one reads no clock")).unwrap(); + w.lowering(2, || panic!("a lowering to one reads no clock")).unwrap(); + w.lowering(1, || 17).unwrap(); + assert_eq!(w.take(), (0, 7)); + } + + #[test] + fn a_pass_ends_the_preemption_off_window_and_starts_the_next() { + let w = open_at(1); + w.raised(1, || 10).unwrap(); + w.scheduled(|| 20).unwrap(); + w.lowering(1, || 23).unwrap(); + assert_eq!(w.take(), (0, 10), "the window is the pass's, not the whole raise"); + } + + #[test] + fn the_idle_halt_inside_a_pass_is_no_window() { + let w = open_at(1); + w.raised(1, || 10).unwrap(); + w.halting(|| 14).unwrap(); + w.woken(|| 1_000).unwrap(); + w.lowering(1, || 1_003).unwrap(); + assert_eq!(w.take(), (0, 4), "the wait is not counted, either side of it is"); + } + + #[test] + fn a_whole_set_opens_or_closes_only_across_zero() { + let w = open_at(1); + w.set(0, 2, || 10).unwrap(); + w.set(2, 3, || panic!("a set between two raised counts reads no clock")).unwrap(); + w.set(3, 0, || 16).unwrap(); + assert_eq!(w.take(), (0, 6)); + } + + #[test] + fn a_start_counts_from_how_the_cpu_stands() { + let w = Windows::new(); + w.start(1, 5); + w.unmasking(|| 9).unwrap(); + w.lowering(1, || 12).unwrap(); + assert_eq!(w.take(), (4, 7)); + } + + #[test] + fn every_transition_nothing_reported_before_is_named() { + let w = open_at(1); + assert_eq!(w.unmasking(|| 2), Err(Unseen::AMask)); + w.masked(|| 3).unwrap(); + assert_eq!(w.masked(|| 4), Err(Unseen::AnUnmask)); + + let w = open_at(1); + assert_eq!(w.lowering(1, || 2), Err(Unseen::ARaise)); + assert_eq!(w.scheduled(|| 2), Err(Unseen::ARaise)); + assert_eq!(w.halting(|| 2), Err(Unseen::ARaise)); + assert_eq!(w.set(1, 0, || 2), Err(Unseen::ARaise)); + w.raised(1, || 3).unwrap(); + assert_eq!(w.raised(1, || 4), Err(Unseen::ALowering)); + assert_eq!(w.woken(|| 4), Err(Unseen::ALowering)); + assert_eq!(w.set(0, 1, || 4), Err(Unseen::ALowering)); + } + + #[test] + fn an_untracked_cpu_records_and_refuses_nothing() { + let w = Windows::new(); + w.masked(|| 1).unwrap(); + w.masked(|| 2).unwrap(); + w.unmasking(|| 3).unwrap(); + w.raised(1, || 4).unwrap(); + w.lowering(1, || 5).unwrap(); + w.lowering(1, || 6).unwrap(); + w.scheduled(|| 7).unwrap(); + assert_eq!(w.take(), (0, 0)); + + let w = open_at(1); + w.masked(|| 2).unwrap(); + w.stop(); + w.masked(|| 3).unwrap(); + assert_eq!(w.take(), (0, 0), "a stopped CPU is untracked again"); + } +}