Repository navigation
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 - #681
Conversation
…are interrupts every CPU every 2.2 s One T14 boot of main at c59e09e with a throwaway instrument (never landed; scout.patch sha256 f5a0208c…ac458a) named what opens every interrupts-off window of 2 ms or more, sampled the CPU holding it, traced each shootdown's acknowledgements and read MSR_SMI_COUNT on every CPU. It ran test_rs_ring_park_herd forty times. Its lines are quoted on the pull request; the scratch readback does not outlive the session. - some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more is renamed to what the boot shows and rewritten as present state: the LOG fsd's SYS_PARTITION_WRITE spins in XhciController::wait_transfer with interrupts masked for the whole USB transfer, 8.3 to 10.7 ms on one CPU nine times, and twice while seven herd threads in SYS_THREAD_EXIT spin masked on its shootdown acknowledgement, 7.7 to 7.85 ms. The old title's "some boots" was a sampling artefact of one herd run per boot: the write recurs every 2.0 to 4.6 s. Owners: the small-kernel track and syscall-preemption-is-incidental. The opened date stays, as renames do. - cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14 has its opener: init in SYS_DEVICE_CLAIM, two partition claims reading the stick's table through the same wait and one PCI claim whose single sample is in PciDevice::is_id. The exit's naming half is met and goes. - New: the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos-and- not-under-linux. MSR_SMI_COUNT went 4824 to 4841 on all eight CPUs, each step about 4.5 ms on every CPU; under Linux perf read 0 in 120 s. The cause is not known. - a-process-lengthens-an-interrupts-off-walk…: its citation follows the rename. the-cpu-that-spawns-a-toybox-applet… is unchanged: the instrument printed only windows of 2 ms or more, so this boot says nothing new about it. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
Evidence 2 of 4: all eight CPUs at once, 17.416 s. Every window below opens at The shootdown counter, in the report before and the report afterThe sixteen windows: cpu4 is pid 4 in
|
|
Evidence 3 of 4: all eight CPUs at once, 21.116 s. Every window below opens at The shootdown counter, in the report before and the report afterThe sixteen windows: cpu1 is pid 4 in
|
|
Evidence 4 of 4: the firmware's interrupt. The boot and the instrument's guide are in evidence 1. Cited by
|
| count | windows | latest close=, ns |
since the one before, ns |
|---|---|---|---|
| 4825 | 1 | 3281577599 | |
| 4826 | 1 | 5497184164 | 2215606565 |
| 4827 | 1 | 7713328706 | 2216144542 |
| 4828 | 8 | 9929880191 | 2216551485 |
| 4829 | 1 | 12151456863 | 2221576672 |
| 4830 | 3 | 14368004296 | 2216547433 |
| 4831 | 0 | ||
| 4832 | 1 | 18798762258 | 4430757962 over 2 steps |
| 4833 | 1 | 21018245462 | 2219483204 |
| 4834 | 1 | 23234782472 | 2216537010 |
| 4835 | 1 | 25450110369 | 2215327897 |
| 4836 | 1 | 27665660867 | 2215550498 |
| 4837 | 0 | ||
| 4838 | 1 | 32128591020 | 4462930153 over 2 steps |
| 4839 | 1 | 34345123915 | 2216532895 |
| 4840 | 2 | 36560657093 | 2215533178 |
| 4841 | 1 | 38781275190 | 2220618097 |
Twelve single steps: 2,215,327,897 to 2,221,576,672 ns, median 2,216,534,952. From the first caught to the last, 35,499,697,591 ns over 16 steps.
Linux on the same machine
linuxcmp/smi.sh ran perf stat -a -A -e msr/smi/ -o $f -- rtla timerlat top -q -d 2m --dma-latency 0 as root on the T14's Ubuntu; linuxcmp/linux-smi.log, whole but for the terminal's colour codes:
aperf
cpu_thermal_margin
cpu_thermal_margin.snapshot
cpu_thermal_margin.unit
mperf
pperf
smi
tsc
Timer Latency
0 00:02:00 | IRQ Timer Latency (us) | Thread Timer Latency (us)
CPU COUNT | cur min avg max | cur min avg max
0 #120000 | 0 0 0 4 | 2 1 2 25
1 #120000 | 0 0 0 53 | 2 1 2 592
2 #120000 | 0 0 0 4 | 2 1 2 12
3 #120000 | 0 0 0 35 | 2 1 2 40
4 #120000 | 0 0 0 13 | 2 1 2 15
5 #120000 | 0 0 0 39 | 2 1 2 91
6 #120000 | 0 0 0 19 | 2 1 2 23
7 #120000 | 0 0 0 19 | 2 1 2 49
# started on Fri Oct 2 21:30:16 2026
Performance counter stats for 'system wide':
CPU0 0 msr/smi/
CPU1 0 msr/smi/
CPU2 0 msr/smi/
CPU3 0 msr/smi/
CPU4 0 msr/smi/
CPU5 0 msr/smi/
CPU6 0 msr/smi/
CPU7 0 msr/smi/
120.378123249 seconds time elapsed
done
That Linux, from linuxcmp/linux-t14.log, whose script runs uname -r; nproc; grep -m1 "model name" /proc/cpuinfo; cat /sys/kernel/debug/sched/preempt first:
6.8.0-142-generic
8
model name : 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
none (voluntary) full
What the tree does about the firmware's interrupts
At a93067fc2:
$ rg -n -i 'smi_cmd|acpi_enable|sci_en|smi_en|0xb2\b' kernel/src bootloader/src
kernel/src/drivers/xhci/legacy.rs:22:const SMI_ENABLES: u32 = (1 << 0) | (1 << 4) | (1 << 13) | (1 << 14) | (1 << 15);
kernel/src/drivers/xhci/legacy.rs:157: bar.write_u32(legsup + LEGCTLSTS, (ctl & !SMI_ENABLES) | SMI_STATUS);
EXIT=0
$ git grep -n -i -E 'smi_cmd|acpi_enable|sci_en|smi_en\b|SMI_EN[^A-Z]' HEAD -- . ':!issues' ':!rust'
HEAD:tests/common/power.rs:123:/// set through every write this tree makes, and what it gates is `SMI_EN.TCO_EN`
HEAD:toyos-tco/src/lib.rs:59:/// gates is `SMI_EN.TCO_EN` — not the countdown and not the reboot.
EXIT=0
$ rg -n 'inw|inl|inb' kernel/src/arch/x86_64/power.rs
EXIT=1
The first search's two hits are the xHCI legacy handoff's own enables in USBLEGCTLSTS (SMI_ENABLES matches smi_en); the second's two are doc comments about the TCO watchdog; the third finds no port read in the module that writes PM1a_CNT for soft-off. Nothing writes SMI_CMD, and nothing reads PM1a_CNT.SCI_EN or the chipset's SMI_EN. The handoff, in this boot:
16: [2026-10-02 22:16:13 0.000 cpu0 boot] ACPI: FACP at 0x90ca0000 len=276 rev=6 oem="LENOVO" checksummed
28: [2026-10-02 22:16:13 0.000 cpu0] ACPI: PM1a=0x1804 SLP_TYPa=7
167: [2026-10-02 22:16:13 0.250 cpu0] xHCI: firmware did not claim the controller (USBLEGSUP 0x01002201)
168: [2026-10-02 22:16:13 0.250 cpu0] xHCI: USBLEGCTLSTS 0xe0000000 -> 0x00000000 (SMI generation off)
187: [2026-10-02 22:16:13 0.250 cpu0] xHCI: firmware did not claim the controller (USBLEGSUP 0x01002201)
188: [2026-10-02 22:16:13 0.250 cpu0] xHCI: USBLEGCTLSTS 0xe0000000 -> 0x00000000 (SMI generation off)
Reported, with no output kept
The orchestrator reports from that Linux: the FADT's SMI_CMD=0xb2 and ACPI_ENABLE=0xf0, PM1a_CNT.SCI_EN=1, and SMI_EN=0x10002033. No file under the session's scratch directory carries the output of those reads: grep -rIl 10002033 over it finds the orchestrator's own notes and nothing else. They are quoted here as reported, not as read.
The three files that rest on the scout boot now name the comments its lines are quoted in: 5962618149 (the boot, its control, the storage windows), 5962618492 and 5962618868 (the two all-CPU events) and 5962619169 (the firmware's interrupt). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
The scout patch, part 1 of 2. The throwaway instrument the evidence comments read (never landed): diff --git a/kernel/src/arch/x86_64/hw.rs b/kernel/src/arch/x86_64/hw.rs
index 50ed0a049..5e9266dbb 100644
--- a/kernel/src/arch/x86_64/hw.rs
+++ b/kernel/src/arch/x86_64/hw.rs
@@ -303,6 +303,8 @@ impl Hw for KernelHw {
crate::preempt::set_count(incoming.preempt);
percpu::set_current_tid(incoming.id.map(|id| id.1));
percpu::set_current_pid(incoming.id.map(|id| id.0));
+ #[cfg(feature = "mask-windows")]
+ crate::windows::note_switch();
match incoming.id {
Some(_) => {
percpu::set_kernel_stack(incoming.kernel_stack_top);
diff --git a/kernel/src/arch/x86_64/idt/mod.rs b/kernel/src/arch/x86_64/idt/mod.rs
index c7f63b304..a5a7702b1 100644
--- a/kernel/src/arch/x86_64/idt/mod.rs
+++ b/kernel/src/arch/x86_64/idt/mod.rs
@@ -391,6 +391,7 @@ fn windows_entered(frame: &TrapFrame) {
}
crate::windows::irqs_masked();
crate::windows::preempt_raised();
+ crate::windows::note_trap(frame.vector, frame.rip);
}
/// 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/nmi.rs b/kernel/src/arch/x86_64/idt/nmi.rs
index a9a8ab28e..3ce7c177a 100644
--- a/kernel/src/arch/x86_64/idt/nmi.rs
+++ b/kernel/src/arch/x86_64/idt/nmi.rs
@@ -49,6 +49,9 @@ pub(super) extern "sysv64" fn nmi_entry() {
"mov rdi, [rsp + {rip_offset}]",
"mov rsi, [rsp + {rsp_offset}]",
"mov rdx, [rsp + {rflags_offset}]",
+ // SCOUT: the interrupted `rbp`, pushed last, and the frame's `cs`.
+ "mov rcx, [rsp]",
+ "mov r8, [rsp + {cs_offset}]",
"mov rbp, rsp",
"and rsp, -16",
"call {note}",
@@ -78,6 +81,7 @@ pub(super) extern "sysv64" fn nmi_entry() {
rip_offset = const RIP_OFFSET,
rsp_offset = const RSP_OFFSET,
rflags_offset = const RFLAGS_OFFSET,
+ cs_offset = const RIP_OFFSET + 8,
nested_rip = const NESTED_RIP_OFFSET,
nested_rsp = const NESTED_RSP_OFFSET,
note = sym note,
@@ -85,9 +89,13 @@ pub(super) extern "sysv64" fn nmi_entry() {
);
}
-extern "sysv64" fn note(rip: u64, rsp: u64, rflags: u64) {
+extern "sysv64" fn note(rip: u64, rsp: u64, rflags: u64, rbp: u64, cs: u64) {
crate::arch::percpu::irq_took!(Nmi);
crate::sched::dump::note_nmi(rip);
+ #[cfg(feature = "mask-windows")]
+ crate::windows::nmi(rip, rflags, cs, rbp);
+ #[cfg(not(feature = "mask-windows"))]
+ let _ = (rbp, cs);
// After the probe's store and before the nested-NMI staging: a hard lockup
// ends the machine from here, so the sibling asking where this CPU is still
// gets its answer, and nothing stages a second NMI onto a frame that is
diff --git a/kernel/src/arch/x86_64/idt/timer.rs b/kernel/src/arch/x86_64/idt/timer.rs
index 1ce8cb24f..fc25e44e1 100644
--- a/kernel/src/arch/x86_64/idt/timer.rs
+++ b/kernel/src/arch/x86_64/idt/timer.rs
@@ -97,6 +97,7 @@ pub(super) extern "sysv64" fn timer_entry() {
#[cfg(feature = "mask-windows")]
extern "sysv64" fn ring0_tick() {
crate::windows::irqs_masked();
+ crate::windows::note_irq(crate::irq_census::Source::Timer);
crate::deadline::poll();
crate::windows::irqs_unmasking();
}
diff --git a/kernel/src/arch/x86_64/percpu.rs b/kernel/src/arch/x86_64/percpu.rs
index 3cd57d6dd..e11be54ef 100644
--- a/kernel/src/arch/x86_64/percpu.rs
+++ b/kernel/src/arch/x86_64/percpu.rs
@@ -550,6 +550,11 @@ pub unsafe fn set_kernel_stack(rsp: u64) {
core::ptr::write_unaligned(&raw mut (*percpu).tss.rsp0, rsp);
}
+/// SCOUT: the top of the kernel stack [`set_kernel_stack`] last named.
+pub fn kernel_stack_top() -> u64 {
+ gs::read_u64::<OFF_KERNEL_RSP>()
+}
+
/// The two words [`set_kernel_stack`] writes: `kernel_rsp` (syscall entry) and `tss.rsp0` (Ring 3 interrupt entry); read only by an instrument.
/// # Safety: must be called from the CPU whose GS base points to the relevant PerCpu.
#[cfg(feature = "stack-witness")]
@@ -715,6 +720,8 @@ macro_rules! irq_took {
options(nostack),
);
}
+ #[cfg(feature = "mask-windows")]
+ $crate::windows::note_irq($crate::irq_census::Source::$source);
}};
}
diff --git a/kernel/src/arch/x86_64/syscall.rs b/kernel/src/arch/x86_64/syscall.rs
index e48bd3f50..7aabce32a 100644
--- a/kernel/src/arch/x86_64/syscall.rs
+++ b/kernel/src/arch/x86_64/syscall.rs
@@ -106,6 +106,7 @@ extern "sysv64" fn syscall_handler(num: u64, a1: u64, a2: u64, _: u64, a3: u64,
{
crate::windows::irqs_masked();
crate::windows::preempt_raised();
+ crate::windows::note_syscall(num);
}
#[cfg(feature = "df-witness")]
cpu::df_witness("syscall_handler");
diff --git a/kernel/src/arch/x86_64/tlb.rs b/kernel/src/arch/x86_64/tlb.rs
index a6565cd2f..01fb6e987 100644
--- a/kernel/src/arch/x86_64/tlb.rs
+++ b/kernel/src/arch/x86_64/tlb.rs
@@ -75,14 +75,26 @@ pub fn shootdown(origin: Origin) {
let began = crate::clock::nanos_since_boot();
let me = percpu::cpu_id() as usize;
let generation = SHOOTDOWN.issue();
+ #[cfg(feature = "mask-windows")]
+ let mut scout = crate::windows::Shoot::begin(me, generation.raw(), origin as u64);
// This CPU answers itself locally instead of by self-IPI.
SHOOTDOWN.serve(me, crate::mm::paging::flush_tlb_all);
+ #[cfg(feature = "mask-windows")]
+ crate::windows::served(crate::windows::VIA_OWN, SHOOTDOWN.flushed(me));
apic::tlb_ipi();
for cpu in 0..cpus {
if cpu as usize != me {
+ #[cfg(not(feature = "mask-windows"))]
wait_for(me, cpu, generation);
+ #[cfg(feature = "mask-windows")]
+ {
+ wait_for(me, cpu, generation, &mut scout);
+ scout.seen(cpu as usize);
+ }
}
}
+ #[cfg(feature = "mask-windows")]
+ scout.end(cpus);
let took = crate::clock::nanos_since_boot().saturating_sub(began);
WAIT_NS.fetch_add(took, Ordering::Relaxed);
MAX_NS.fetch_max(took, Ordering::Relaxed);
@@ -125,10 +137,20 @@ pub fn bench() {
/// Never logs: `drivers::serial`'s lock under its `IrqGuard` would deadlock a
/// target that cannot answer while blocked on it.
-fn wait_for(me: usize, cpu: u32, generation: Generation) {
+fn wait_for(
+ me: usize,
+ cpu: u32,
+ generation: Generation,
+ #[cfg(feature = "mask-windows")] scout: &mut crate::windows::Shoot,
+) {
let mut spins = 0u32;
let mut deadline = None;
while !SHOOTDOWN.wait_turn(me, cpu as usize, generation, crate::mm::paging::flush_tlb_all) {
+ #[cfg(feature = "mask-windows")]
+ {
+ crate::windows::served(crate::windows::VIA_WAIT, SHOOTDOWN.flushed(me));
+ scout.turn(cpu as usize);
+ }
core::hint::spin_loop();
spins += 1;
if spins == SPINS_PER_DEADLINE_CHECK {
@@ -154,6 +176,8 @@ pub fn serve_ipi() {
crate::mm::paging::flush_tlb_all();
stage_ack_delay();
});
+ #[cfg(feature = "mask-windows")]
+ crate::windows::served(crate::windows::VIA_IPI, SHOOTDOWN.flushed(cpu));
}
/// Answers a pending shootdown without taking a lock or allocating, so it is
@@ -168,6 +192,8 @@ pub fn poll() {
crate::mm::paging::flush_tlb_all();
stage_ack_delay();
});
+ #[cfg(feature = "mask-windows")]
+ crate::windows::served(crate::windows::VIA_POLL, SHOOTDOWN.flushed(cpu));
}
/// Settle every shootdown issued before this CPU could answer one; called
@@ -175,6 +201,8 @@ pub fn poll() {
pub fn join() {
let cpu = percpu::cpu_id() as usize;
SHOOTDOWN.serve(cpu, crate::mm::paging::flush_tlb_all);
+ #[cfg(feature = "mask-windows")]
+ crate::windows::served(crate::windows::VIA_JOIN, SHOOTDOWN.flushed(cpu));
}
#[cfg(not(feature = "test-actuators"))]
diff --git a/kernel/src/clock.rs b/kernel/src/clock.rs
index ee7795c7d..94c26bb2d 100644
--- a/kernel/src/clock.rs
+++ b/kernel/src/clock.rs
@@ -80,6 +80,11 @@ pub fn nanos_since_boot() -> u64 {
((delta as u128 * period_fs as u128) / 1_000_000) as u64
}
+/// SCOUT: a counter reading as nanoseconds since boot, the log's own clock.
+pub fn nanos_at(counter: u64) -> u64 {
+ nanos_of_ticks(counter.saturating_sub(TSC_BOOT.load(Relaxed)))
+}
+
/// The same reading as an [`Instant`], the type arithmetic on it is allowed in.
/// The one bridge between hardware and `crate::time`, which stays `core`-only for `kernel-loom`.
pub fn now() -> Instant {
diff --git a/kernel/src/hardlockup/mod.rs b/kernel/src/hardlockup/mod.rs
index 3b2e518d8..44b5534d7 100644
--- a/kernel/src/hardlockup/mod.rs
+++ b/kernel/src/hardlockup/mod.rs
@@ -75,7 +75,9 @@ pub const LOCKED_UP: &str = "a cpu locked up with interrupts off";
/// Declared beside the bound it samples, so the host judging a lockup's
/// lateness reads the same period.
-const SAMPLE_NS: u64 = toyos_tco::HARD_LOCKUP_SAMPLE_NS;
+// SCOUT: a sample every millisecond a CPU runs, where the detector takes one a second.
+const SAMPLE_NS: u64 =
+ if cfg!(feature = "mask-windows") { 1_000_000 } else { toyos_tco::HARD_LOCKUP_SAMPLE_NS };
/// The bound in TSC ticks, or 0 for a boot that armed none. Written on the BSP
/// before any AP exists.
diff --git a/kernel/src/irq_census.rs b/kernel/src/irq_census.rs
index be637d91d..d371786e1 100644
--- a/kernel/src/irq_census.rs
+++ b/kernel/src/irq_census.rs
@@ -146,4 +146,6 @@ pub fn log_census() {
#[cfg(feature = "mask-windows")]
crate::windows::log_cpu(cpu);
}
+ #[cfg(feature = "mask-windows")]
+ crate::windows::log_scout();
}
diff --git a/kernel/src/shootdown.rs b/kernel/src/shootdown.rs
index 6c453a99c..6fd8cd779 100644
--- a/kernel/src/shootdown.rs
+++ b/kernel/src/shootdown.rs
@@ -22,6 +22,13 @@ const OWED: Ordering = Ordering::Relaxed;
#[derive(Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Debug)]
pub struct Generation(u64);
+impl Generation {
+ /// SCOUT: the generation's number.
+ pub fn raw(self) -> u64 {
+ self.0
+ }
+}
+
pub struct Shootdown {
requested: AtomicU64,
flushed: [AtomicU64; MAX_CPUS],
@@ -62,6 +69,11 @@ impl Shootdown {
self.flushed[cpu].fetch_max(owed, Ordering::Release);
}
+ /// SCOUT: the newest generation `cpu` has published a flush for.
+ pub fn flushed(&self, cpu: usize) -> u64 {
+ self.flushed[cpu].load(Ordering::Relaxed)
+ }
+
/// Does `cpu` owe anyone a flush?
pub fn owes(&self, cpu: usize) -> bool {
// A hint: `serve` carries the real ordering, so a stale `false` costs nothing.
diff --git a/kernel/src/sync.rs b/kernel/src/sync.rs
index bfa85e8e8..b4d586f09 100644
--- a/kernel/src/sync.rs
+++ b/kernel/src/sync.rs
@@ -4,6 +4,8 @@ use core::ops::{Deref, DerefMut};
use core::cell::UnsafeCell;
#[cfg(not(feature = "loom"))]
use core::sync::atomic::{AtomicU32, Ordering};
+#[cfg(feature = "mask-windows")]
+use core::sync::atomic::AtomicU64;
#[cfg(feature = "loom")]
use crate::cell::UnsafeCell;
@@ -77,6 +79,11 @@ impl AtomicTicket {
pub struct Lock<T> {
ticket: AtomicTicket,
now: AtomicTicket,
+ /// SCOUT: the CPU that holds this, plus one, and the site it took it at.
+ #[cfg(feature = "mask-windows")]
+ held_cpu: AtomicU32,
+ #[cfg(feature = "mask-windows")]
+ held_at: AtomicU64,
data: UnsafeCell<T>,
}
@@ -92,6 +99,10 @@ impl<T> Lock<T> {
Self {
ticket: AtomicTicket::new(Ticket::ZERO),
now: AtomicTicket::new(Ticket::ZERO),
+ #[cfg(feature = "mask-windows")]
+ held_cpu: AtomicU32::new(0),
+ #[cfg(feature = "mask-windows")]
+ held_at: AtomicU64::new(0),
data: UnsafeCell::new(val),
}
}
@@ -126,7 +137,11 @@ impl<T> Lock<T> {
// poll inside this spin takes locks of its own, and a nested one that
// succeeded would otherwise clear the slot while this spin still waits.
let mut was = None;
+ #[cfg(feature = "mask-windows")]
+ let mut watch = crate::windows::SpinWatch::new();
while self.now.load(ACQUIRED) != my_ticket {
+ #[cfg(feature = "mask-windows")]
+ watch.turn(self.now.load(Ordering::Relaxed).raw(), &self.held_cpu, &self.held_at);
// Inside the loop, so an uncontended acquisition writes nothing:
// what a CPU is waiting for is the one thing a record sealed from
// that CPU's own NMI cannot read off its registers.
@@ -156,6 +171,12 @@ impl<T> Lock<T> {
if let Some(was) = was {
crate::hardlockup::spinning_on_nothing(was);
}
+ #[cfg(feature = "mask-windows")]
+ {
+ let caller = core::panic::Location::caller();
+ watch.end(self as *const Self as *const () as u64, caller);
+ crate::windows::holds(&self.held_cpu, &self.held_at, caller as *const _ as u64);
+ }
LockGuard { lock: self }
}
@@ -163,7 +184,11 @@ impl<T> Lock<T> {
crate::preempt::disable();
let current = self.now.load(ACQUIRED);
match self.ticket.compare_advance(current, Ordering::Relaxed, Ordering::Relaxed) {
- Ok(_) => Some(LockGuard { lock: self }),
+ Ok(_) => {
+ #[cfg(feature = "mask-windows")]
+ crate::windows::holds(&self.held_cpu, &self.held_at, 0);
+ Some(LockGuard { lock: self })
+ }
Err(_) => {
crate::preempt::enable();
None
diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs
index 2b7e5eef1..1afc2b767 100644
--- a/kernel/src/windows.rs
+++ b/kernel/src/windows.rs
@@ -26,8 +26,14 @@
//! 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;
+// SCOUT: AArch64 has none of the sites that feed the scout's records.
+#![cfg_attr(not(target_arch = "x86_64"), allow(dead_code, unused))]
+
+use core::cell::Cell;
+use core::fmt;
+use core::panic::Location;
use core::sync::atomic::Ordering::Relaxed;
+use core::sync::atomic::{AtomicBool, AtomicU32, AtomicU64};
use toyos_sched::windows::{Unseen, Windows, HELD_NS};
@@ -59,12 +65,19 @@ 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();
+ LONG.store(crate::clock::counter_ticks(LONG_NS), Relaxed);
+ NOTE.store(crate::clock::counter_ticks(NOTE_NS), Relaxed);
CPUS[percpu::cpu_id() as usize].start(crate::preempt::count(), cpu::counter());
}
/// Interrupts were open and this CPU has just masked them.
+#[inline(never)]
pub fn irqs_masked() {
- on(|w| w.masked(cpu::counter));
+ let Some(me) = here() else { return };
+ if let Err(unseen) = CPUS[me].masked(cpu::counter) {
+ refuse(unseen);
+ }
+ opened(me, IRQS, cpu::frame_pointer());
}
/// This CPU took an exception in the kernel, which ends the machine: nothing
@@ -77,38 +90,85 @@ pub fn stop_here() {
}
/// Interrupts are masked and this CPU is about to open them.
+#[inline(never)]
pub fn irqs_unmasking() {
- on(|w| w.unmasking(cpu::counter));
+ let Some(me) = here() else { return };
+ let since = CPUS[me].irqs_since();
+ let at = Cell::new(0);
+ let now = || {
+ let t = cpu::counter();
+ at.set(t);
+ t
+ };
+ if let Err(unseen) = CPUS[me].unmasking(now) {
+ refuse(unseen);
+ }
+ closed(me, IRQS, since, at.get(), cpu::frame_pointer());
+}
+
+/// A preempt transition, and the scout's look at what it opened or closed.
+#[inline(always)]
+fn preempt(fp: u64, transition: impl FnOnce(&Windows, &dyn Fn() -> u64) -> Result<(), Unseen>) {
+ let Some(me) = here() else { return };
+ let w = &CPUS[me];
+ let before = w.preempt_since();
+ let at = Cell::new(0);
+ let now = || {
+ let t = cpu::counter();
+ at.set(t);
+ t
+ };
+ if let Err(unseen) = transition(w, &now) {
+ refuse(unseen);
+ }
+ let after = w.preempt_since();
+ if after == before {
+ return;
+ }
+ if before != 0 {
+ closed(me, PREEMPT, before, at.get(), fp);
+ }
+ if after != 0 {
+ opened(me, PREEMPT, fp);
+ }
}
/// The preempt count has just been raised by one.
+#[inline(never)]
pub fn preempt_raised() {
- on(|w| w.raised(crate::preempt::count(), cpu::counter));
+ preempt(cpu::frame_pointer(), |w, now| w.raised(crate::preempt::count(), now));
}
/// The preempt count is about to be lowered by one.
+#[inline(never)]
pub fn preempt_lowering() {
- on(|w| w.lowering(crate::preempt::count(), cpu::counter));
+ preempt(cpu::frame_pointer(), |w, now| w.lowering(crate::preempt::count(), now));
}
/// The preempt count was just set from `old` to `new` whole.
+#[inline(never)]
pub fn preempt_set(old: u32, new: u32) {
- on(|w| w.set(old, new, cpu::counter));
+ preempt(cpu::frame_pointer(), |w, now| w.set(old, new, now));
}
/// A scheduler pass has decided what runs here.
+#[inline(never)]
pub fn scheduled() {
- on(|w| w.scheduled(cpu::counter));
+ preempt(cpu::frame_pointer(), |w, now| w.scheduled(now));
}
/// This CPU halts inside a pass.
+#[inline(never)]
pub fn halting() {
- on(|w| w.halting(cpu::counter));
+ note(K_HALT, 0, 0, 0);
+ preempt(cpu::frame_pointer(), |w, now| w.halting(now));
}
/// The halt has ended, still inside its pass.
+#[inline(never)]
pub fn woken() {
- on(|w| w.woken(cpu::counter));
+ preempt(cpu::frame_pointer(), |w, now| w.woken(now));
+ note(K_WAKE, 0, 0, 0);
}
/// `cpu`'s line, taking its longest windows so the next report starts from none.
@@ -138,4 +198,1025 @@ pub fn hold_once() {
ns = crate::clock::nanos_of_ticks(cpu::counter() - from);
}
crate::log!("windows: held cpu{} ns={ns}", percpu::cpu_id());
+ crate::log!(
+ "scout: armed long_ns={LONG_NS} long_ticks={} note_ns={NOTE_NS} chain={CHAIN} keep={KEEP}",
+ LONG.load(Relaxed),
+ );
+}
+
+// ---------------------------------------------------------------------------
+// SCOUT, never landing: what each CPU is doing across a long window. Every
+// fact is kept in per-CPU words and printed by `log_scout`, with the report.
+// Stamps are `cpu::counter`, printed as nanoseconds since boot, the log's clock.
+// ---------------------------------------------------------------------------
+
+/// A window or a wait longer than this is recorded.
+const LONG_NS: u64 = 2_000_000;
+/// A lock or shootdown wait shorter than this leaves no event on the trail.
+const NOTE_NS: u64 = 20_000;
+/// The two as counter ticks; zero until a CPU joins the scheduler.
+static LONG: AtomicU64 = AtomicU64::new(0);
+static NOTE: AtomicU64 = AtomicU64::new(0);
+
+const IRQS: usize = 0;
+const PREEMPT: usize = 1;
+
+/// Return addresses kept per site.
+const CHAIN: usize = 6;
+/// A trail event: at, kind, a, b, c.
+const EV: usize = 5;
+const TRAIL: usize = 64;
+/// Trail events copied into a window's record: its last `KEEP`, and the next `AFTER`.
+const KEEP: usize = 16;
+const AFTER: usize = 4;
+/// An open window's site: chain, who, trail seq, SMI count.
+const OPEN_WORDS: usize = CHAIN + 3;
+const W_HEAD: usize = 10;
+const W_WORDS: usize = W_HEAD + 2 * CHAIN + (KEEP + AFTER) * EV;
+const WREC: usize = 6;
+/// A serve: generation, at, via.
+const SERVES: usize = 64;
+/// Trail events of each target copied into a shootdown's record.
+const T_KEEP: usize = 6;
+const S_HEAD: usize = 8;
+const S_PER: usize = 3 + T_KEEP * EV;
+const S_WORDS: usize = S_HEAD + MAX_CPUS * S_PER;
+const SREC: usize = 3;
+const N_HEAD: usize = 6;
+const N_WORDS: usize = N_HEAD + CHAIN;
+const NREC: usize = 16;
+const L_WORDS: usize = 10;
+const LREC: usize = 4;
+/// NMIs one wait sends, one each further `LONG_NS` it has waited.
+const PROBES: u64 = 4;
+/// Lines one report prints at most; what is left waits for the next.
+const BUDGET: usize = 280;
+
+const K_SYS: u64 = 1;
+const K_SWITCH: u64 = 2;
+const K_IRQ: u64 = 3;
+const K_TRAP: u64 = 4;
+const K_HALT: u64 = 5;
+const K_WAKE: u64 = 6;
+const K_LOCK: u64 = 7;
+const K_SHOOT: u64 = 8;
+
+/// How a CPU answered a shootdown.
+pub const VIA_IPI: u64 = 1;
+pub const VIA_POLL: u64 = 2;
+pub const VIA_OWN: u64 = 3;
+pub const VIA_WAIT: u64 = 4;
+pub const VIA_JOIN: u64 = 5;
+const VIA: [&str; 6] = ["none", "ipi", "poll", "own", "wait", "join"];
+
+struct Words<const N: usize>([AtomicU64; N]);
+
+impl<const N: usize> Words<N> {
+ const fn new() -> Self {
+ Self([const { AtomicU64::new(0) }; N])
+ }
+ fn set(&self, i: usize, v: u64) {
+ self.0[i].store(v, Relaxed);
+ }
+ fn get(&self, i: usize) -> u64 {
+ self.0[i].load(Relaxed)
+ }
+}
+
+struct Scout {
+ trail: Words<{ TRAIL * EV }>,
+ seq: AtomicU64,
+ open: [Words<OPEN_WORDS>; 2],
+ wrecs: Words<{ WREC * W_WORDS }>,
+ w_written: AtomicU64,
+ w_printed: AtomicU64,
+ w_dropped: AtomicU64,
+ /// The record slot, plus one, the next trail events are also copied into.
+ after_of: AtomicU64,
+ after_n: AtomicU64,
+ serves: Words<{ SERVES * 3 }>,
+ serve_seq: AtomicU64,
+ served_gen: AtomicU64,
+ srecs: Words<{ SREC * S_WORDS }>,
+ s_written: AtomicU64,
+ s_printed: AtomicU64,
+ s_dropped: AtomicU64,
+ nrecs: Words<{ NREC * N_WORDS }>,
+ n_written: AtomicU64,
+ n_printed: AtomicU64,
+ n_dropped: AtomicU64,
+ lrecs: Words<{ LREC * L_WORDS }>,
+ l_written: AtomicU64,
+ l_printed: AtomicU64,
+ l_dropped: AtomicU64,
+ /// Who asked for this CPU's next NMI to be a sample, plus one.
+ probe_by: AtomicU64,
+ probed_at: AtomicU64,
+ sampled_at: AtomicU64,
+ smi: AtomicU64,
+ smi_at: AtomicU64,
+}
+
+impl Scout {
+ const fn new() -> Self {
+ Self {
+ trail: Words::new(),
+ seq: AtomicU64::new(0),
+ open: [const { Words::new() }; 2],
+ wrecs: Words::new(),
+ w_written: AtomicU64::new(0),
+ w_printed: AtomicU64::new(0),
+ w_dropped: AtomicU64::new(0),
+ after_of: AtomicU64::new(0),
+ after_n: AtomicU64::new(0),
+ serves: Words::new(),
+ serve_seq: AtomicU64::new(0),
+ served_gen: AtomicU64::new(0),
+ srecs: Words::new(),
+ s_written: AtomicU64::new(0),
+ s_printed: AtomicU64::new(0),
+ s_dropped: AtomicU64::new(0),
+ nrecs: Words::new(),
+ n_written: AtomicU64::new(0),
+ n_printed: AtomicU64::new(0),
+ n_dropped: AtomicU64::new(0),
+ lrecs: Words::new(),
+ l_written: AtomicU64::new(0),
+ l_printed: AtomicU64::new(0),
+ l_dropped: AtomicU64::new(0),
+ probe_by: AtomicU64::new(0),
+ probed_at: AtomicU64::new(0),
+ sampled_at: AtomicU64::new(0),
+ smi: AtomicU64::new(0),
+ smi_at: AtomicU64::new(0),
+ }
+ }
+}
+
+static SCOUT: [Scout; MAX_CPUS] = [const { Scout::new() }; MAX_CPUS];
+
+/// This CPU, once there is a per-CPU block to say which it is.
+fn here() -> Option<usize> {
+ crate::log::PERCPU_READY.load(Relaxed).then(|| percpu::cpu_id() as usize)
+}
+
+/// The thread this CPU runs: pid in the high half, tid in the low, all ones for none.
+fn who() -> u64 {
+ let pid = percpu::current_pid().map_or(u32::MAX, |pid| pid.raw());
+ let tid = percpu::current_tid().map_or(u32::MAX, |tid| tid.raw());
+ (u64::from(pid) << 32) | u64::from(tid)
+}
+
+/// The kernel stack this CPU stands on, as the per-CPU block names it.
+#[cfg(target_arch = "x86_64")]
+fn stack_bounds() -> (u64, u64) {
+ let top = percpu::kernel_stack_top();
+ (top.saturating_sub(crate::process::KERNEL_STACK_SIZE as u64), top)
+}
+
+#[cfg(not(target_arch = "x86_64"))]
+fn stack_bounds() -> (u64, u64) {
+ (0, 0)
+}
+
+/// `MSR_SMI_COUNT`: the SMIs this CPU has taken since reset.
+#[cfg(target_arch = "x86_64")]
+fn smi_count() -> u64 {
+ cpu::rdmsr(0x34)
+}
+
+#[cfg(not(target_arch = "x86_64"))]
+fn smi_count() -> u64 {
+ 0
+}
+
+/// The return addresses up the frame chain from `fp`, zero past its end. Every
+/// frame read is inside the kernel stack this CPU stands on and above the one
+/// before it.
+fn chain_into(into: &[AtomicU64], mut fp: u64) {
+ let (low, high) = stack_bounds();
+ for slot in into {
+ let mut ret = 0;
+ if fp >= low && fp.saturating_add(16) <= high && fp.is_multiple_of(8) {
+ // SAFETY: both words are inside this CPU's own kernel stack, by the bounds above.
+ let (next, ra) = unsafe { (*(fp as *const u64), *((fp + 8) as *const u64)) };
+ ret = ra;
+ fp = if next > fp { next } else { 0 };
+ } else {
+ fp = 0;
+ }
+ slot.store(ret, Relaxed);
+ }
+}
+
+/// A window of `kind` has just opened: where, by whom, and the trail's place.
+#[inline(always)]
+fn opened(me: usize, kind: usize, fp: u64) {
+ let s = &SCOUT[me];
+ let o = &s.open[kind];
+ chain_into(&o.0[..CHAIN], fp);
+ o.set(CHAIN, who());
+ o.set(CHAIN + 1, s.seq.load(Relaxed));
+ if kind == IRQS {
+ let smi = smi_count();
+ o.set(CHAIN + 2, smi);
+ s.smi.store(smi, Relaxed);
+ s.smi_at.store(CPUS[me].irqs_since(), Relaxed);
+ }
+}
+
+/// A window of `kind` opened at `since` closed at `at`.
+#[inline(always)]
+fn closed(me: usize, kind: usize, since: u64, at: u64, fp: u64) {
+ if since == 0 || at <= since {
+ return;
+ }
+ let long = LONG.load(Relaxed);
+ if long == 0 || at - since <= long {
+ return;
+ }
+ // A preemption-off window that opened and closes inside one interrupts-off
+ // window is that window's record, not a second one.
+ if kind == PREEMPT {
+ let masked = CPUS[me].irqs_since();
+ if masked != 0 && masked <= since {
+ return;
+ }
+ }
+ record_window(me, kind, since, at, fp);
+}
+
+#[cold]
+#[inline(never)]
+fn record_window(me: usize, kind: usize, since: u64, at: u64, fp: u64) {
+ // A preempt hook may run with interrupts open, and an interrupt's own long
+ // window would take the same slot.
+ let _masked = (kind == PREEMPT).then(crate::arch::IrqGuard::close);
+ let s = &SCOUT[me];
+ let n = s.w_written.load(Relaxed);
+ if n.wrapping_sub(s.w_printed.load(Relaxed)) >= WREC as u64 {
+ s.w_dropped.fetch_add(1, Relaxed);
+ return;
+ }
+ let slot = n as usize % WREC;
+ if s.after_of.load(Relaxed) == slot as u64 + 1 {
+ s.after_of.store(0, Relaxed);
+ }
+ let base = slot * W_WORDS;
+ let o = &s.open[kind];
+ let seq_open = o.get(CHAIN + 1);
+ let seq_now = s.seq.load(Relaxed);
+ let events = seq_now.wrapping_sub(seq_open);
+ let kept = events.min(KEEP as u64);
+ let head = [
+ kind as u64 + 1,
+ since,
+ at,
+ o.get(CHAIN),
+ who(),
+ o.get(CHAIN + 2),
+ if kind == IRQS { smi_count() } else { 0 },
+ events,
+ kept,
+ 0,
+ ];
+ for (i, word) in head.iter().enumerate() {
+ s.wrecs.set(base + i, *word);
+ }
+ for i in 0..CHAIN {
+ s.wrecs.set(base + W_HEAD + i, o.get(i));
+ }
+ chain_into(&s.wrecs.0[base + W_HEAD + CHAIN..base + W_HEAD + 2 * CHAIN], fp);
+ let events_at = base + W_HEAD + 2 * CHAIN;
+ for k in 0..kept as usize {
+ let from = (seq_now.wrapping_sub(kept).wrapping_add(k as u64) as usize % TRAIL) * EV;
+ for j in 0..EV {
+ s.wrecs.set(events_at + k * EV + j, s.trail.get(from + j));
+ }
+ }
+ if kind == IRQS {
+ s.after_n.store(0, Relaxed);
+ s.after_of.store(slot as u64 + 1, Relaxed);
+ }
+ s.w_written.store(n + 1, Relaxed);
+}
+
+/// One event on this CPU's trail.
+#[inline]
+fn note(kind: u64, a: u64, b: u64, c: u64) {
+ let Some(me) = here() else { return };
+ let s = &SCOUT[me];
+ let event = [cpu::counter(), kind, a, b, c];
+ let base = (s.seq.fetch_add(1, Relaxed) as usize % TRAIL) * EV;
+ for (j, word) in event.iter().enumerate() {
+ s.trail.set(base + j, *word);
+ }
+ let after_of = s.after_of.load(Relaxed);
+ if after_of != 0 {
+ let k = s.after_n.fetch_add(1, Relaxed);
+ if k < AFTER as u64 {
+ let rec = (after_of as usize - 1) * W_WORDS;
+ let to = rec + W_HEAD + 2 * CHAIN + (KEEP + k as usize) * EV;
+ for (j, word) in event.iter().enumerate() {
+ s.wrecs.set(to + j, *word);
+ }
+ s.wrecs.set(rec + 9, k + 1);
+ } else {
+ s.after_of.store(0, Relaxed);
+ }
+ }
+}
+
+/// A syscall's Rust half has begun.
+pub fn note_syscall(num: u64) {
+ note(K_SYS, num, 0, 0);
+}
+
+/// This CPU has just been told which thread it switches onto.
+pub fn note_switch() {
+ note(K_SWITCH, who(), 0, 0);
+}
+
+/// An interrupt's handler runs. The NMI leaves no event: it is the sampler.
+pub fn note_irq(source: crate::irq_census::Source) {
+ if source != crate::irq_census::Source::Nmi {
+ note(K_IRQ, source as u64, 0, 0);
+ }
+}
+
+/// An exception's dispatch runs.
+pub fn note_trap(vector: u64, rip: u64) {
+ note(K_TRAP, vector, rip, 0);
+}
+
+/// This CPU has published a flush for `generation`, by `via`.
+#[inline]
+pub fn served(via: u64, generation: u64) {
+ let Some(me) = here() else { return };
+ let s = &SCOUT[me];
+ if s.served_gen.load(Relaxed) == generation {
+ return;
+ }
+ s.served_gen.store(generation, Relaxed);
+ let base = (s.serve_seq.fetch_add(1, Relaxed) as usize % SERVES) * 3;
+ s.serves.set(base + 1, cpu::counter());
+ s.serves.set(base + 2, via);
+ s.serves.set(base, generation);
+}
+
+/// Ask `target` for a sample of itself, at most one a half `LONG_NS` whoever asks.
+fn probe(me: usize, target: usize, now: u64) {
+ if target == me || target >= MAX_CPUS || target as u32 >= crate::smp::cpu_count() {
+ return;
+ }
+ let t = &SCOUT[target];
+ if now.saturating_sub(t.probed_at.load(Relaxed)) < LONG.load(Relaxed) / 2 {
+ return;
+ }
+ t.probed_at.store(now, Relaxed);
+ t.probe_by.store(me as u64 + 1, Relaxed);
+ #[cfg(target_arch = "x86_64")]
+ crate::arch::apic::send_nmi(target as u32);
+}
+
+/// From the NMI entry: no lock and no log. A sample is taken when another CPU
+/// asked for one, or when this CPU's interrupts have been masked past `LONG_NS`.
+pub fn nmi(rip: u64, rflags: u64, cs: u64, rbp: u64) {
+ let me = percpu::cpu_id() as usize;
+ if me >= MAX_CPUS {
+ return;
+ }
+ let s = &SCOUT[me];
+ let by = s.probe_by.swap(0, Relaxed);
+ let now = cpu::counter();
+ let long = LONG.load(Relaxed);
+ let since = CPUS[me].irqs_since();
+ // The CPU printing the report samples itself for nobody: its window is the report's.
+ let own = long != 0
+ && since != 0
+ && now.saturating_sub(since) > long
+ && REPORTING.load(Relaxed) != me as u64 + 1;
+ if by == 0 && !own {
+ return;
+ }
+ if now.saturating_sub(s.sampled_at.load(Relaxed)) < long / 4 * 3 {
+ return;
+ }
+ s.sampled_at.store(now, Relaxed);
+ let n = s.n_written.load(Relaxed);
+ if n.wrapping_sub(s.n_printed.load(Relaxed)) >= NREC as u64 {
+ s.n_dropped.fetch_add(1, Relaxed);
+ return;
+ }
+ let base = (n as usize % NREC) * N_WORDS;
+ let ring = cs & 3;
+ let head = [now, by, rip, ((rflags >> 9) & 1) | (ring << 1), who(), since];
+ for (i, word) in head.iter().enumerate() {
+ s.nrecs.set(base + i, *word);
+ }
+ chain_into(&s.nrecs.0[base + N_HEAD..base + N_WORDS], if ring == 0 { rbp } else { 0 });
+ s.n_written.store(n + 1, Relaxed);
+}
+
+/// An initiator's look at its own shootdown.
+pub struct Shoot {
+ me: usize,
+ generation: u64,
+ origin: u64,
+ begin: u64,
+ last: u64,
+ gap: u64,
+ gap_at: u64,
+ probes: u64,
+ seen: [u64; MAX_CPUS],
+}
+
+impl Shoot {
+ pub fn begin(me: usize, generation: u64, origin: u64) -> Self {
+ let begin = cpu::counter();
+ Self { me, generation, origin, begin, last: begin, gap: 0, gap_at: 0, probes: 0, seen: [0; MAX_CPUS] }
+ }
+
+ /// One turn of the wait for `target`, which has not answered.
+ #[inline]
+ pub fn turn(&mut self, target: usize) {
+ let now = cpu::counter();
+ let gap = now.saturating_sub(self.last);
+ if gap > self.gap {
+ self.gap = gap;
+ self.gap_at = now;
+ }
+ self.last = now;
+ let long = LONG.load(Relaxed);
+ if long != 0 && self.probes < PROBES && now.saturating_sub(self.begin) > long * (self.probes + 1) {
+ self.probes += 1;
+ probe(self.me, target, now);
+ }
+ }
+
+ /// `cpu` has answered, as this CPU saw it.
+ pub fn seen(&mut self, cpu: usize) {
+ let now = cpu::counter();
+ self.seen[cpu] = now;
+ self.last = now;
+ }
+
+ pub fn end(self, cpus: u32) {
+ let end = cpu::counter();
+ let took = end.saturating_sub(self.begin);
+ let note_ticks = NOTE.load(Relaxed);
+ if note_ticks != 0 && took >= note_ticks {
+ note(K_SHOOT, self.generation, took, 0);
+ }
+ let long = LONG.load(Relaxed);
+ if long != 0 && took > long {
+ self.record(end, cpus);
+ }
+ }
+
+ #[cold]
+ #[inline(never)]
+ fn record(&self, end: u64, cpus: u32) {
+ let _masked = crate::arch::IrqGuard::close();
+ let s = &SCOUT[self.me];
+ let n = s.s_written.load(Relaxed);
+ if n.wrapping_sub(s.s_printed.load(Relaxed)) >= SREC as u64 {
+ s.s_dropped.fetch_add(1, Relaxed);
+ return;
+ }
+ let base = (n as usize % SREC) * S_WORDS;
+ let head =
+ [self.generation, self.begin, end, self.gap, self.gap_at, self.probes, u64::from(cpus), self.origin];
+ for (i, word) in head.iter().enumerate() {
+ s.srecs.set(base + i, *word);
+ }
+ for cpu in 0..(cpus as usize).min(MAX_CPUS) {
+ let at = base + S_HEAD + cpu * S_PER;
+ let t = &SCOUT[cpu];
+ // The first flush this target published that covers the generation.
+ let mut ack = (u64::MAX, 0, 0);
+ for i in 0..SERVES {
+ let generation = t.serves.get(i * 3);
+ if generation >= self.generation && generation < ack.0 {
+ ack = (generation, t.serves.get(i * 3 + 1), t.serves.get(i * 3 + 2));
+ }
+ }
+ s.srecs.set(at, self.seen[cpu]);
+ s.srecs.set(at + 1, ack.1);
+ s.srecs.set(at + 2, ack.2);
+ let seq = t.seq.load(Relaxed);
+ let kept = seq.min(T_KEEP as u64);
+ for k in 0..T_KEEP {
+ let from = (seq.wrapping_sub(kept).wrapping_add(k as u64) as usize % TRAIL) * EV;
+ for j in 0..EV {
+ let word = if (k as u64) < kept { t.trail.get(from + j) } else { 0 };
+ s.srecs.set(at + 3 + k * EV + j, word);
+ }
+ }
+ }
+ s.s_written.store(n + 1, Relaxed);
+ }
+}
+
+/// A contended `Lock::lock`'s look at its own spin.
+pub struct SpinWatch {
+ turns: u64,
+ begin: u64,
+ last: u64,
+ gap: u64,
+ gap_at: u64,
+ now: u32,
+ since: u64,
+ held_cpu: u32,
+ held_at: u64,
+ longest: u64,
+ longest_cpu: u32,
+ longest_at: u64,
+ probes: u64,
+}
+
+impl SpinWatch {
+ pub const fn new() -> Self {
+ Self {
+ turns: 0,
+ begin: 0,
+ last: 0,
+ gap: 0,
+ gap_at: 0,
+ now: 0,
+ since: 0,
+ held_cpu: 0,
+ held_at: 0,
+ longest: 0,
+ longest_cpu: 0,
+ longest_at: 0,
+ probes: 0,
+ }
+ }
+
+ fn tenure_ends(&mut self, at: u64) {
+ let tenure = at.saturating_sub(self.since);
+ if tenure > self.longest {
+ self.longest = tenure;
+ self.longest_cpu = self.held_cpu;
+ self.longest_at = self.held_at;
+ }
+ }
+
+ /// One turn of the spin: the lock serves ticket `now`, and its holder said who it is.
+ #[inline]
+ pub fn turn(&mut self, now: u32, held_cpu: &AtomicU32, held_at: &AtomicU64) {
+ let at = cpu::counter();
+ let mut look = self.turns & 63 == 0;
+ if self.turns == 0 {
+ self.begin = at;
+ self.now = now;
+ self.since = at;
+ } else {
+ let gap = at.saturating_sub(self.last);
+ if gap > self.gap {
+ self.gap = gap;
+ self.gap_at = at;
+ }
+ if now != self.now {
+ self.tenure_ends(at);
+ self.now = now;
+ self.since = at;
+ look = true;
+ }
+ }
+ if look {
+ self.held_cpu = held_cpu.load(Relaxed);
+ self.held_at = held_at.load(Relaxed);
+ }
+ self.last = at;
+ self.turns += 1;
+ let long = LONG.load(Relaxed);
+ if long != 0
+ && self.probes < PROBES
+ && self.held_cpu != 0
+ && at.saturating_sub(self.begin) > long * (self.probes + 1)
+ {
+ self.probes += 1;
+ if let Some(me) = here() {
+ probe(me, self.held_cpu as usize - 1, at);
+ }
+ }
+ }
+
+ /// The lock is this CPU's.
+ pub fn end(mut self, lock: u64, caller: &'static Location<'static>) {
+ if self.turns == 0 {
+ return;
+ }
+ let end = cpu::counter();
+ self.tenure_ends(end);
+ let took = end.saturating_sub(self.begin);
+ let note_ticks = NOTE.load(Relaxed);
+ if note_ticks == 0 || took < note_ticks {
+ return;
+ }
+ let caller = caller as *const Location<'static> as u64;
+ note(K_LOCK, lock, took, caller);
+ let long = LONG.load(Relaxed);
+ if long != 0 && took > long {
+ self.record(lock, caller, end);
+ }
+ }
+
+ #[cold]
+ #[inline(never)]
+ fn record(&self, lock: u64, caller: u64, end: u64) {
+ let Some(me) = here() else { return };
+ let _masked = crate::arch::IrqGuard::close();
+ let s = &SCOUT[me];
+ let n = s.l_written.load(Relaxed);
+ if n.wrapping_sub(s.l_printed.load(Relaxed)) >= LREC as u64 {
+ s.l_dropped.fetch_add(1, Relaxed);
+ return;
+ }
+ let base = (n as usize % LREC) * L_WORDS;
+ let words = [
+ lock,
+ caller,
+ self.begin,
+ end,
+ self.gap,
+ self.gap_at,
+ u64::from(self.longest_cpu),
+ self.longest_at,
+ self.longest,
+ self.probes,
+ ];
+ for (i, word) in words.iter().enumerate() {
+ s.lrecs.set(base + i, *word);
+ }
+ s.l_written.store(n + 1, Relaxed);
+ }
+}
+
+/// This CPU holds the lock these two words belong to, taken at `caller`.
+#[inline]
+pub fn holds(held_cpu: &AtomicU32, held_at: &AtomicU64, caller: u64) {
+ if let Some(me) = here() {
+ held_at.store(caller, Relaxed);
+ held_cpu.store(me as u32 + 1, Relaxed);
+ }
+}
+
+struct Ns(u64);
+
+impl fmt::Display for Ns {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ write!(f, "{}", if self.0 == 0 { 0 } else { crate::clock::nanos_at(self.0) })
+ }
+}
+
+struct Who(u64);
+
+impl fmt::Display for Who {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ let (pid, tid) = ((self.0 >> 32) as u32, self.0 as u32);
+ match (pid, tid) {
+ (u32::MAX, _) => f.write_str("idle"),
+ (pid, u32::MAX) => write!(f, "{pid}:-"),
+ (pid, tid) => write!(f, "{pid}:{tid}"),
+ }
+ }
+}
+
+/// A `&'static Location` as `Lock::lock` stored it, or `?` for none.
+struct Loc(u64);
+
+impl fmt::Display for Loc {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ if self.0 == 0 {
+ return f.write_str("?");
+ }
+ // SAFETY: stored from a `&'static Location` and nothing else.
+ let at: &'static Location<'static> = unsafe { &*(self.0 as *const Location<'static>) };
+ write!(f, "{}:{}", at.file(), at.line())
+ }
+}
+
+/// At most `N` bytes of what is written to it.
+struct Clip<const N: usize> {
+ bytes: [u8; N],
+ len: usize,
+}
+
+impl<const N: usize> fmt::Write for Clip<N> {
+ fn write_str(&mut self, s: &str) -> fmt::Result {
+ let mut fit = s.len().min(N - self.len);
+ while !s.is_char_boundary(fit) {
+ fit -= 1;
+ }
+ self.bytes[self.len..self.len + fit].copy_from_slice(&s.as_bytes()[..fit]);
+ self.len += fit;
+ Ok(())
+ }
+}
+
+/// An address by the kernel's own symbols; `ret` says it is a return address.
+struct Sym(u64, bool);
+
+impl fmt::Display for Sym {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ let back = u64::from(self.1);
+ match crate::symbols::kernel_symbol(self.0.saturating_sub(back)) {
+ Some((name, offset)) => {
+ let mut clip = Clip::<96> { bytes: [0; 96], len: 0 };
+ let _ = fmt::Write::write_fmt(&mut clip, format_args!("{:#}", rustc_demangle::demangle(name)));
+ let text = core::str::from_utf8(&clip.bytes[..clip.len]).unwrap_or("?");
+ write!(f, "{text}+{:#x}", offset + back)
+ }
+ None => write!(f, "{:#x}", self.0),
+ }
+ }
+}
+
+struct Frames([u64; CHAIN]);
+
+impl fmt::Display for Frames {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ if self.0[0] == 0 {
+ return f.write_str("-");
+ }
+ for (i, frame) in self.0.iter().take_while(|frame| **frame != 0).enumerate() {
+ if i > 0 {
+ f.write_str(" < ")?;
+ }
+ write!(f, "{}", Sym(*frame, true))?;
+ }
+ Ok(())
+ }
+}
+
+/// Trail events, `EV` words each: `<ns>:<what>`, ` | ` between.
+struct Events<'a>(&'a [u64]);
+
+impl fmt::Display for Events<'_> {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ let mut first = true;
+ for e in self.0.chunks_exact(EV) {
+ if e[0] == 0 {
+ continue;
+ }
+ if !first {
+ f.write_str(" | ")?;
+ }
+ first = false;
+ write!(f, "{}:", Ns(e[0]))?;
+ match e[1] {
+ K_SYS => write!(f, "sys({})", e[2])?,
+ K_SWITCH => write!(f, "to({})", Who(e[2]))?,
+ K_IRQ => write!(
+ f,
+ "irq({})",
+ crate::irq_census::Source::NAMES.get(e[2] as usize).copied().unwrap_or("?")
+ )?,
+ K_TRAP => write!(f, "trap({} rip={})", e[2], Sym(e[3], false))?,
+ K_HALT => f.write_str("halt")?,
+ K_WAKE => f.write_str("wake")?,
+ K_LOCK => write!(
+ f,
+ "lock({} {:#x} {}ns)",
+ Loc(e[4]),
+ e[2],
+ crate::clock::nanos_of_ticks(e[3])
+ )?,
+ K_SHOOT => write!(f, "shoot(g={} {}ns)", e[2], crate::clock::nanos_of_ticks(e[3]))?,
+ other => write!(f, "?{other}")?,
+ }
+ }
+ if first {
+ f.write_str("-")?;
+ }
+ Ok(())
+ }
+}
+
+struct Smi(usize);
+
+impl fmt::Display for Smi {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ for (cpu, s) in SCOUT.iter().enumerate().take(self.0) {
+ write!(f, " cpu{cpu}={}@{}", s.smi.load(Relaxed), Ns(s.smi_at.load(Relaxed)))?;
+ }
+ Ok(())
+ }
+}
+
+/// The CPU printing a report, plus one.
+static REPORTING: AtomicU64 = AtomicU64::new(0);
+
+/// Everything the scout kept since the report before, after the census.
+pub fn log_scout() {
+ let Some(me) = here() else { return };
+ if REPORTING.compare_exchange(0, me as u64 + 1, Relaxed, Relaxed).is_err() {
+ return;
+ }
+ let cpus = (crate::smp::cpu_count() as usize).min(MAX_CPUS);
+ SCOUT[me].smi.store(smi_count(), Relaxed);
+ SCOUT[me].smi_at.store(cpu::counter(), Relaxed);
+ crate::log!("scout: smi at={}{}", Ns(cpu::counter()), Smi(cpus));
+ let mut left = BUDGET;
+ for cpu in 0..cpus {
+ log_windows(cpu, &mut left);
+ }
+ for cpu in 0..cpus {
+ log_shoots(cpu, &mut left);
+ }
+ for cpu in 0..cpus {
+ log_samples(cpu, &mut left);
+ }
+ for cpu in 0..cpus {
+ log_locks(cpu, &mut left);
+ }
+ let mut dropped = [0u64; 4];
+ let mut unprinted = 0;
+ for s in SCOUT.iter().take(cpus) {
+ dropped[0] += s.w_dropped.swap(0, Relaxed);
+ dropped[1] += s.s_dropped.swap(0, Relaxed);
+ dropped[2] += s.n_dropped.swap(0, Relaxed);
+ dropped[3] += s.l_dropped.swap(0, Relaxed);
+ unprinted += s.w_written.load(Relaxed).wrapping_sub(s.w_printed.load(Relaxed))
+ + s.s_written.load(Relaxed).wrapping_sub(s.s_printed.load(Relaxed))
+ + s.n_written.load(Relaxed).wrapping_sub(s.n_printed.load(Relaxed))
+ + s.l_written.load(Relaxed).wrapping_sub(s.l_printed.load(Relaxed));
+ }
+ if dropped != [0; 4] || unprinted != 0 {
+ crate::log!(
+ "scout: dropped win={} shoot={} nmi={} lock={} unprinted={unprinted}",
+ dropped[0],
+ dropped[1],
+ dropped[2],
+ dropped[3],
+ );
+ }
+ crate::log!("scout: end at={} lines={}", Ns(cpu::counter()), BUDGET - left);
+ REPORTING.store(0, Relaxed);
+}
+
+fn log_windows(cpu: usize, left: &mut usize) {
+ let s = &SCOUT[cpu];
+ let written = s.w_written.load(Relaxed);
+ let mut printed = s.w_printed.load(Relaxed);
+ while printed != written && *left >= 8 {
+ let base = (printed as usize % WREC) * W_WORDS;
+ let mut r = [0u64; W_WORDS];
+ for (i, word) in r.iter_mut().enumerate() {
+ *word = s.wrecs.get(base + i);
+ }
+ let kind = if r[0] == IRQS as u64 + 1 { "irqs" } else { "preempt" };
+ let open = crate::clock::nanos_at(r[1]);
+ crate::log!(
+ "scout: win cpu{cpu} {kind} open={open} close={} span_ns={} smi={}->{} opener={} closer={} events={}",
+ Ns(r[2]),
+ crate::clock::nanos_of_ticks(r[2].saturating_sub(r[1])),
+ r[5],
+ r[6],
+ Who(r[3]),
+ Who(r[4]),
+ r[7],
+ );
+ let mut frames = [0u64; CHAIN];
+ frames.copy_from_slice(&r[W_HEAD..W_HEAD + CHAIN]);
+ crate::log!("scout: win cpu{cpu} {kind} open={open} opened_at: {}", Frames(frames));
+ frames.copy_from_slice(&r[W_HEAD + CHAIN..W_HEAD + 2 * CHAIN]);
+ crate::log!("scout: win cpu{cpu} {kind} open={open} closed_at: {}", Frames(frames));
+ *left -= 3;
+ let events_at = W_HEAD + 2 * CHAIN;
+ let kept = (r[8] as usize).min(KEEP);
+ for line in r[events_at..events_at + kept * EV].chunks(6 * EV) {
+ crate::log!("scout: win cpu{cpu} {kind} open={open} during: {}", Events(line));
+ *left -= 1;
+ }
+ let after = (r[9] as usize).min(AFTER);
+ if after != 0 {
+ let after_at = events_at + KEEP * EV;
+ crate::log!(
+ "scout: win cpu{cpu} {kind} open={open} after: {}",
+ Events(&r[after_at..after_at + after * EV])
+ );
+ *left -= 1;
+ }
+ printed += 1;
+ s.w_printed.store(printed, Relaxed);
+ }
+}
+
+fn log_shoots(cpu: usize, left: &mut usize) {
+ let s = &SCOUT[cpu];
+ let written = s.s_written.load(Relaxed);
+ let mut printed = s.s_printed.load(Relaxed);
+ while printed != written && *left >= 1 + MAX_CPUS {
+ let base = (printed as usize % SREC) * S_WORDS;
+ let mut r = [0u64; S_WORDS];
+ for (i, word) in r.iter_mut().enumerate() {
+ *word = s.srecs.get(base + i);
+ }
+ let generation = r[0];
+ crate::log!(
+ "scout: shoot cpu{cpu} gen={generation} origin={} begin={} end={} span_ns={} gap_ns={} gap_at={} probes={}",
+ crate::invalidation::Origin::NAMES.get(r[7] as usize).copied().unwrap_or("?"),
+ Ns(r[1]),
+ Ns(r[2]),
+ crate::clock::nanos_of_ticks(r[2].saturating_sub(r[1])),
+ crate::clock::nanos_of_ticks(r[3]),
+ Ns(r[4]),
+ r[5],
+ );
+ *left -= 1;
+ for target in (0..(r[6] as usize).min(MAX_CPUS)).filter(|target| *target != cpu) {
+ let at = S_HEAD + target * S_PER;
+ crate::log!(
+ "scout: shoot cpu{cpu} gen={generation} target=cpu{target} ack={} via={} seen={} trail: {}",
+ Ns(r[at + 1]),
+ VIA.get(r[at + 2] as usize).copied().unwrap_or("?"),
+ Ns(r[at]),
+ Events(&r[at + 3..at + S_PER]),
+ );
+ *left -= 1;
+ }
+ printed += 1;
+ s.s_printed.store(printed, Relaxed);
+ }
+}
+
+fn log_samples(cpu: usize, left: &mut usize) {
+ let s = &SCOUT[cpu];
+ let written = s.n_written.load(Relaxed);
+ let mut printed = s.n_printed.load(Relaxed);
+ while printed != written && *left >= 1 {
+ let base = (printed as usize % NREC) * N_WORDS;
+ let mut r = [0u64; N_WORDS];
+ for (i, word) in r.iter_mut().enumerate() {
+ *word = s.nrecs.get(base + i);
+ }
+ let mut frames = [0u64; CHAIN];
+ frames.copy_from_slice(&r[N_HEAD..N_WORDS]);
+ struct By(u64);
+ impl fmt::Display for By {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ match self.0 {
+ 0 => f.write_str("self"),
+ by => write!(f, "cpu{}", by - 1),
+ }
+ }
+ }
+ crate::log!(
+ "scout: nmi cpu{cpu} at={} by={} ring={} if={} who={} masked_since={} rip={} stack: {}",
+ Ns(r[0]),
+ By(r[1]),
+ r[3] >> 1,
+ r[3] & 1,
+ Who(r[4]),
+ Ns(r[5]),
+ Sym(r[2], false),
+ Frames(frames),
+ );
+ *left -= 1;
+ printed += 1;
+ s.n_printed.store(printed, Relaxed);
+ }
+}
+
+fn log_locks(cpu: usize, left: &mut usize) {
+ let s = &SCOUT[cpu];
+ let written = s.l_written.load(Relaxed);
+ let mut printed = s.l_printed.load(Relaxed);
+ while printed != written && *left >= 1 {
+ let base = (printed as usize % LREC) * L_WORDS;
+ let mut r = [0u64; L_WORDS];
+ for (i, word) in r.iter_mut().enumerate() {
+ *word = s.lrecs.get(base + i);
+ }
+ struct Holder(u64);
+ impl fmt::Display for Holder {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ match self.0 {
+ 0 => f.write_str("?"),
+ cpu => write!(f, "cpu{}", cpu - 1),
+ }
+ }
+ }
+ crate::log!(
+ "scout: lock cpu{cpu} lock={} at={} begin={} end={} span_ns={} gap_ns={} gap_at={} holder={} held_ns={} holder_at={} probes={}",
+ Sym(r[0], false),
+ Loc(r[1]),
+ Ns(r[2]),
+ Ns(r[3]),
+ crate::clock::nanos_of_ticks(r[3].saturating_sub(r[2])),
+ crate::clock::nanos_of_ticks(r[4]),
+ Ns(r[5]),
+ Holder(r[6]),
+ crate::clock::nanos_of_ticks(r[8]),
+ Loc(r[7]),
+ r[9],
+ );
+ *left -= 1;
+ printed += 1;
+ s.l_printed.store(printed, Relaxed);
+ }
}
diff --git a/tests/scoutcase/system.toml b/tests/scoutcase/system.toml
new file mode 100644
index 000000000..4dad7e46e
--- /dev/null
+++ b/tests/scoutcase/system.toml
@@ -0,0 +1,82 @@
+
+[boot]
+start = ["logd", "blockd", "fsd", "soundd", "test-runner"]
+
+# **Every image that carries a `TOYOS-LOG` partition runs this**, and every
+# image does. The kernel keeps the record ring and writes no file at all, so a
+# boot config without `logd` is a boot whose `/log` is empty —
+# `every_boot_config_runs_logd` is what refuses one.
+# It claims no device and serves no port: its row's authority is `logread`,
+# which is `Rights::LOG | Rights::WAIT` on a `SysCap` duplicate, and init hands
+# it every program's output beside that.
+[programs.logd]
+service = true
+syscap = ["logread"]
+
+[programs.soundd]
+service = true
+serves = ["soundd"]
+devices = ["hda-audio", "virtio-sound"]
+syscap = ["rt"]
+
+# The test estate's authority.
+# `device` because five of the guest binaries claim the keyboard or the mouse
+# and no manifest row can name them — they are not `[programs]` keys — and `dup`
+# because a claim moves and one boot runs several of them.
+# `logread` because the log gate reads the kernel's own records and cannot be
+# a spawned binary: a `SysCap` dup is not part of the namespace test-runner
+# hands down.
+# `power` because `endowment_denied` narrows it *away* to prove the two power
+# syscalls refuse a capability without it, which a capability that never
+# carried it would make vacuous. `run shutdown` does not use it: the applet asks
+# init through the `power` connector, and init has `logd` make the log whole
+# before it stops the machine.
+# `roster` because guest binaries read `SYS_SYSINFO`'s per-thread entries —
+# soundd's, for the idle-suspend certification, and their own, which arrive in
+# the same machine-wide answer and have no narrower question in the ABI. It is
+# also what `endowment_denied` narrows *away* to prove the refusal, so an estate
+# without it would make that arm vacuous rather than red.
+[programs.test-runner]
+receives = ["soundd", "power"]
+syscap = ["device", "dup", "logread", "power", "roster"]
+args = ["--bound-ms=3600000", "test_rs_idle_span", "pwd", "test_rs_ring_park_herd"]
+
+[programs.toybox]
+receives = ["soundd"]
+
+[symlinks]
+"bin/cat" = "/system/bin/toybox"
+"bin/cp" = "/system/bin/toybox"
+"bin/echo" = "/system/bin/toybox"
+"bin/free" = "/system/bin/toybox"
+"bin/grep" = "/system/bin/toybox"
+"bin/hexdump" = "/system/bin/toybox"
+"bin/ls" = "/system/bin/toybox"
+"bin/mkdir" = "/system/bin/toybox"
+"bin/mv" = "/system/bin/toybox"
+"bin/ps" = "/system/bin/toybox"
+"bin/pwd" = "/system/bin/toybox"
+"bin/reboot" = "/system/bin/toybox"
+"bin/rm" = "/system/bin/toybox"
+"bin/shutdown" = "/system/bin/toybox"
+# The shipped audio client, and the one the T14 hangs on. The raw-API tone in
+# `toyos-rust-tests` drains the same sink perfectly, so a suite that ran only
+# that one certified a path no user takes.
+"bin/tone" = "/system/bin/toybox"
+
+# The block service: the NVMe controller this machine's DATA is on, driven
+# from userland through its claim. Started again when it ends; the claim goes
+# back with the process and is minted again for the next.
+[programs.blockd]
+service = true
+restart = true
+serves = ["block"]
+devices = ["pci:1b36:0010"]
+
+# The file servers: DATA, the log and the running slot's volume, one process
+# each, serving every program the directories of its role. Started again when
+# one ends, on the same ports.
+[programs.fsd]
+restart = true
+roles = ["data", "log", "boot"]
+receives = ["block"] |
|
The scout patch, part 2 of 2. The throwaway instrument the evidence comments read (never landed): diff --git a/tests/toyos.rs b/tests/toyos.rs
index 9081943e0..543a58395 100644
--- a/tests/toyos.rs
+++ b/tests/toyos.rs
@@ -185,6 +185,8 @@ const MACHINE_TESTS: &[&str] = &[
// no way to turn it back on, so only a machine QEMU reports stopping can
// be asked. `machine_soft_off_decoded` reads the T14's own decode.
"machine_shutdown",
+ // SCOUT: the T14 row's kernel and job list under TCG, read for its lines' shape.
+ "x86_scout_probe",
];
/// **The metal profile**: which registrations run on the ThinkPad T14, what
@@ -2312,10 +2314,193 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> {
"iommu_virtio_platform" => common::iommu::iommu_virtio_platform(test_config),
"nested_nmi_is_loud" => faults::nested_nmi_is_loud(test_config),
"machine_shutdown" => power::machine_shutdown(test_config),
+ "x86_scout_probe" => scout_probe(),
other => Err(format!("unknown machine test {other}")),
}
}
+/// SCOUT: boot the `mask_windows` row's kernel and job list on eight CPUs under
+/// TCG, wait for every run of the herd, and read every `scout:` line for its
+/// shape. No duration here is a verdict.
+fn scout_probe() -> Result<(), String> {
+ const CPUS: u32 = 8;
+ const RUNS: usize = 40;
+ let root = compile::repo_root();
+ let bin = |name: &str| {
+ (
+ format!("bin/test_rs_{name}"),
+ qemu::build_toyos_bin(toyos_build::arch::Arch::X86_64, &root.join("tests/toyos-rust-tests"), name),
+ )
+ };
+ let mut qemu = QemuInstance::boot_with_options(
+ &root.join("tests/scoutcase"),
+ &[],
+ &[],
+ BootOptions {
+ smp: CPUS,
+ kernel_features: toyos_build::build::MASK_WINDOWS_KERNEL,
+ extra_root_files: vec![bin("ring_park_herd"), bin("idle_span")],
+ ..Default::default()
+ },
+ );
+ let end = format!("===TEST_END {WINDOWS_LOAD} ");
+ let mut rest = String::new();
+ let mut from = 0;
+ let mut waited = Ok(());
+ for run in 0..RUNS {
+ waited = qemu::await_marker_new(&mut qemu, &mut rest, &end, from, &format!("run {run} of the herd to end"));
+ if waited.is_err() {
+ break;
+ }
+ from += rest[from..].find(&end).expect("the marker was awaited") + end.len();
+ }
+ if waited.is_ok() {
+ waited = await_marker(&mut qemu, &mut rest, "exit: test-runner pid=", "the runner to end");
+ }
+ let serial = format!("{}\n{rest}", qemu.boot_log());
+ for line in serial.lines().filter(|l| {
+ l.contains("scout: ") || l.contains("windows: ") || l.contains("tlb: ") || l.contains("exit: ") && l.contains(" pid=") || l.contains("===TEST_")
+ }) {
+ eprintln!(" [scout] {line}");
+ }
+ waited.map_err(|why| format!("{why}\nserial:\n{serial}"))?;
+ let exits = serial.lines().filter(|l| l.contains(&format!("===TEST_END {WINDOWS_LOAD} exit=0==="))).count();
+ if exits != RUNS {
+ return Err(format!("{exits} runs of the herd ended with exit 0, want {RUNS}"));
+ }
+ let counts = scout_lines(&serial, CPUS)?;
+ eprintln!(" [scout] parsed: {counts:?}");
+ if counts.get("smi") != counts.get("end") {
+ return Err(format!("a report that began and did not end: {counts:?}"));
+ }
+ for owed in ["armed", "smi", "win", "win.opened_at", "win.closed_at", "shoot", "shoot.target", "nmi.asked", "lock"] {
+ if counts.get(owed).copied().unwrap_or(0) == 0 {
+ return Err(format!("no `scout: {owed}` line in the capture"));
+ }
+ }
+ mask_windows(&serial, CPUS)?;
+ eprintln!(" [scout] {:?}", common::irqcensus::windows_under(&serial, CPUS, &windows_load_exited()));
+ Ok(())
+}
+
+/// Every `scout:` line of `capture` by kind, each held to its shape: the fields
+/// it owes, in order, and every number a number.
+fn scout_lines(capture: &str, cpus: u32) -> Result<std::collections::BTreeMap<String, usize>, String> {
+ let mut counts = std::collections::BTreeMap::new();
+ let number = |line: &str, rest: &str, key: &str| -> Result<u64, String> {
+ let field = rest
+ .split_whitespace()
+ .find_map(|f| f.strip_prefix(key))
+ .ok_or_else(|| format!("no `{key}` field\nline: {line}"))?;
+ field.parse().map_err(|_| format!("`{key}{field}` is no number\nline: {line}"))
+ };
+ let owes = |line: &str, rest: &str, keys: &[&str]| -> Result<(), String> {
+ let mut at = 0;
+ for key in keys {
+ at += rest[at..].find(key).ok_or_else(|| format!("no `{key}` after byte {at}\nline: {line}"))? + key.len();
+ }
+ Ok(())
+ };
+ for line in capture.lines() {
+ let Some(rest) = line.split("scout: ").nth(1) else { continue };
+ let kind = rest.split_whitespace().next().unwrap_or("");
+ let named = match kind {
+ "armed" => {
+ number(line, rest, "long_ns=")?;
+ number(line, rest, "long_ticks=")?;
+ "armed".to_string()
+ }
+ "end" => {
+ number(line, rest, "at=")?;
+ number(line, rest, "lines=")?;
+ "end".to_string()
+ }
+ "smi" => {
+ number(line, rest, "at=")?;
+ for cpu in 0..cpus {
+ let key = format!("cpu{cpu}=");
+ let field = rest
+ .split_whitespace()
+ .find_map(|f| f.strip_prefix(key.as_str()))
+ .ok_or_else(|| format!("no `{key}` field\nline: {line}"))?;
+ let (count, at) =
+ field.split_once('@').ok_or_else(|| format!("no `@` in `{field}`\nline: {line}"))?;
+ count.parse::<u64>().map_err(|_| format!("`{count}` is no number\nline: {line}"))?;
+ at.parse::<u64>().map_err(|_| format!("`{at}` is no number\nline: {line}"))?;
+ }
+ "smi".to_string()
+ }
+ "win" if rest.contains(" close=") => {
+ owes(line, rest, &[" open=", " close=", " span_ns=", " smi=", " opener=", " closer=", " events="])?;
+ let (open, close, span) =
+ (number(line, rest, "open=")?, number(line, rest, "close=")?, number(line, rest, "span_ns=")?);
+ if close <= open || span.abs_diff(close - open) > 1 || span <= 2_000_000 {
+ return Err(format!("a window of {span} ns from {open} to {close}\nline: {line}"));
+ }
+ number(line, rest, "events=")?;
+ "win".to_string()
+ }
+ "win" => {
+ number(line, rest, "open=")?;
+ let part = ["opened_at:", "closed_at:", "during:", "after:"]
+ .into_iter()
+ .find(|part| rest.contains(part))
+ .ok_or_else(|| format!("a window line of no known part\nline: {line}"))?;
+ if rest.split(part).nth(1).is_none_or(|said| said.trim().is_empty()) {
+ return Err(format!("`{part}` says nothing\nline: {line}"));
+ }
+ format!("win.{}", part.trim_end_matches(':'))
+ }
+ "shoot" if rest.contains(" target=") => {
+ owes(line, rest, &[" gen=", " target=cpu", " ack=", " via=", " seen=", " trail: "])?;
+ number(line, rest, "ack=")?;
+ number(line, rest, "seen=")?;
+ "shoot.target".to_string()
+ }
+ "shoot" => {
+ owes(line, rest, &[" gen=", " origin=", " begin=", " end=", " span_ns=", " gap_ns=", " gap_at=", " probes="])?;
+ let (begin, end, span) =
+ (number(line, rest, "begin=")?, number(line, rest, "end=")?, number(line, rest, "span_ns=")?);
+ if end <= begin || span.abs_diff(end - begin) > 1 || span <= 2_000_000 {
+ return Err(format!("a shootdown of {span} ns from {begin} to {end}\nline: {line}"));
+ }
+ number(line, rest, "gap_ns=")?;
+ number(line, rest, "probes=")?;
+ "shoot".to_string()
+ }
+ "nmi" => {
+ owes(line, rest, &[" at=", " by=", " ring=", " if=", " who=", " masked_since=", " rip=", " stack: "])?;
+ number(line, rest, "at=")?;
+ number(line, rest, "masked_since=")?;
+ if rest.contains(" by=self ") { "nmi.self".to_string() } else { "nmi.asked".to_string() }
+ }
+ "lock" => {
+ owes(
+ line,
+ rest,
+ &[" lock=", " at=", " begin=", " end=", " span_ns=", " gap_ns=", " gap_at=", " holder=", " held_ns=", " holder_at=", " probes="],
+ )?;
+ let (begin, end, span) =
+ (number(line, rest, "begin=")?, number(line, rest, "end=")?, number(line, rest, "span_ns=")?);
+ if end <= begin || span.abs_diff(end - begin) > 1 || span <= 2_000_000 {
+ return Err(format!("a lock wait of {span} ns from {begin} to {end}\nline: {line}"));
+ }
+ number(line, rest, "held_ns=")?;
+ "lock".to_string()
+ }
+ "dropped" => {
+ for key in ["win=", "shoot=", "nmi=", "lock=", "unprinted="] {
+ number(line, rest, key)?;
+ }
+ "dropped".to_string()
+ }
+ other => return Err(format!("a `scout:` line of no known kind {other:?}\nline: {line}")),
+ };
+ *counts.entry(named).or_insert(0) += 1;
+ }
+ Ok(counts)
+}
+
/// Every CPU's `CR0` and `CR4`, against what a CPU running this kernel must
/// hold.
///
diff --git a/toyos-sched/src/windows.rs b/toyos-sched/src/windows.rs
index 8c80caffb..b792f8ab3 100644
--- a/toyos-sched/src/windows.rs
+++ b/toyos-sched/src/windows.rs
@@ -225,6 +225,19 @@ impl Windows {
}
}
+ /// SCOUT: the counter the open interrupts-off window opened at, or 0.
+ pub fn irqs_since(&self) -> u64 {
+ match self.irqs_off.load(Ordering::Relaxed) {
+ UNTRACKED => 0,
+ at => at,
+ }
+ }
+
+ /// SCOUT: the counter the open preemption-off window opened at, or 0.
+ pub fn preempt_since(&self) -> u64 {
+ self.preempt_off.load(Ordering::Relaxed)
+ }
+
/// 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) {
diff --git a/userland/test-runner/src/main.rs b/userland/test-runner/src/main.rs
index ac94998b9..45eb42ef5 100644
--- a/userland/test-runner/src/main.rs
+++ b/userland/test-runner/src/main.rs
@@ -36,6 +36,10 @@ static JOB: AtomicU32 = AtomicU32::new(0);
/// the boot its verdict.
static STOPPING: AtomicBool = AtomicBool::new(false);
+/// SCOUT: how many times one boot runs the herd, each a process of its own.
+const SCOUT_HERD_RUNS: usize = 40;
+const SCOUT_HERD: &str = "test_rs_ring_park_herd";
+
/// Nothing this process does can reach a log whose last line is already
/// written, so the loop stops where it is.
///
@@ -90,14 +94,21 @@ fn main() {
}
*RUNNING.lock().expect("the deadline thread does not panic holding this") =
job.clone();
- match run_one(job, &[], cap.as_ref()) {
- Ran::No => {
- give_the_machine_back(&format!("job {job:?} did not run"))
+ let runs = if job == SCOUT_HERD { SCOUT_HERD_RUNS } else { 1 };
+ for _ in 0..runs {
+ match run_one(job, &[], cap.as_ref()) {
+ Ran::No => {
+ give_the_machine_back(&format!("job {job:?} did not run"))
+ }
+ Ran::Spawned => {}
+ }
+ if STOPPING.load(Ordering::Acquire) {
+ stand_down();
}
- Ran::Spawned => {}
}
- if STOPPING.load(Ordering::Acquire) {
- stand_down();
+ if job == SCOUT_HERD {
+ println!("test-runner: the herd ran {runs} times, as the scout asks");
+ let _ = io::stdout().flush();
}
}
FINISHED.store(true, Ordering::Release); |
|
Linux's ACPI state on the T14, read by the orchestrator under Ubuntu (
|
|
Review, round 1, head BLOCKER
NOTE
REMOVE
SEND BACK |
… interrupt keep their own, with owners and exits Review round 1 of #681 found the T14's log-write file a third record of the spin `issues/hardware/xhci-waits-are-spins.md` and `a-disk-operation-can-spin-past-the-tlb-ack-tripwire-before-its-break` already held, with the cpu0 file's partition claims a fourth. - xhci-waits-are-spins.md is the one record: the spin, a disk call's masked syscall, the tripwire arithmetic (folded from the deleted a-disk-operation file), the T14 readings (folded from the deleted log-write file), init's partition claims and #649's readings that are this by reading. Owner: the small-kernel track's step 10. Exit: the tree has no kernel/src/drivers/xhci. Old content dropped as no longer true of the tree: the hot-plug enumeration's ~14 ms (it is stepped now) and the "I/O thread or asynchronous block layer" choice (the track chose usbd). - The cpu0 file keeps only the 3.8 ms PCI claim and is renamed inits-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms: its 6.5 ms is the spin's. Owner: the same track (stage 5's exit, step 10 unmasking cpu0's line). Exit: the mask_windows row's first report reads cpu0 under 3,817,265 ns after step 10. - The firmware file drops "and not under Linux" from its slug: Linux's 0 was read beside rtla timerlat --dma-latency 0 only. It states the Linux ACPI values as read (comment 5962768253), shows the stop by the two lock gaps instead of a late sample, names the T14 loop as owner of the row, and its exit reads the count from init's spawn to the stop's report, after any SMI_CMD write the bring-up makes. - Corrections: the writing CPU acknowledges 130 to 264 ns before each of the fourteen long shootdowns ends; the stop's report read two CPUs over 10 ms in 649-r5/1-head; the walk reads 1.03 to 1.98 ms without the log write and the firmware step. The instrument's control bullet is removed. - a-shutdown-on-a-held-usb-disk's citation of the deleted file follows it. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
Review, round 2, head
Round 1
BLOCKER
NOTE
REMOVE
SEND BACK |
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
Evidence for the PCI claim's exit bound (
|
… tripwire's fix before step 10; the PCI and firmware exits are bounds a fix must clear Round 3 of #681's review (comment 5963284260). - issues/audio/disk-wait-pins-a-cpu.md was a second open record of the xHCI spin. Its one live claim is folded into issues/hardware/xhci-waits-are-spins.md: SYS_FSYNC on a partition claim (partition_fsync, kernel/src/object/ops.rs) is a cache flush through xhci::storage_flush under XHCI, inside a masked syscall, and logd's fsync is one, made by the LOG fsd on its claim (traced logd store.rs sync_all -> std fs toyos.rs Served fsync -> fsd FSYNC -> disk.rs PartitionDev::sync -> SYS_FSYNC). The rest of it is gone from the tree: log_file::SINK and fat32_adapter::VOLUMES no longer exist, the partition fsync takes no VFS, and io-depth-probe is no kernel feature. Its two citations: scheduler-pass-blocks-in-xhci.md now points at the surviving record; the-global-pipe-lock-spans-a-user-copy.md's clause naming it and io-depth-probe is deleted. In the scout boot no SYS_FSYNC window reached 2 ms (none of the 101 opened at sys(15)). - The spin's list of what still spins names a disk's bind after boot, which still blocks in a scheduler pass (msc::bind's doc, poll_if_pending's doc). - The fold's lost exit is restored beside step 10's, under the same owner: one operation's IF-clear spin under DEAF_CPU by construction, shown by a staged boot. The orchestrator ruled the cheaper fix stays owed. - The PCI claim's exit is a bound a fix must clear, 223 us, derived from 24 vendor-ID reads at the enumeration's bulk rate (7,871 absent reads in at most 73 ms), with MSR_SMI_COUNT unmoved so a firmware step cannot fail a fixed claim. The same enumeration read the 31 to 38 absent functions behind 00:1c.4 at about 80 to 160 us a read, the order of the claim's 159 us; the file says so. Lines quoted on #681, comment 5966492598. - The firmware issue's interval opens after the boot's last SMI_CMD write, whoever makes it, and its owner line says the T14 loop owns only the reading and the fix has none in the tree yet: the owner approved a scout of the switch to ACPI mode, and the fix's ownership is put to him with its result. - issues/kernel/the-scheduler-and-the-clocks-never-talk.md cited an "ACPI/power track (task #136)" that has no file; the citation goes and the AML interpreter idle-cpus-enter-the-c-states-cst-names.md points at stays. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
The scout's window trails (kernel.log, `scout: win` lines) carry the LOG fsd's SYS_FSYNC after 15 of its windows; in 7 the next event is a contended `lock(src/drivers/xhci/mod.rs:1689 …)`, which at c59e09e is `with_disk_by`'s `XHCI.lock()`. The instrument records a lock only when it spins (scout.patch, SpinWatch: "A contended `Lock::lock`'s look at its own spin"), so the other 8 say nothing either way. No window of 2 ms or more opened at syscall 15. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
Evidence for the LOG fsd's In 7 of them |
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
Review, round 3, head
Round 2
The out-of-scope file is not a fourth record of this spin.
BLOCKER
NOTE
SEND BACK |
…rmware's spans two periods, and the missing AML interpreter has a file Round 3 of #681's review. - The PCI claim's exit bounded the syscall from entry to return at 223 us, from the enumeration's reads of absent functions on buses no bridge decodes, a population the claim never reads: it reads 24 present functions, and its one reading is 159 us a read. A fix in the owner's stage 5 shape opens interrupts between those reads, closes the title's defect, and would still have failed that bound. The exit now bounds the longest interrupts-off window inside the claim at one register access, with MSR_SMI_COUNT unmoved across it; that access's figure comes from the claim's own reads timed on the T14, which nobody has timed. The enumeration-rate derivation goes. - The firmware issue's exit had no minimum interval: two readings closer than one 2.2 s period agree with nothing fixed. The interval now spans at least 4.444 s, twice the longest period read (2,221,576,672 ns). - No file recorded that ToyOS interprets no AML, and the two tracks that wait on it pointed at each other for it. New issues/kernel/toyos-interprets-no-aml.md says what is missing and who waits; both lines point at it. Filing it starts no work. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
Review, round 4, head
Round 3
Round 3's NOTE 2 is met at The new file's kind is one
BLOCKER
NOTENone. REMOVE
SEND BACK |
…st of who waits The owner's line "own AML interpreter, battery first" sat in issues/kernel/the-scheduler-and-the-clocks-never-talk.md beside the false "task #136" label until 995b368 removed both. It came from the 2026-08-16 direction conversation that 0ee814f records, and the AML track is now its home: without it the next agent could take a third-party interpreter or start from _CST against a recorded direction. The "Two tracks wait on it" line goes: git grep answers who waits, and the count was already short (the touchpad's GpioInt is a _CRS descriptor, and HID over I2C takes its descriptor address from _DSM). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
The firmware-interrupt scout on the T14, run by the orchestrator on the owner's go. A throwaway patch that never lands (
So the periodic firmware interrupt is the firmware's legacy-mode work, and the ACPI enable handshake stops it. The switch itself costs one firmware interrupt and 2.13 ms until Readbacks: |
The orchestrator's scout on the owner's go (comment 5966817345 on #681) booted main at 73282fa on the T14 twice, each boot 30 s idle then 30 s with a spinning thread per CPU. With nothing written the firmware leaves the machine in legacy mode (PM1a_CNT 0x0000, SCI_EN clear, all boot) and MSR_SMI_COUNT rises once every 2.2 s, idle and busy alike, 27 in 60 s. With ACPI_ENABLE written to SMI_CMD, SCI_EN reads set 2.13 ms later, the write costs one firmware interrupt, and the count then stays flat on every CPU for 61 s. That replaces "neither SCI_EN nor SMI_EN has been read" and "the cause is not known". Who owns the fix is still the owner's to rule. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
…s firmware fix The owner ruled on the firmware scout (#681, comment 5966817345): the ACPI enable lands as the first stage of the ACPI track, together with a userland server that claims the SCI and handles the power button, a fixed event that needs no AML, so nothing the firmware does in legacy mode today is lost. The AML interpreter, battery first (his direction of 0ee814f), follows as later stages. He chose this over landing the write alone with the events masked, and over waiting for the AML work. toyos-interprets-no-aml no longer says what the track is, so it becomes toyos-runs-the-machine-in-acpi-mode-and-interprets-its-aml, keeps its opened date and stays an open track. Its two citations move with it. The firmware issue's fix is owned by that track's stage 1; its exit is stage 1's first half. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
Review, round 5, head
Round 4
Round 4's REMOVE 2 is made: the "Two tracks wait on it" line does not survive the rename. REMOVE 3 is made too: the PR body no longer carries the enumeration-reads sentence. BLOCKERNone. NOTE
REMOVE
LAND AFTER NAMED CHANGES |
|
Firmware scout, |
|
Firmware scout, |
|
Firmware scout patch diff --git a/kernel/Cargo.toml b/kernel/Cargo.toml
index b3c602b75..530d4cc19 100644
--- a/kernel/Cargo.toml
+++ b/kernel/Cargo.toml
@@ -140,6 +140,13 @@ sched-check = ["toyos-sched/check"]
# count crossing zero, on every entry and exit: a kernel being measured for
# anything else must not carry it.
mask-windows = []
+# SCOUT, never landed: `arch/x86_64/smi_scout.rs` reads every CPU's
+# `MSR_SMI_COUNT` beside the ACPI, SMI and TCO registers; `smi-switch` also
+# writes `ACPI_ENABLE` to `SMI_CMD` early.
+smi-scout = []
+smi-switch = ["smi-scout"]
+# QEMU only: `ACPI_DISABLE` first, so `smi-switch`'s write runs on q35.
+smi-rehearse = ["smi-switch"]
# 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/x86_64/idt/timer.rs b/kernel/src/arch/x86_64/idt/timer.rs
index 1ce8cb24f..743a63fae 100644
--- a/kernel/src/arch/x86_64/idt/timer.rs
+++ b/kernel/src/arch/x86_64/idt/timer.rs
@@ -76,10 +76,12 @@ pub(super) extern "sysv64" fn timer_entry() {
"pop rcx",
"pop rax",
"iretq",
- #[cfg(not(feature = "mask-windows"))]
+ #[cfg(not(any(feature = "mask-windows", feature = "smi-scout")))]
deadline = sym crate::deadline::poll,
#[cfg(feature = "mask-windows")]
deadline = sym ring0_tick,
+ #[cfg(all(feature = "smi-scout", not(feature = "mask-windows")))]
+ deadline = sym smi_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,
@@ -101,11 +103,20 @@ extern "sysv64" fn ring0_tick() {
crate::windows::irqs_unmasking();
}
+/// SCOUT: the Ring 0 branch's Rust half under `smi-scout`.
+#[cfg(all(feature = "smi-scout", not(feature = "mask-windows")))]
+extern "sysv64" fn smi_ring0_tick() {
+ crate::arch::smi_scout::sample();
+ crate::deadline::poll();
+}
+
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);
+ #[cfg(feature = "smi-scout")]
+ crate::arch::smi_scout::sample();
// 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.
crate::deadline::poll();
diff --git a/kernel/src/arch/x86_64/ioapic.rs b/kernel/src/arch/x86_64/ioapic.rs
index 17f797b42..0a2e9b339 100644
--- a/kernel/src/arch/x86_64/ioapic.rs
+++ b/kernel/src/arch/x86_64/ioapic.rs
@@ -301,6 +301,14 @@ pub fn route(
Ok(())
}
+/// SCOUT: `gsi`'s redirection entry as the chip holds it.
+#[cfg(feature = "smi-scout")]
+pub fn rte(gsi: Gsi) -> Option<u64> {
+ let topology = TOPOLOGY.lock();
+ let (unit, n) = locate(&topology, gsi).ok()?;
+ Some(u64::from(unit.read(REG_REDTBL + 2 * n + 1)) << 32 | u64::from(unit.read(REG_REDTBL + 2 * n)))
+}
+
pub fn set_masked(gsi: Gsi, masked: bool) -> Result<(), RouteError> {
let topology = TOPOLOGY.lock();
let (unit, n) = locate(&topology, gsi)?;
diff --git a/kernel/src/arch/x86_64/mod.rs b/kernel/src/arch/x86_64/mod.rs
index 5d9a48a9a..4afc99137 100644
--- a/kernel/src/arch/x86_64/mod.rs
+++ b/kernel/src/arch/x86_64/mod.rs
@@ -31,6 +31,8 @@ pub mod percpu;
pub mod pmu;
pub mod power;
pub mod rtc;
+#[cfg(feature = "smi-scout")]
+pub mod smi_scout;
pub mod smp;
pub mod switch;
pub mod syscall;
diff --git a/kernel/src/arch/x86_64/smi_scout.rs b/kernel/src/arch/x86_64/smi_scout.rs
new file mode 100644
index 000000000..6230f4738
--- /dev/null
+++ b/kernel/src/arch/x86_64/smi_scout.rs
@@ -0,0 +1,331 @@
+//! SCOUT, never landed: what makes the firmware interrupt every CPU, read
+//! without writing anything but (under `smi-switch`) `ACPI_ENABLE` to
+//! `SMI_CMD`.
+//!
+//! Every CPU stores its own `MSR_SMI_COUNT` and the time it read it at each
+//! timer-vector interrupt, which a kick is too; a report kicks every other CPU,
+//! waits a bounded while for their fresh readings, and prints one `smi: report`
+//! line beside the registers that can say where an SMI comes from. Nothing here
+//! writes a TCO register or `SMI_EN`.
+
+use core::arch::asm;
+use core::fmt;
+use core::sync::atomic::{AtomicBool, AtomicU16, AtomicU32, AtomicU64, AtomicU8, Ordering::{Acquire, Relaxed, Release}};
+
+use super::{cpu, ioapic, irqchip, percpu};
+use crate::drivers::pci::PciDevice;
+use crate::log;
+
+const MSR_SMI_COUNT: u32 = 0x34;
+const MAX_CPUS: usize = crate::sched::MAX_CPUS;
+
+/// `PM1_CNT.SCI_EN`.
+const SCI_EN: u16 = 1 << 0;
+/// `SMI_EN` and `SMI_STS` from the PM1a event block's base, where Linux read
+/// `SMI_EN` on the T14 and where ICH9 keeps both.
+const SMI_EN_OFF: u16 = 0x30;
+const SMI_STS_OFF: u16 = 0x34;
+/// Past this the switch has failed.
+#[cfg(feature = "smi-switch")]
+const SWITCH_BOUND_NS: u64 = 3_000_000_000;
+/// How long a report waits for every other CPU's reading after its kick.
+const FRESH_BOUND_NS: u64 = 5_000_000;
+#[cfg(feature = "smi-switch")]
+const RTE_MASKED: u64 = 1 << 16;
+
+/// FADT offsets, ACPI 6.5 Table 5.9.
+const SCI_INT: usize = 46;
+const SMI_CMD: usize = 48;
+const ACPI_ENABLE: usize = 52;
+const ACPI_DISABLE: usize = 53;
+const PM1A_EVT_BLK: usize = 56;
+const PM1A_CNT_BLK: usize = 64;
+const PM_TMR_BLK: usize = 76;
+const GPE0_BLK: usize = 80;
+const PM1_EVT_LEN: usize = 88;
+const GPE0_BLK_LEN: usize = 92;
+const FLAGS: usize = 112;
+const HW_REDUCED_ACPI: u32 = 1 << 20;
+
+struct Slot {
+ count: AtomicU64,
+ /// Nanoseconds since boot of the read, 0 for never.
+ at: AtomicU64,
+}
+
+static SLOTS: [Slot; MAX_CPUS] = [const { Slot { count: AtomicU64::new(0), at: AtomicU64::new(0) } }; MAX_CPUS];
+
+/// Written by [`early`] on the BSP before any AP runs.
+static PM1A_EVT: AtomicU16 = AtomicU16::new(0);
+static PM1_EN_OFF: AtomicU16 = AtomicU16::new(0);
+static PM1A_CNT: AtomicU16 = AtomicU16::new(0);
+static GPE0: AtomicU16 = AtomicU16::new(0);
+static GPE0_HALF: AtomicU8 = AtomicU8::new(0);
+static SMI_EN_PORT: AtomicU16 = AtomicU16::new(0);
+static TCO_PORT: AtomicU16 = AtomicU16::new(0);
+static SCI_GSI: AtomicU32 = AtomicU32::new(u32::MAX);
+/// The chipset is q35's LPC bridge, the one machine [`rehearse`] may act on.
+static Q35: AtomicBool = AtomicBool::new(false);
+const Q35_LPC: u16 = 0x2918;
+static SEQ: AtomicU32 = AtomicU32::new(0);
+
+/// This CPU's reading, from the timer vector's entry in either ring.
+pub fn sample() {
+ let me = percpu::cpu_id() as usize;
+ let Some(slot) = SLOTS.get(me) else { return };
+ slot.count.store(cpu::rdmsr(MSR_SMI_COUNT), Relaxed);
+ slot.at.store(crate::clock::nanos_since_boot().max(1), Release);
+}
+
+fn inl(port: u16) -> u32 {
+ let value: u32;
+ // SAFETY: one `in` into the declared output, no memory operand; a read commands nothing on the ports this reads.
+ unsafe { asm!("in eax, dx", out("eax") value, in("dx") port, options(nomem, nostack, preserves_flags)) };
+ value
+}
+
+fn port_of(what: &str, block: u32) -> u16 {
+ u16::try_from(block).unwrap_or_else(|_| panic!("smi: the FADT puts {what} at {block:#x}, past the port space"))
+}
+
+/// Why a report was taken.
+#[derive(Clone, Copy)]
+pub enum Why {
+ Early,
+ #[cfg(feature = "smi-switch")]
+ Switched,
+ Ready,
+ Exit(u32),
+ Stop,
+}
+
+impl fmt::Display for Why {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ match self {
+ Self::Early => f.write_str("early"),
+ #[cfg(feature = "smi-switch")]
+ Self::Switched => f.write_str("switched"),
+ Self::Ready => f.write_str("ready"),
+ Self::Exit(pid) => write!(f, "exit pid={pid}"),
+ Self::Stop => f.write_str("stop"),
+ }
+ }
+}
+
+/// The FADT's power-management blocks, the chipset's SMI and TCO ports and
+/// the SCI's line, each said once; then the first report, and under
+/// `smi-switch` the switch and a report after it.
+pub fn early(rsdp_addr: u64, devices: &[PciDevice]) {
+ let fadt = toyos_acpi::find_table(crate::drivers::acpi::direct_phys(), rsdp_addr, b"FACP", FLAGS + 4)
+ .unwrap_or_else(|e| panic!("smi: the FADT is unreadable: {e:?}"));
+ let u8_at = |at| fadt.byte(at).expect("inside the length asked for");
+ let u32_at = |at| fadt.u32_at(at).expect("inside the length asked for");
+ let sci_int = fadt.u16_at(SCI_INT).expect("inside the length asked for");
+ let (smi_cmd, enable, disable) = (u32_at(SMI_CMD), u8_at(ACPI_ENABLE), u8_at(ACPI_DISABLE));
+ let (evt, evt_len, cnt) = (u32_at(PM1A_EVT_BLK), u8_at(PM1_EVT_LEN), u32_at(PM1A_CNT_BLK));
+ let (gpe0, gpe0_len, flags) = (u32_at(GPE0_BLK), u8_at(GPE0_BLK_LEN), u32_at(FLAGS));
+ log!(
+ "smi: fadt sci_int={sci_int} smi_cmd={smi_cmd:#x} acpi_enable={enable:#04x} acpi_disable={disable:#04x} \
+ pm1a_evt={evt:#x} pm1_evt_len={evt_len} pm1a_cnt={cnt:#x} pm_tmr={:#x} gpe0={gpe0:#x} gpe0_len={gpe0_len} \
+ flags={flags:#x} hw_reduced={}",
+ u32_at(PM_TMR_BLK),
+ u8::from(flags & HW_REDUCED_ACPI != 0),
+ );
+ let evt = port_of("PM1a_EVT_BLK", evt);
+ PM1A_EVT.store(evt, Relaxed);
+ PM1_EN_OFF.store(u16::from(evt_len / 2), Relaxed);
+ PM1A_CNT.store(port_of("PM1a_CNT_BLK", cnt), Relaxed);
+ GPE0.store(port_of("GPE0_BLK", gpe0), Relaxed);
+ GPE0_HALF.store(gpe0_len / 2, Relaxed);
+
+ match devices.iter().find_map(|d| toyos_tco::chipset(d.vendor_id(), d.device_id()).map(|row| (d, row))) {
+ Some((pci, row)) => {
+ SMI_EN_PORT.store(evt + SMI_EN_OFF, Relaxed);
+ let base = pci.read_config_u32(u64::from(row.base_reg));
+ let enable =
+ if row.enable.reg == row.base_reg { base } else { pci.read_config_u32(u64::from(row.enable.reg)) };
+ if row.device == Q35_LPC {
+ Q35.store(true, Relaxed);
+ }
+ let (vendor, device, smi_en) = (row.vendor, row.device, evt + SMI_EN_OFF);
+ match row.port(base, enable) {
+ Ok(port) => {
+ TCO_PORT.store(port, Relaxed);
+ log!("smi: chipset {vendor:04x}:{device:04x}, so SMI_EN at {smi_en:#x} and the TCO block at {port:#x}");
+ }
+ Err(why) => log!("smi: chipset {vendor:04x}:{device:04x}, so SMI_EN at {smi_en:#x}, and no TCO port ({why:?})"),
+ }
+ }
+ None => log!("smi: no chipset toyos_tco knows, so SMI_EN, SMI_STS and the TCO block go unread"),
+ }
+
+ match u8::try_from(sci_int).ok().and_then(ioapic::gsi_for_isa_irq) {
+ Some(line) => {
+ SCI_GSI.store(line.gsi.0, Relaxed);
+ log!("smi: the SCI is ISA irq {sci_int}, gsi {} {:?}/{:?}", line.gsi.0, line.trigger, line.polarity);
+ }
+ None => log!("smi: the SCI's irq {sci_int} reaches no I/O APIC line"),
+ }
+
+ report(Why::Early);
+ #[cfg(feature = "smi-switch")]
+ switch(smi_cmd, enable, disable);
+}
+
+/// ACPI's legacy-to-ACPI handshake: `ACPI_ENABLE` to `SMI_CMD`, then `SCI_EN`
+/// waited for, bounded.
+#[cfg(feature = "smi-switch")]
+fn switch(smi_cmd: u32, enable: u8, disable: u8) {
+ let cnt_port = PM1A_CNT.load(Relaxed);
+ #[cfg(feature = "smi-rehearse")]
+ rehearse(smi_cmd, disable);
+ let cnt = cpu::inw(cnt_port);
+ if cnt & SCI_EN != 0 {
+ log!("smi: switch: SCI_EN is already set (PM1a_CNT={cnt:#06x}), so nothing is written");
+ return;
+ }
+ if smi_cmd == 0 || (enable == 0 && disable == 0) {
+ log!("smi: switch: the FADT names no switch (SMI_CMD={smi_cmd:#x} ACPI_ENABLE={enable:#04x}), so nothing is written");
+ return;
+ }
+ let gsi = SCI_GSI.load(Relaxed);
+ let rte = ioapic::rte(ioapic::Gsi(gsi)).unwrap_or_else(|| panic!("smi: switch: the SCI's gsi {gsi} has no entry to hold masked"));
+ assert!(rte & RTE_MASKED != 0, "smi: switch: the SCI's entry {rte:#018x} is not masked, and nothing here handles it");
+ let port = port_of("SMI_CMD", smi_cmd);
+ let before = cpu::rdmsr(MSR_SMI_COUNT);
+ let wrote_at = crate::clock::nanos_since_boot();
+ // SAFETY: the FADT's own `SMI_CMD` and `ACPI_ENABLE`, the write ACPI has OSPM make to leave legacy mode; nothing else is written.
+ unsafe { cpu::outb(port, enable) };
+ let after = cpu::rdmsr(MSR_SMI_COUNT);
+ let set_at = loop {
+ let now = crate::clock::nanos_since_boot();
+ if cpu::inw(cnt_port) & SCI_EN != 0 {
+ break now;
+ }
+ assert!(
+ now - wrote_at < SWITCH_BOUND_NS,
+ "smi: switch: SCI_EN still clear {SWITCH_BOUND_NS} ns after {enable:#04x} went to SMI_CMD {port:#x} \
+ (PM1a_CNT={:#06x})",
+ cpu::inw(cnt_port)
+ );
+ core::hint::spin_loop();
+ };
+ log!(
+ "smi: switch: wrote {enable:#04x} to SMI_CMD {port:#x} at={wrote_at}, SCI_EN read set {} ns later \
+ (PM1a_CNT={:#06x}); this CPU's MSR_SMI_COUNT {before} before the write, {after} after it, {} once set",
+ set_at - wrote_at,
+ cpu::inw(cnt_port),
+ cpu::rdmsr(MSR_SMI_COUNT)
+ );
+ report(Why::Switched);
+}
+
+/// QEMU's alone, refused anywhere else: q35's firmware hands over with `SCI_EN`
+/// set, so `ACPI_DISABLE` clears it for [`switch`]'s write to run.
+#[cfg(feature = "smi-rehearse")]
+fn rehearse(smi_cmd: u32, disable: u8) {
+ assert!(Q35.load(Relaxed), "smi: rehearse: QEMU's q35 only, and this is not one");
+ let cnt_port = PM1A_CNT.load(Relaxed);
+ let port = port_of("SMI_CMD", smi_cmd);
+ // SAFETY: q35's own `SMI_CMD` and `ACPI_DISABLE`, on a guest.
+ unsafe { cpu::outb(port, disable) };
+ let cnt = cpu::inw(cnt_port);
+ assert!(cnt & SCI_EN == 0, "smi: rehearse: SCI_EN still set after ACPI_DISABLE (PM1a_CNT={cnt:#06x})");
+ log!("smi: rehearse: wrote {disable:#04x} to SMI_CMD {port:#x}, PM1a_CNT={cnt:#06x}");
+}
+
+/// One `smi: report` line: every register, and every CPU's count as fresh as
+/// a kick and [`FRESH_BOUND_NS`] get it. Thread context only: it takes the I/O
+/// APIC's lock.
+pub fn report(why: Why) {
+ let seq = SEQ.fetch_add(1, Relaxed);
+ let me = percpu::cpu_id();
+ let asked = crate::clock::nanos_since_boot();
+ sample();
+ let cpus = crate::smp::cpu_count().min(MAX_CPUS as u32);
+ for c in 0..cpus {
+ if c != me {
+ irqchip::kick_cpu(c);
+ }
+ }
+ let stale = |c: u32| SLOTS[c as usize].at.load(Acquire) < asked;
+ while (0..cpus).any(stale) && crate::clock::nanos_since_boot() - asked < FRESH_BOUND_NS {
+ core::hint::spin_loop();
+ }
+ log!("smi: report={seq} why={why} on=cpu{me} at={asked} {} sci_rte={}{}", Regs, Rte, Counts(cpus));
+}
+
+/// The SCI's redirection entry, `-` where it has none.
+struct Rte;
+
+impl fmt::Display for Rte {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ match SCI_GSI.load(Relaxed) {
+ u32::MAX => f.write_str("-"),
+ gsi => match ioapic::rte(ioapic::Gsi(gsi)) {
+ Some(rte) => write!(f, "{rte:#018x}"),
+ None => f.write_str("-"),
+ },
+ }
+ }
+}
+
+/// Every power-management, SMI and TCO register, read now.
+struct Regs;
+
+impl fmt::Display for Regs {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ let evt = PM1A_EVT.load(Relaxed);
+ let cnt = cpu::inw(PM1A_CNT.load(Relaxed));
+ write!(
+ f,
+ "sci_en={} pm1_cnt={cnt:#06x} pm1_sts={:#06x} pm1_en={:#06x}",
+ cnt & SCI_EN,
+ cpu::inw(evt),
+ cpu::inw(evt + PM1_EN_OFF.load(Relaxed))
+ )?;
+ match SMI_EN_PORT.load(Relaxed) {
+ 0 => f.write_str(" smi_en=- smi_sts=-")?,
+ _ => write!(f, " smi_en={:#010x} smi_sts={:#010x}", inl(evt + SMI_EN_OFF), inl(evt + SMI_STS_OFF))?,
+ }
+ let (gpe0, half) = (GPE0.load(Relaxed), u16::from(GPE0_HALF.load(Relaxed)));
+ for (name, from) in [("gpe0_sts", gpe0), ("gpe0_en", gpe0 + half)] {
+ write!(f, " {name}=")?;
+ if gpe0 == 0 || half == 0 {
+ f.write_str("-")?;
+ continue;
+ }
+ // Byte-wide, which every GPE register answers; the lowest address first.
+ for i in 0..half.min(16) {
+ write!(f, "{}{:02x}", if i > 0 && i % 4 == 0 { "." } else { "" }, cpu::inb(from + i))?;
+ }
+ }
+ match TCO_PORT.load(Relaxed) {
+ 0 => f.write_str(" tco=-"),
+ port => write!(
+ f,
+ " tco_rld={:#06x} tco_tmr={:#06x} tco1_cnt={:#06x} tco1_sts={:#06x} tco2_sts={:#06x}",
+ cpu::inw(port + toyos_tco::TCO_RLD),
+ cpu::inw(port + toyos_tco::TCO_TMR),
+ cpu::inw(port + toyos_tco::TCO1_CNT),
+ cpu::inw(port + toyos_tco::TCO1_STS),
+ cpu::inw(port + toyos_tco::TCO2_STS)
+ ),
+ }
+ }
+}
+
+/// ` cpuN=count@ns` for every CPU, `cpuN=-` for one that never read.
+struct Counts(u32);
+
+impl fmt::Display for Counts {
+ fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+ for (c, slot) in SLOTS.iter().enumerate().take(self.0 as usize) {
+ match slot.at.load(Acquire) {
+ 0 => write!(f, " cpu{c}=-")?,
+ at => write!(f, " cpu{c}={}@{at}", slot.count.load(Relaxed))?,
+ }
+ }
+ Ok(())
+ }
+}
diff --git a/kernel/src/main.rs b/kernel/src/main.rs
index 91566f5c4..c2ea75cd2 100644
--- a/kernel/src/main.rs
+++ b/kernel/src/main.rs
@@ -430,6 +430,8 @@ pub(crate) unsafe extern "C" fn kernel_main(kernel_args: &KernelArgs) -> ! {
// Before storage and everything under it: what it covers is the rest of this
// boot, and a wedge down there is the reason to have one.
arch::watchdog::init(&pci_devices);
+ #[cfg(feature = "smi-scout")]
+ arch::smi_scout::early(kernel_args.rsdp_addr, &pci_devices);
file_cache::init();
gpt::init(kernel_args);
@@ -561,6 +563,8 @@ pub(crate) unsafe extern "C" fn kernel_main(kernel_args: &KernelArgs) -> ! {
if actuator::tlb_shootdown_bench() {
arch::tlb::bench();
}
+ #[cfg(feature = "smi-scout")]
+ arch::smi_scout::report(arch::smi_scout::Why::Ready);
crate::scheduler::enter_idle_loop();
}
diff --git a/kernel/src/process.rs b/kernel/src/process.rs
index 54ef3ee91..29fced182 100644
--- a/kernel/src/process.rs
+++ b/kernel/src/process.rs
@@ -1019,6 +1019,8 @@ fn teardown_resources(
thread_data_arc: &Arc<Lock<ThreadData>>,
pid: Pid,
) -> (u64, u64) {
+ #[cfg(feature = "smi-scout")]
+ crate::arch::smi_scout::report(crate::arch::smi_scout::Why::Exit(pid.raw()));
// Never hold ThreadData + ProcessData at once.
let (syscall_total, syscall_total_ns, syscall_counts) = {
let mut tdata = thread_data_arc.lock();
diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs
index e79004b43..c801d3904 100644
--- a/kernel/src/syscall/machine.rs
+++ b/kernel/src/syscall/machine.rs
@@ -73,6 +73,8 @@ fn quiesce(last: &str) -> Result<(), SyscallError> {
// The final census: no process runs after this to report another.
crate::irq_census::log_census();
crate::drivers::panic_console::log_census();
+ #[cfg(feature = "smi-scout")]
+ crate::arch::smi_scout::report(crate::arch::smi_scout::Why::Stop);
// A shortfall is the budget spent, not the reset refused: it is said at
// alert level, and the reset lands anyway.
if stopped.stopped_the_machine() {
diff --git a/src/build.rs b/src/build.rs
index 1c6fd4bf6..3852a0c97 100644
--- a/src/build.rs
+++ b/src/build.rs
@@ -1358,8 +1358,8 @@ fn declared_kernel_features(root: &Path) -> Vec<String> {
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; 3] =
- ["", "boot-actuators,test-actuators", MASK_WINDOWS_KERNEL[0]];
+pub const TEST_SUITE_KERNEL_BUILDS: [&str; 6] =
+ ["", "boot-actuators,test-actuators", MASK_WINDOWS_KERNEL[0], "smi-scout", "smi-switch", "smi-rehearse"];
/// The shipping kernel with the windows' instrument and nothing else, for
/// [`SCHED_CHECK_KERNEL`]'s reason: one spelling, so one build.
diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs
index 4abf78d63..c7e0b1023 100644
--- a/tests/common/qemu.rs
+++ b/tests/common/qemu.rs
@@ -158,7 +158,7 @@ pub fn boot_census() -> (u32, u32, Vec<String>) {
/// 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] =
+pub const DECLARED_KERNEL_BUILDS: [&str; 6] =
toyos_build::build::TEST_SUITE_KERNEL_BUILDS;
/// How many guests the run may have up at once.
diff --git a/tests/smiscoutcase/system.toml b/tests/smiscoutcase/system.toml
new file mode 100644
index 000000000..3c858d3ca
--- /dev/null
+++ b/tests/smiscoutcase/system.toml
@@ -0,0 +1,28 @@
+# SCOUT, never landed: `tests/jobcase` with the `smi_scout` row's job list,
+# for its QEMU probe.
+[boot]
+start = ["logd", "blockd", "fsd", "test-runner"]
+
+[programs.logd]
+service = true
+syscap = ["logread"]
+
+[programs.test-runner]
+receives = ["power"]
+args = ["--bound-ms=110000", "test_rs_smi_stretch", "reboot"]
+
+[programs.toybox]
+
+[symlinks]
+"bin/reboot" = "/system/bin/toybox"
+
+[programs.blockd]
+service = true
+restart = true
+serves = ["block"]
+devices = ["pci:1b36:0010"]
+
+[programs.fsd]
+restart = true
+roles = ["data", "log", "boot"]
+receives = ["block"]
diff --git a/tests/toyos-rust-tests/src/bin/smi_stretch.rs b/tests/toyos-rust-tests/src/bin/smi_stretch.rs
new file mode 100644
index 000000000..5d1bd341f
--- /dev/null
+++ b/tests/toyos-rust-tests/src/bin/smi_stretch.rs
@@ -0,0 +1,55 @@
+//! SCOUT, never landed: two stretches an `smi-scout` kernel reports across,
+//! each marked every [`MARK_EVERY`] by a child of this binary whose exit is the
+//! kernel's report. First plain idle, every CPU free to halt; then every CPU
+//! kept in C0 by a spinning thread of its own.
+
+use std::process::Command;
+use std::sync::atomic::{AtomicBool, Ordering};
+use std::sync::Arc;
+use std::thread;
+use std::time::{Duration, Instant};
+
+const STRETCH: Duration = Duration::from_secs(30);
+const MARK_EVERY: Duration = Duration::from_secs(3);
+const ME: &str = "/system/bin/test_rs_smi_stretch";
+const MARK: &str = "mark";
+
+fn main() {
+ if std::env::args().nth(1).as_deref() == Some(MARK) {
+ return;
+ }
+ stretch("idle");
+ let stop = Arc::new(AtomicBool::new(false));
+ // The kernel's own count: std's `available_parallelism` answers 1 here.
+ let cpus = toyos_abi::syscall::cpu_count();
+ let spinners: Vec<_> = (0..cpus)
+ .map(|_| {
+ let stop = Arc::clone(&stop);
+ thread::spawn(move || {
+ while !stop.load(Ordering::Relaxed) {
+ std::hint::spin_loop();
+ }
+ })
+ })
+ .collect();
+ println!("smi_stretch: {cpus} spinners started");
+ stretch("busy");
+ stop.store(true, Ordering::Relaxed);
+ for spinner in spinners {
+ spinner.join().expect("a spinner does not panic");
+ }
+ println!("smi_stretch: done");
+}
+
+fn stretch(name: &str) {
+ let start = Instant::now();
+ let marks = (STRETCH.as_millis() / MARK_EVERY.as_millis()) as u32;
+ for k in 0..=marks {
+ if let Some(left) = (start + MARK_EVERY * k).checked_duration_since(Instant::now()) {
+ thread::sleep(left);
+ }
+ println!("smi_stretch: {name} mark {k} of {marks}");
+ let status = Command::new(ME).arg(MARK).status().expect("the mark child spawns");
+ assert!(status.success(), "the mark child exited {status:?}");
+ }
+}
diff --git a/tests/toyos.rs b/tests/toyos.rs
index f1e5ee8f9..8f6837b79 100644
--- a/tests/toyos.rs
+++ b/tests/toyos.rs
@@ -61,6 +61,8 @@ const ACTUATOR_KERNEL: &[&str] = toyos_build::build::TEST_KERNEL;
// Rust helper binaries that are spawned by tests, not tests themselves.
const RUST_SKIP: &[&str] = &[
+ // SCOUT: the `smi_scout` row's job.
+ "smi_stretch",
// **Its exit code is a measurement, not a verdict**, and the shared block
// judges every member on `exit=0` alone — so it would red on every boot
// that measured anything. It also needs the real-time band, which only
@@ -188,6 +190,11 @@ const MACHINE_TESTS: &[&str] = &[
// no way to turn it back on, so only a machine QEMU reports stopping can
// be asked. `machine_soft_off_decoded` reads the T14's own decode.
"machine_shutdown",
+ // SCOUT: the `smi_scout` row's two kernels and job under TCG, read for their lines' shape.
+ "x86_smi_scout_a",
+ "x86_smi_scout_b",
+ // SCOUT: arm B's write and wait, run on q35 by clearing `SCI_EN` first.
+ "x86_smi_scout_rehearsal",
];
/// **The metal profile**: which registrations run on the ThinkPad T14, what
@@ -255,6 +262,17 @@ const METAL: &[(&str, metal::Metal)] = &[
"mask_windows",
metal::Metal { arms: WINDOWSCASE, judge: |b| windows_on_metal(b[0]) },
),
+ (
+ // SCOUT: arm A reads, arm B switches the firmware to ACPI mode first.
+ "smi_scout",
+ metal::Metal {
+ arms: SMI_SCOUT,
+ judge: |b| {
+ smi_scout_read(b[0].kernel().text(), b[0].cpus()?, "a")?;
+ smi_scout_read(b[1].kernel().text(), b[1].cpus()?, "b")
+ },
+ },
+ ),
(
"mkdir_cap",
metal::Metal {
@@ -664,6 +682,14 @@ const TESTCASES_READDIR: &[metal::Arm] =
const JOBCASE: &[metal::Arm] = &[metal::once("jobcase", "tests/jobcase", &[], &[])];
+/// SCOUT: the quietest committed config, held up by the stretch job past the
+/// runner's own sixty seconds and inside the kernel's hundred and twenty.
+const SMI_SCOUT_JOBS: &[&str] = &["--bound-ms=110000", "test_rs_smi_stretch"];
+const SMI_SCOUT: &[metal::Arm] = &[
+ metal::Arm { features: &["smi-scout"], ..metal::once("smiscout-a", "tests/jobcase", &[], SMI_SCOUT_JOBS) },
+ metal::Arm { features: &["smi-switch"], ..metal::once("smiscout-b", "tests/jobcase", &[], SMI_SCOUT_JOBS) },
+];
+
/// 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
@@ -2315,10 +2341,133 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> {
"iommu_virtio_platform" => common::iommu::iommu_virtio_platform(test_config),
"nested_nmi_is_loud" => faults::nested_nmi_is_loud(test_config),
"machine_shutdown" => power::machine_shutdown(test_config),
+ "x86_smi_scout_a" => smi_scout_probe(&["smi-scout"], "a"),
+ "x86_smi_scout_b" => smi_scout_probe(&["smi-switch"], "b"),
+ "x86_smi_scout_rehearsal" => smi_scout_probe(&["smi-rehearse"], "rehearsal"),
other => Err(format!("unknown machine test {other}")),
}
}
+/// SCOUT: one arm's kernel and the row's job list on eight CPUs under TCG,
+/// waited to the stop's report and read for its lines' shape. QEMU has no SMM
+/// worth the name, so no count here says anything.
+fn smi_scout_probe(features: &'static [&'static str], arm: &str) -> Result<(), String> {
+ const CPUS: u32 = 8;
+ let root = compile::repo_root();
+ let job = (
+ "bin/test_rs_smi_stretch".to_string(),
+ qemu::build_toyos_bin(toyos_build::arch::Arch::X86_64, &root.join("tests/toyos-rust-tests"), "smi_stretch"),
+ );
+ let mut qemu = QemuInstance::boot_with_options(
+ &root.join("tests/smiscoutcase"),
+ &[],
+ &[],
+ BootOptions { smp: CPUS, kernel_features: features, extra_root_files: vec![job], ..Default::default() },
+ );
+ let mut rest = String::new();
+ let waited = await_marker(&mut qemu, &mut rest, " why=stop ", "the stop's report");
+ let serial = format!("{}\n{rest}", qemu.boot_log());
+ for line in serial.lines().filter(|l| l.contains("smi: ") || l.contains("smi_stretch") || l.contains("===TEST_")) {
+ eprintln!(" [smi] {line}");
+ }
+ waited.map_err(|why| format!("{why}\nserial:\n{serial}"))?;
+ if !serial.contains("===TEST_END test_rs_smi_stretch exit=0===") {
+ return Err("the stretch job did not end with exit 0".to_string());
+ }
+ let switches = features.iter().any(|f| f.starts_with("smi-switch") || f.starts_with("smi-rehearse"));
+ if switches != serial.contains("smi: switch: ") {
+ return Err(format!("arm {arm}: a `smi: switch:` line where none is owed, or none where one is"));
+ }
+ if features.contains(&"smi-rehearse")
+ && !(serial.contains("smi: rehearse: wrote ") && serial.contains("smi: switch: wrote ") && serial.contains(" why=switched "))
+ {
+ return Err(format!("arm {arm}: the rehearsal did not run the switch's write"));
+ }
+ smi_scout_read(&serial, CPUS, arm)
+}
+
+/// SCOUT: one `smi: report=` line.
+struct SmiReport {
+ line: String,
+ why: String,
+ pid: Option<u64>,
+ at: u64,
+ /// Every CPU's `MSR_SMI_COUNT` and when it read it.
+ counts: Vec<(u64, u64)>,
+}
+
+/// SCOUT: every `smi:` line of a capture held to its shape, every report
+/// printed, and the count over each stretch the job marked: its eleven `idle`
+/// marks, then its eleven `busy` ones.
+fn smi_scout_read(capture: &str, cpus: u32, arm: &str) -> Result<(), String> {
+ for owed in ["smi: fadt ", "smi: report="] {
+ if !capture.contains(owed) {
+ return Err(format!("arm {arm}: no `{owed}` line"));
+ }
+ }
+ if !capture.contains("smi: chipset ") && !capture.contains("smi: no chipset") {
+ return Err(format!("arm {arm}: no line saying which chipset the SMI ports were read on"));
+ }
+ let mut reports = Vec::new();
+ for line in capture.lines() {
+ let Some(rest) = line.split("smi: report=").nth(1) else { continue };
+ let field = |key: &str| {
+ rest.split_whitespace()
+ .find_map(|f| f.strip_prefix(key))
+ .ok_or_else(|| format!("arm {arm}: no `{key}`\nline: {line}"))
+ };
+ let number = |s: &str| s.parse::<u64>().map_err(|_| format!("arm {arm}: `{s}` is no number\nline: {line}"));
+ let why = field("why=")?.to_string();
+ let pid = if why == "exit" { Some(number(field("pid=")?)?) } else { None };
+ let at = number(field("at=")?)?;
+ for key in ["sci_en=", "pm1_cnt=", "pm1_sts=", "pm1_en=", "smi_en=", "smi_sts=", "gpe0_sts=", "gpe0_en=", "sci_rte="] {
+ field(key)?;
+ }
+ if !rest.contains(" tco_rld=") && !rest.contains(" tco=-") {
+ return Err(format!("arm {arm}: no TCO field\nline: {line}"));
+ }
+ // Before the APs start only the BSP has read, and as they are released
+ // they may not have taken an interrupt yet.
+ let online = if why == "early" || why == "switched" { 1 } else { cpus };
+ let mut counts = Vec::new();
+ for c in 0..online {
+ let value = field(&format!("cpu{c}="))?;
+ match value.split_once('@') {
+ Some((count, read)) => counts.push((number(count)?, number(read)?)),
+ None if why == "ready" && c > 0 => {}
+ None => return Err(format!("arm {arm}: cpu{c} never read\nline: {line}")),
+ }
+ }
+ reports.push(SmiReport { line: line.to_string(), why, pid, at, counts });
+ }
+ let stretch_pids: BTreeSet<u64> = capture
+ .lines()
+ .filter_map(|l| l.split("exit: test_rs_smi_stretch pid=").nth(1))
+ .filter_map(|r| r.split_whitespace().next()?.parse().ok())
+ .collect();
+ for r in &reports {
+ let (lo, hi) = (r.counts.iter().map(|c| c.0).min(), r.counts.iter().map(|c| c.0).max());
+ let oldest = r.counts.iter().map(|c| r.at.saturating_sub(c.1)).max().unwrap_or(0);
+ let mark = if r.pid.is_some_and(|p| stretch_pids.contains(&p)) { " [stretch]" } else { "" };
+ eprintln!(" [smi] {arm} why={}{mark} at={} smi={lo:?}..{hi:?} oldest_read_ns={oldest}", r.why, r.at);
+ }
+ let marks: Vec<&SmiReport> = reports.iter().filter(|r| r.pid.is_some_and(|p| stretch_pids.contains(&p))).collect();
+ // Eleven marks a stretch, and the job's own exit after them.
+ if marks.len() != 23 {
+ return Err(format!("arm {arm}: {} reports at the stretch job's exits, want 23", marks.len()));
+ }
+ for (name, first, last) in [("idle", 0, 10), ("busy", 11, 21)] {
+ let (a, b) = (marks[first], marks[last]);
+ let smis = b.counts[0].0 - a.counts[0].0;
+ let ns = b.at - a.at;
+ let steps: Vec<u64> = marks[first..=last].windows(2).map(|w| w[1].counts[0].0 - w[0].counts[0].0).collect();
+ eprintln!(" [smi] {arm} {name}: cpu0 counted {smis} SMIs over {ns} ns, per 3 s mark {steps:?}");
+ eprintln!(" [smi] {arm} {name} opens: {}", a.line.trim());
+ eprintln!(" [smi] {arm} {name} closes: {}", b.line.trim());
+ }
+ Ok(())
+}
+
/// Every CPU's `CR0` and `CR4`, against what a CPU running this kernel must
/// hold.
/// |
…ames what a press does, and the firmware issue records the two GPEs the switch moved The track's ruling said stage 1 lands "with its events served in userland", which claims more than the owner ruled: he ruled a userland server that claims the SCI and handles the power button, and the ruling now says that. Stage 1's exit said a press of the power button "is handled", which names nothing a row can read. It now names what the ruling implies: the press stops the machine cleanly through ToyOS's own power-off path, SYS_SHUTDOWN, and the boot's log records the press and that stop, which is where a T14 row reads it. The firmware issue's ACPI_ENABLE bullet now records the two GPE readings the boot carried, read from its kernel.log lines quoted whole on #681 (comment 5966982752; the other boot's in 5966982609, the patch in 5966982939): the firmware's enable set GPE 9's enable bit (gpe0_en byte 1, 00 at line 121, 02 at line 123), and GPE 110's status rose after the switch and stayed set, served by nothing (gpe0_sts byte 13, 40 from line 298 through line 759, in none of the other boot's 25 reports). Stage 1's server meets both once it unmasks GSI 9. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
No conflict. main's side since the merge base 4adc1c0 is #681, issues only: it does not touch issues/hardware/the-t14-boots-toyos-unattended.md, which this branch deletes, and it adds a third citation of it. issues/hardware/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md (new in #681) named the deleted track as the owner of its reading: "The T14 loop owns only the reading: its jobs are the measurements owed on hardware, and it builds the row." That track is gone after this merge, so the citation goes in it. The reading's owner is now the fix's: stage 1 of issues/kernel/toyos-runs-the-machine-in-acpi-mode-and-interprets-its-aml.md (also new in #681). Its exit is "on the T14, MSR_SMI_COUNT stays flat on every CPU over the interval the firmware issue's exit defines", so the stage cannot show its exit without the row, and a row that reads the count flat cannot land green before the stage's switch to ACPI mode does. Neither track this branch adds builds measurement rows: the session track decides how rows run, and the watchdog track's readings are the TCO's. Searched in the merged index, by bare name and by path: `git grep --cached the-t14-boots-toyos-unattended` and `git grep --cached -i 'boots toyos unattended'` find nothing; before the fix the first found that one line. The same slug in every fork clone, the primary's rust/ and every ~/.cargo/git/checkouts tree: 125 searches, no hit. No file this branch adds or changes cites one of the four issues #681 deleted (disk-wait-pins-a-cpu, a-disk-operation-can-spin-past-the-tlb-ack- tripwire-before-its-break, cpu0-holds-interrupts-and-preemption-off-for-6-5- ms-on-the-t14, some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or- more): `git grep --cached` of the four slugs finds nothing in the merged index. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm
|
Evidence 1 of 4: the boot, its control, and the storage windows. Quoted because the readback lives in a scratch directory that does not outlive the session. Cited by The boot. One T14 boot (LENOVO 20W0003AMZ, BIOS N34ET71W (1.71), The instrument's own guide, from the staging request's comments, verbatim: Syscall numbers, The control: a 50 ms hold
The window is 56,000,902 ns for a hold of 50,000,024. The report sits inside it: Pid 4 is the log's file server, and the log volume is on the stickPid 4 in
|
| opener | first event | windows | span, ns |
|---|---|---|---|
| pid 4 (fsd, LOG) | sys(120) |
11 | 7,848,573 to 10,669,042 |
| pid 4 | sys(120) |
16 | 2,368,371 to 2,905,716 |
| pid 4 | sys(119) |
2 | 2,596,003 and 2,954,780 |
| pid 0 (init) | sys(111) |
3 | 3,817,265; 6,002,063; 6,623,907 |
| a herd thread | sys(5), with a shoot( |
14 | 7,789,015 to 7,990,941 |
| a herd thread | sys(5), with a shoot( |
14 | 2,800,115 to 2,948,801 |
| an exiting job | sys(72), the report |
7 | 2,380,417 to 11,926,485 |
idle_span |
sys(72), the hold |
1 | 56,000,902 |
The 8 preempt windows: cpu5's above, and seven of 4,528,459 to 4,714,002 ns at the instants of three count steps (evidence 4).
Issues only; no code. One T14 boot of
mainatc59e09ed6with a throwaway instrument (never landed) named what opens every interrupts-off window of 2 ms or more, sampled the CPU holding it, traced each TLB shootdown's acknowledgements and readMSR_SMI_COUNTon every CPU, over forty runs oftest_rs_ring_park_herd. Beside the instrument's own reports and its control, it found three causes: the xHCI spin, the firmware's interrupt and init's claim of a PCI function the machine lacks. This records each once, with an owner and an exit.Evidence, quoted because the readback is a scratch directory:
SYS_FSYNCin the windows' trails: comment 5966523482;mainat73282fa93: comment 5966817345, the one the owner ruled on. Everysmi:andsmi_stretch:line of each boot'skernel.logis in comment 5966982609 (nothing written) and comment 5966982752 (ACPI_ENABLEwritten). Its patchsmi.patch, whole, sha256582bb410…f538d6, is in comment 5966982939;f5a0208c…ac458a: comments 5962629281 and 5962629511.Machine: LENOVO 20W0003AMZ, BIOS N34ET71W (1.71). Image sha256
bead136b…6b66.verdict.txtreadspassed.What changed, per decision
The spin has one record:
issues/hardware/xhci-waits-are-spins.md. The T14's 8 to 11 ms window is the LOG fsd'sSYS_PARTITION_WRITE. It spins inXhciController::wait_transferunderXHCIinside a syscall, which is masked. It holds one CPU for 8.3 to 10.7 ms nine times, and twice all eight: seven herd threads inSYS_THREAD_EXITspin, masked, on its shootdown acknowledgement. The file carries:msc::bind, whose own doc says so), and a disk call;SYS_PARTITION_READ,SYS_PARTITION_WRITEandSYS_FSYNC, and the tableSYS_DEVICE_CLAIMreads.SYS_FSYNCis a cache flush throughxhci::storage_flushunderXHCI(partition_fsync,kernel/src/object/ops.rs). logd'sfsyncis one:sync_allon its/logfile is fsd'sFSYNC, which the LOG fsd answers withSYS_FSYNCon its claim (userland/fsd/src/disk.rs,toyos/src/device.rs);DEAF_CPU's 5 s);SYS_FSYNCfollows 15 of its windows, and in 7 it spins on a contendedXHCIatwith_disk_by. None of the boot's 101 windows opened at syscall 15;Owner:
issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md, for both exits. Exits:IF-clear spin is underDEAF_CPUby 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. A staged boot whose first batch spends most of the budget and whose next batch breaks shows it;kernel/src/drivers/xhci. The tree reads that, so the exit needs no instrument the tree lacks. Step 10 meets both.Deleted, folded into that file, all three on
main:issues/kernel/some-t14-boots-carry-an-interrupts-off-window-of-9-ms-or-more.md. Its readings are the spin's, and its stop-report line is corrected.issues/kernel/a-disk-operation-can-spin-past-the-tlb-ack-tripwire-before-its-break.md. Its arithmetic and its exit are the spin's tripwire and first exit. Its one citation was a bare name inissues/kernel/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md, which now points at the spin's file.issues/audio/disk-wait-pins-a-cpu.md. Its one live claim is theSYS_FSYNCabove. The rest is gone from the tree:log_file::SINKandfat32_adapter::VOLUMESno longer exist, the partition fsync takes no VFS, andio-depth-probeis no kernel feature. It had two citations:issues/kernel/scheduler-pass-blocks-in-xhci.mdsent "the disk wait that survives" to it, and now sends it to the spin's file.issues/kernel/the-global-pipe-lock-spans-a-user-copy.mdnamed it andio-depth-probeas the tools that would price its hold. That clause is deleted, and the sentence ends at "the first thing owed".A search of the tree, dotfiles included (
rg --hidden --no-ignore, andgit grepat the head), finds no citation of the three or of the renamed slug below. It also found no other defect that records this spin:issues/kernel/every-wait-in-this-kernel-is-a-spin.mdstill names the disk path holdingXHCI. It is an assigned track whose ordering the small-kernel track supersedes, keeping it "as the evidence each stage closes". This branch leaves it alone.scheduler-pass-blocks-in-xhci.md,issues/hardware/hotplug-blocks-a-scheduler-pass.mdandissues/hardware/a-disk-plugged-in-after-boot-is-bound-inside-a-scheduling-pass.mdare the scheduler pass's records, each with its own exit.issues/kernel/a-held-disk-waits-for-a-pass-no-cpu-takes-when-every-cpu-is-in-a-call-on-it.md,issues/kernel/a-shutdown-on-a-held-usb-disk-left-a-cpu-deaf-to-a-tlb-shootdown.md,issues/kernel/a-stick-that-answers-late-is-broken-by-the-two-second-abandon.mdandissues/kernel/a-deliberate-wedge-inside-a-driver-panics-every-other-cpu-that-wants-its-lock.mdeach record a different failure of the same driver, with its own exit.issues/kernel/cpu0-holds-interrupts-and-preemption-off-for-6-5-ms-on-the-t14.mdbecomesissues/kernel/inits-claim-of-a-pci-function-the-t14-lacks-holds-interrupts-off-for-3-8-ms.md. Its 6.5 ms is init's partition claims, which belong to the spin. What is its own is init'sSYS_DEVICE_CLAIMfor blockd'spci:1b36:0010, which this machine lacks: 3,817,265 ns on cpu0. The claim reads 24 vendor IDs, and nothing has said what it spends 3.8 ms on.openedstays, as renames in this tracker keep it.MSR_SMI_COUNTunmoved across that window, so a firmware step cannot fail a fixed claim. The exit bounds the masked hold the title names, not the syscall from entry to return. A fix that opens interrupts between the reads closes the defect even if the reads stay slow.New:
issues/hardware/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md.rtla timerlat --dma-latency 0, which holds C-states shallow and runs a 1 kHz timer. So the slug and the title claim ToyOS only, and the body names that condition.SMI_CMD=0xb2,ACPI_ENABLE=0xf0,PM1a_CNT=0x0001,SMI_EN=0x10002033withAPMC_ENset. ToyOS makes no enable handshake.mainat73282fa93twice, each boot 30 s idle and then 30 s with a spinning thread on every CPU. With nothing written,SCI_ENread clear all boot and the count rose once every 2.2 s, idle and busy alike, 27 in 60 s. WithACPI_ENABLEwritten toSMI_CMD,SCI_ENread set 2.13 ms later, the write cost one firmware interrupt, and the count then stayed flat on every CPU for 61 s. The SCI's line stayed masked, and nothing in ToyOS handles an SCI. After the switch the firmware had set GPE 9's enable bit, and GPE 110's status rose and stayed set, served by nothing. The issue'sACPI_ENABLEbullet records both, with their lines in comment 5966982752, because stage 1's server meets them once it unmasks GSI 9.Owner: the fix is stage 1 of the ACPI track below, as the owner ruled. The T14 loop (
issues/hardware/the-t14-boots-toyos-unattended.md) owns only the reading, and builds the row. Exit: a T14 row reads the count on every CPU twice and the readings agree on every CPU.SMI_CMD, whoever makes it. The ACPI enable is itself such a write, and raises one firmware interrupt whereAPMC_ENis set.New:
issues/kernel/toyos-runs-the-machine-in-acpi-mode-and-interprets-its-aml.md, the ACPI track, with the owner's ruling on the scout. It staysopen, a track that starts no work by itself, and draws no design. It says what is missing:ACPI_ENABLEtoSMI_CMDand nothing handles an SCI, and the T14's firmware hands the machine over in legacy mode, which is the firmware issue above;toyos-acpi/src/dsdt.rsfinds\_S5_by a byte scan, the loader asks UEFI for the windows_CRSwould name (bootloader/src/rootbridge.rs), and nothing reads_CST.The owner's ruling, on the scout in comment 5966817345: the ACPI enable lands as the track's stage 1, together with a userland server that claims the SCI and handles the power button, a fixed event that needs no AML, so nothing the firmware does in legacy mode today is lost. He chose this over landing the write alone with the events masked, and over waiting for the AML work. The AML interpreter follows as later stages: ToyOS writes its own, battery first, his direction that
mainrecorded in the scheduler file (0ee814f5a, from the 2026-08-16 direction conversation).Stage 1's exit: on the T14,
MSR_SMI_COUNTstays flat on every CPU over the interval the firmware issue's exit defines, and a press of the power button stops the machine cleanly, through ToyOS's own power-off path (SYS_SHUTDOWN), and the boot's log records the press and that stop, where a T14 row reads both. The power button's half is what the ruling implies, named so a row can fail it; the track does not design the server.Two files that cited the interpreter point at it:
issues/kernel/the-scheduler-and-the-clocks-never-talk.mdcited an "ACPI/power track (task nightly: an instrument for the "Rust + QEMU is everything" premise #136 — own AML interpreter, battery first)" that has no file. The false citation goes, the direction moves to the track, and the line's AML interpreter now points there.issues/kernel/idle-cpus-enter-the-c-states-cst-names.mdsent its reader to the scheduler file for that interpreter. That file, in turn, named no file for it. The line now points at the track.issues/kernel/a-process-lengthens-an-interrupts-off-walk-by-the-threads-it-parks-on-one-ring.mdnow names its two readings that belong to other causes. 2 × 5,075,290 is the log write, and 4,725,822 is a firmware step, by reading. Without them, one size reads 1.03 to 1.98 ms.Where the log differs from the reading in the brief
idle_span's report is printed inside that sameSYS_EXIT, andsmi at=1752151655toend at=1758069743is 5,918,088 ns of it. Stage 6 step 2, built: the longest interrupts-off and preemption-off windows per CPU, and a held window the T14 reads back #649's shipping kernel, whose report is a few lines, read the same hold at 50,075,527 to 50,080,844 ns. Seven windows, 2.38 to 11.93 ms, are the instrument's own reports and are counted as such. Nothing in the issues rests on this.by=cpuM. A waiting initiator sends them.by=selfis the single-CPU case.gap_nsis about a microsecond on twelve of the fourteen long shootdowns, 1,141 to 1,676 ns. The other two read 10,819 and 8,476 ns.What else the boot showed
Of the 93 interrupts-off windows, 25 cross a firmware step. The other 68 are:
The table is in comment 5962618149. The three lock waits of about 4.5 ms all fall on firmware steps: two at 9.925 s and one at 36.556 s. One window is named here and nowhere else: cpu5's first idle pass held preemption off for 2,454,682 ns at 1.160 s. That pass printed the i8042 line. It carries
events=0and no sample, because its interrupts were open.Gates
cargo run -- --ci hostatdfa31c8a9, this head: EXIT=0. Its last line is[ci] Host: 67 step(s), all green. Log:/Users/jan/.claude/jobs/2280e09e/tmp/scratchpad/orch/681-named/ci-host.log.issues/.issues/README.md. The host gate reads an issue file only where a manifest or a build reason cites it (src/userlandhost.rs,src/build.rs), and none cites these.Net: 14 files, +275 −265, all under
issues/. On the windows' subjects that is three issue files wheremainhad five, plus the ACPI track.Unsure
🤖 Generated with Claude Code
https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm