issues: the T14's 8 to 11 ms window is the xHCI spin's log write, and its firmware interrupts every CPU every 2.2 s under ToyOS

issues/hardware/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md

@@ -0,0 +1,85 @@
+---
+status: open
+kind: defect
+opened: 2026-10-03
+---
+
+# The T14's firmware interrupts every CPU every 2.2 s under ToyOS
+
+On LENOVO 20W0003AMZ, BIOS N34ET71W (1.71), one boot of `main` at `c59e09ed6`
+with a throwaway instrument that reads `MSR_SMI_COUNT` (MSR 0x34) on each CPU
+as each interrupts-off window opens and closes read the count from 1.20 s to
+38.79 s into the boot, `test_rs_ring_park_herd` running forty times in it. Its
+lines are quoted on #681 (comment 5962619169; the boot itself in comment
+5962618149).
+
+- **It moved 17 times, from 4824 to 4841, on all eight CPUs alike**: at each of
+  the boot's 42 reports the eight read the same value.
+- **About every 2.2 s.** Fifteen of the steps fall inside a window the
+  instrument printed, and the windows that caught consecutive steps close
+  2,215,327,897 to 2,221,576,672 ns apart, median 2,216,534,952.
+- **Each step stops every CPU for about 4.5 ms.** The 25 interrupts-off
+  windows a step falls in read 4,529,514 to 4,764,935 ns: sixteen open in a
+  job's syscall or interrupt, thirteen of them `SYS_SYSINFO`, and nine in a
+  pass leaving idle. None of those sections reads 2 ms where no step falls. At
+  9.925 s all eight CPUs carry one at once. That the CPU stops is shown by two
+  CPUs waiting on a lock across a step, which went 4,503,694 and 4,554,675 ns
+  between two turns of their own spin.
+- **Linux, in one condition, read none.** On the same machine under Ubuntu's
+  `6.8.0-142-generic`, `perf stat -a -A -e msr/smi/` read 0 on every CPU over
+  120.378 s beside `rtla timerlat top -q -d 2m --dma-latency 0`, which holds
+  every CPU's C-states shallow and runs a 1 kHz timer on each. Linux idle has
+  not been read.
+
+What differs, as far as anything has read:
+
+- ToyOS performs no ACPI enable handshake: `rg -n -i
+  'smi_cmd|acpi_enable|sci_en|smi_en|0xb2\b' kernel/src bootloader/src` finds
+  only the xHCI legacy handoff's own `USBLEGCTLSTS` enables
+  (`kernel/src/drivers/xhci/legacy.rs`), and nothing reads `PM1a_CNT.SCI_EN`
+  or the chipset's `SMI_EN`. Both controllers' `USBLEGCTLSTS` read
+  `0xe0000000`, no enable set, before the handoff wrote it.
+- Under that Linux, read as root from `/sys/firmware/acpi/tables/FACP` and
+  `/dev/port` with nothing written (comment 5962768253): the FADT's
+  `SMI_CMD=0xb2` and `ACPI_ENABLE=0xf0`; `PM1a_CNT` (port 0x1804) `0x0001`,
+  `SCI_EN` set; `SMI_EN` (port 0x1830) `0x10002033`, bits 0 (`GBL_SMI_EN`), 1
+  (`EOS`), 4 (`SLP_SMI_EN`), 5 (`APMC_EN`), 13 (`TCO_EN`) and 28.
+
+**The cause, measured, is the firmware's legacy mode.** A scout on `main` at
+`73282fa93` (comment 5966817345) booted the T14 twice, each boot 30 s idle and
+then 30 s with a spinning thread on every CPU:
+
+- With nothing written, `PM1a_CNT` read `0x0000`, `SCI_EN` clear, from 0.156 s
+  to 61.226 s, and `SMI_EN` read `0x10002033`, Linux's value. The count rose
+  by 14 in the idle 30 s and 13 in the busy 30 s, on every CPU alike.
+- With `ACPI_ENABLE` written to `SMI_CMD` at 0.156 s, `SCI_EN` read set
+  2,129,279 ns later. The write moved the writing CPU's count from 4817 to
+  4818, and every CPU then read 4818 at every report through 61.233 s. The
+  SCI's line, GSI 9, stayed masked: nothing in ToyOS handles an SCI. Two GPEs
+  moved after the switch, in that boot's `kernel.log` lines quoted in comment
+  5966982752 (the patch, comment 5966982939, prints each GPE register byte by
+  byte, lowest address first):
+  - the firmware's enable set GPE 9's enable bit: `gpe0_en` byte 1 reads `00`
+    at line 121, before the write, and `02` at line 123, after it;
+  - GPE 110's status rose after the switch and stayed set, served by nothing:
+    `gpe0_sts` byte 13 reads `00` at line 123 and `40` at every report from
+    line 298 through line 759. The boot with nothing written shows it in none
+    of its 25 reports (comment 5966982609).
+
+The `mask-windows` kernel prints such a window as its CPU's own: cpu4's
+4,720,498 ns in the sixth of #649's `mask_windows` boots at `72f16e39a`, and cpu0's 4,725,822 in `649-r6/3-idle-halt-counted`
+(`issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md`),
+are this by reading, those kernels not reading the count.
+
+**Owner**: the fix is stage 1 of
+`issues/kernel/toyos-runs-the-machine-in-acpi-mode-and-interprets-its-aml.md`.
+The T14 loop (`issues/hardware/the-t14-boots-toyos-unattended.md`) owns only
+the reading: its jobs are the measurements owed on hardware, and it builds the
+row.
+
+**Exit**: a T14 row reads `MSR_SMI_COUNT` on every CPU after init is spawned
+and after the boot's last write to `SMI_CMD`, whoever makes it, and again at
+the stop's report at least 4.444 s later, two of the longest period read, and
+on every CPU the two agree. The interval opens after that write because the
+ACPI enable is one, a write of `ACPI_ENABLE` to `SMI_CMD`, and raises one
+firmware interrupt where `APMC_EN` is set.

issues/hardware/xhci-waits-are-spins.md

@@ -4,44 +4,108 @@ kind: defect
 opened: 2026-08-03
 ---
 
-# The xHCI driver's waits are spins with preemption disabled, wherever they run
-
-`bdf2596` moved the *boundary* — an input read no longer drives the driver — so
-the only thread that runs enumeration and recovery now is the one inside
-`drain_irqs`. That fixes who pays; it does not change what is paid.
-
-Every wait in this driver is a spin against a wall-clock deadline, taken while
-holding `XHCI`, which is a ticket spinlock and therefore preemption off for its
-whole life:
-
-- `settles()` — controller halt, HCRST, CNR, R/S, and the port reset. Bound
-  `USB_TIMEOUT_NS`, 2 s.
-- `wait_command()` and `wait_transfer()` — every command and every transfer.
-  Same bound.
-
-**The port machine took the two that ran inside a scheduler pass out of that
-list.** A teardown's Disable Slot and an endpoint recovery's three-in-a-row
-(Reset or Stop Endpoint, Set TR Dequeue, CLEAR_FEATURE(HALT)) are
-submit-and-return now, so the six seconds above are reachable only from the boot
-path and from `storage_read`/`storage_write` — the first has no scheduler to
-give a pass back to, and the second is the case named below that this conversion
-does not fix.
-
-So a worst case is a CPU that does not reschedule for **six seconds**, and an
-ordinary hot-plug enumeration on the T14 is ~14 ms of it (`hotplug-blocks-a-scheduler-pass`).
-Nothing in the suite can measure the bad case: QEMU answers every one of these
-in microseconds, which is why a driver built entirely out of them passed
-everything here for a season.
-
-**The hot-plug half of that conversion has landed**: enumeration is
-`device::begin`/`stepped`, submit-and-return, driven by the port machine — so
-no runtime path blocks a scheduler pass on it any more. `restart_endpoint`'s
-half is done the same way: the route is `toyos_xhci::recovery`'s, driven twice
-— a blocking loop for a disk's bulk pair, which runs on the thread that
-faulted, and a stepped one for HID.
-
-One case is *not* fixed by that and needs its own answer: `storage_read` and
-`storage_write` are called by the page cache on a faulting thread, so a thread
-touching a file on a USB disk drives a SCSI command under the same lock. The
-input poll was gratuitous and could simply be deleted; this one is inherent, and
-the choice is between an I/O thread and making the block layer asynchronous.
+# The xHCI driver's waits are spins, and a USB disk call spins with interrupts masked
+
+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
+so preemption off for its whole life: `settles()` for the controller's halt,
+reset and port reset, and `wait_command()` and `wait_transfer()` for every
+command and transfer, each bounded by `USB_TIMEOUT_NS`, 2 s. The port
+machine's enumeration and HID recovery submit and return; what still spins is
+the boot path's bring-up, the stop, a disk's bind after boot, inside a
+scheduler pass
+(`issues/hardware/a-disk-plugged-in-after-boot-is-bound-inside-a-scheduling-pass.md`),
+and a disk call.
+
+A call on a USB disk holds `XHCI` from its first command (`with_disk`,
+`kernel/src/drivers/xhci/wait/msc.rs`) inside a syscall, which runs with
+interrupts masked from entry to exit
+(`issues/kernel/syscall-preemption-is-incidental.md`): a partition claim's
+`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.
+
+**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.
+
+## On the T14
+
+On LENOVO 20W0003AMZ, BIOS N34ET71W (1.71), `/log` is a FAT32 partition of the
+USB stick the machine boots from, which `/system/bin/fsd` in the LOG role
+writes with `SYS_PARTITION_WRITE`. One boot of `main` at `c59e09ed6` with a
+throwaway instrument that records every window of 2 ms or more with the
+addresses that opened and closed it, its CPU's last events, and samples of
+that CPU every 2 ms ran `test_rs_ring_park_herd` forty times. Its lines are
+quoted on #681 (comments 5962618149, 5962618492 and 5962618868). Pid 4 is that
+fsd.
+
+- **Eleven writes of 7.8 ms or more in 37 s**, 2.0 to 4.6 s apart, each window
+  opened at the syscall's entry and closed at its return. Nine are on one CPU
+  alone: 8,289,211 to 10,669,042 ns. 36 of their 37 samples are in
+  `wait_transfer < bulk < bot < scsi < transfer_blocks` under `storage_write`;
+  the 37th is the same syscall waiting for the process table's lock.
+- **All eight CPUs at once, twice**, at 17.416 s and 21.116 s: the write on one
+  CPU (7,848,573 and 7,927,725 ns) while a herd thread on each of the other
+  seven is in `SYS_THREAD_EXIT`, whose unmap shoots down every CPU's TLB. The
+  fourteen shootdowns span 7,703,612 to 7,852,515 ns, and their initiators
+  spin: none goes more than 10,819 ns between two turns of its wait. The other
+  targets acknowledge within 24 µs; the writing CPU acknowledges by interrupt
+  once its syscall has returned, 130 to 264 ns before each shootdown ends. Each
+  event is followed at once by a shorter one of the same shape: the next
+  write, 2,824,878 and 2,846,782 ns, and fourteen more shootdowns. The
+  report's `tlb:` line reads `max=7846us` after the first, where it read
+  `max=1146us` before it.
+- **Shorter**: sixteen of the same server's writes read 2,368,371 to
+  2,905,716 ns, those two among them, and two of its `SYS_PARTITION_READ`
+  2,596,003 and 2,954,780. At the stop, the black box keeps a write opened at
+  38.795 s whose CPU's next event comes 7,953,409 ns later.
+- **init's partition claims**: on cpu0, 6,002,063 ns at 1.171 s and
+  6,623,907 ns at 1.179 s, each `SYS_DEVICE_CLAIM` from entry to return, all
+  four samples in `wait_transfer` under `storage_read`.
+- **Its `SYS_FSYNC`**: 15 windows' trails carry one, and in 7 it spins on a
+  contended `XHCI` at `with_disk_by` (comment 5966523482). None held
+  interrupts off for 2 ms.
+- **Not the firmware**: `MSR_SMI_COUNT` does not move across any of them. The
+  windows it does move across are
+  `issues/hardware/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md`'s.
+
+The `mask-windows` kernel (`kernel/src/windows.rs`) prints a span and no
+opener, and #649's T14 boots printed these by reading:
+
+- cpu0's line before the first job's exit, init's partition claims:
+  6,540,326 to 6,590,095 ns in seven of the eight `mask_windows` boots at
+  `72f16e39a`, and 6,533,222, 2 × 3,273,547 and 6,508,165 in the first report
+  of the three at `8b73eba69` (comment 5959415453).
+- Every CPU at once: 9,603,617 to 9,651,846 ns beside `tlb: … max=9575us`, the
+  fourth boot at `72f16e39a`; 2 × 5,014,552 to 2 × 5,075,290 beside
+  `max=10038us`, `649-r6/2-report-halved` (comment 5960575031).
+- One CPU alone: 9,260,193, the seventh boot at `72f16e39a`; cpu7, where pid 4
+  started, at 11,492,028 and 8,456,658 before the first job's exit
+  (`649-r6/1-head`, `649-r6/3-idle-halt-counted`).
+- The stop's report: one CPU at 10,214,820 to 11,267,384 in four boots at
+  `72f16e39a`, and two in `649-r5/1-head`, cpu7 at 11,522,834 and cpu4 at
+  11,645,411 (`loader.log:57`, `:63`).
+
+**Owner**: `issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md`,
+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 spin's**: the tree has no `kernel/src/drivers/xhci`, so no kernel wait
+  is a USB device's. Step 10 meets both.

issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.md

@@ -57,13 +57,15 @@ mutated kernels) read the same report of the same load at 1980239
   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.
+  (`:431`). It is a log write's all-CPU shape
+  (`issues/hardware/xhci-waits-are-spins.md`) by reading.
+- 4725822 is cpu0's, a firmware step's length by reading
+  (`issues/hardware/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md`).
+  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
+So one size reads 1.03 to 1.98 ms in the four of those reports none of the
+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).
 
 **Exit**: the interrupts-off window step 2's instrument reads on the T14

issues/kernel/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md

@@ -29,8 +29,8 @@ accord is logd's network thread, on a boot that gives logd no netd; the logd
 branch no longer starts that thread there, which would remove this boot's
 trigger and not the deaf CPU.
 
-`a-disk-operation-can-spin-past-the-tlb-ack-tripwire-before-its-break.md` is
-the arithmetic for one disk operation outrunning `time::DEAF_CPU`; this is a boot
+`issues/hardware/xhci-waits-are-spins.md` carries the arithmetic for one disk
+operation outrunning `time::DEAF_CPU`; this is a boot
 that did outrun it, in `quiesce`, across several operations each inside its
 own budget. Whether `quiesce` holds `IF` clear between them is not measured.