feat(obs): export IPI, TLB shootdown and PT_LOCK counters (C3 E1)

.validation/c3-e1/README.md

@@ -0,0 +1,38 @@
+# C3 E1 validation
+
+Source: counters `e66288b8d641226267ee94d0d4e06648c68efb59` on `2e09191` (main after #99), plus `5ec5792`, which raises the hosted coverage pin and changes no kernel code.
+
+Detailed commands, environment identities and artifact hashes are archived in the private documentation repository:
+
+[Immutable receipt archive](https://github.com/Zero-kernel/Nilix-docs-private/tree/4428f515bf16b212d8d0a4d09cab07fbf8f78731/validation/c3-e1) · [Archive PR](https://github.com/Zero-kernel/Nilix-docs-private/pull/12)
+
+## Recorded results and limits
+
+- **Local.**
+  - fmt, clippy, lint and the build pass.
+  - The hosted sub-crate suites pass, 641 tests including the new `PT_LOCK` test. Removing the `contended` increment or the hold-time accumulation fails that test.
+  - All Python harness tests pass except one `iommu_device_probe_test` import error under plain unittest, which is unrelated; CI runs pytest.
+- **Dev host, QEMU 8.2.**
+  - The runtime group is GATE-QUALIFIED, and runtime at 4 vCPUs is QUALIFIED (3) with passed=46.
+  - The strict group still FAILs on the remaining deferrals, with no undeclared scope.
+  - `schedstat_event_counters` reports `not_applicable scope=needs_cpus:2` at 1 vCPU and passes at 4 and 16.
+  - With the IPI handlers' counting removed, it fails (`handled 0->0`), as a negative control should.
+- **ring3-mm.**
+  - It passes at 1, 4 and 8 vCPUs, including `syscall_test`'s 2 KiB `/proc/schedstat` read.
+  - At 16 vCPUs it hit its 900-second deadline while running beside a 16-vCPU stress guest. Run beside its parent `2e09191`, E1 completed in 820.6 s while the parent hit the deadline; at 8 vCPUs it took 210.7 s against 259.4 s. No slowdown from E1 is visible.
+  - Every source tried is marginal against 900 s on this host when a second 16-vCPU guest runs.
+- **Format.**
+  - A 300-second `thread` run at 16 vCPUs is QUALIFIED (3) and shows the four new `/proc/schedstat` lines: 296 of the file's 876 bytes.
+  - That sample is the stress runner's round-1 copy. It is a format check, not a C3 measurement.
+
+None of these results is a strict pass. E2–E4 (#90) do the measurements. Ordinary builds and public CI do not require the private archive.
+
+The local-checks, gates and paired-run receipts have aggregate status 1, from the unrelated unittest import error, the remaining strict deferrals, and the 16-vCPU deadlines respectively. Individual statuses and log hashes are preserved.
+
+## Interpreting IPI samples
+
+`ipis_sent` and `ipis_handled` are independent cumulative event counts for each CPU, not a coherent snapshot. A target can handle an IPI before the sender records its ICR write, and events can occur between procfs reads. A sample with `sent=10` and `handled=11` is therefore valid. LAPIC coalescing also prevents the difference from measuring pending or dropped IPIs, even after send accounting catches up.
+
+E2–E4 analysis should compare each CPU's send and handler counts over an interval separately, using unsigned 64-bit wrapping deltas for samples from the same boot and resetting the baseline after a reboot. Neither a single sample's difference nor the difference of the two interval deltas is an exact backlog or loss metric. Readers must accept `handled > sent` without unsigned underflow, a fabricated backlog, or a delivery-failure verdict.
+
+Existing readers retain the raw counters and do not subtract them. This clarification changes only documentation and Rust doc comments; the recorded runtime results above remain bound to their original sources.

kernel/arch/interrupts.rs

@@ -2446,7 +2446,10 @@ extern "x86-interrupt" fn reschedule_ipi_handler(_stack_frame: InterruptStackFra
     clac_if_smap();
 
     // R69-3 FIX: Mark entering IRQ context
-    current_cpu().irq_enter();
+    let this_cpu = current_cpu();
+    this_cpu.irq_enter();
+    // C3 E1 (#90): per-CPU handled count for /proc/schedstat.
+    kernel_core::process::note_ipi_handled(this_cpu.cpu_id.load(Ordering::Relaxed));
 
     // R155-11 FIX: Save FPU state before any code that might use SSE.
     // Compiler auto-vectorization can emit SSE instructions in handler code,
@@ -2494,7 +2497,10 @@ extern "x86-interrupt" fn tlb_shootdown_ipi_handler(_stack_frame: InterruptStack
     clac_if_smap();
 
     // R69-3 FIX: Mark entering IRQ context
-    current_cpu().irq_enter();
+    let this_cpu = current_cpu();
+    this_cpu.irq_enter();
+    // C3 E1 (#90): per-CPU handled count for /proc/schedstat.
+    kernel_core::process::note_ipi_handled(this_cpu.cpu_id.load(Ordering::Relaxed));
 
     // R155-11 FIX: Save FPU state before any code that might use SSE.
     // Compiler auto-vectorization can emit SSE instructions in handler code,

kernel/arch/ipi.rs

@@ -239,6 +239,10 @@ pub fn send_ipi(target_cpu: usize, ipi_type: IpiType) {
             apic::send_ipi_raw(dest_lapic, ipi_type.vector(), apic::icr_delivery::FIXED);
         }
         bump_stat(ipi_type, 1);
+        // C3 E1 (#90): per-target counts for /proc/schedstat.
+        if matches!(ipi_type, IpiType::Reschedule | IpiType::TlbShootdown) {
+            kernel_core::process::note_ipi_sent(target_cpu);
+        }
     }
 }
 

kernel/kernel_core/process.rs

@@ -6808,6 +6808,48 @@ pub fn note_task_migration(cpu: usize) {
     }
 }
 
+/// C3 E1 (#90): reschedule and TLB-shootdown IPIs sent to each CPU, and the
+/// handler runs on it. Counting by target needs no LAPIC read on the sending
+/// side. These cumulative counts are sampled independently: handled may
+/// temporarily exceed sent because send accounting follows the ICR write or
+/// events occur between reads. The LAPIC can also coalesce sends, so their
+/// difference is not a pending- or dropped-IPI count.
+/// Statistics only: Relaxed, wrapping modulo 2^64.
+static CPU_IPIS_SENT: [AtomicU64; cpu_local::max_cpus()] =
+    [const { AtomicU64::new(0) }; cpu_local::max_cpus()];
+static CPU_IPIS_HANDLED: [AtomicU64; cpu_local::max_cpus()] =
+    [const { AtomicU64::new(0) }; cpu_local::max_cpus()];
+
+/// Record one reschedule or TLB-shootdown IPI sent to `cpu` (IRQ-safe, lock-free).
+pub fn note_ipi_sent(cpu: usize) {
+    if let Some(counter) = CPU_IPIS_SENT.get(cpu) {
+        // lint-fetch-add: allow (statistics counter)
+        counter.fetch_add(1, Ordering::Relaxed);
+    }
+}
+
+/// Record one reschedule or TLB-shootdown IPI handler run on `cpu`.
+pub fn note_ipi_handled(cpu: usize) {
+    if let Some(counter) = CPU_IPIS_HANDLED.get(cpu) {
+        // lint-fetch-add: allow (statistics counter)
+        counter.fetch_add(1, Ordering::Relaxed);
+    }
+}
+
+/// `(IPIs sent to, IPIs handled on)` `cpu` since boot.
+///
+/// The two loads are not a coherent snapshot. For samples from the same boot,
+/// compare each counter's wrapping interval delta separately; subtracting the
+/// two fields does not measure outstanding or lost IPIs.
+pub fn cpu_ipi_counters(cpu: usize) -> (u64, u64) {
+    let load = |counters: &[AtomicU64]| {
+        counters
+            .get(cpu)
+            .map_or(0, |counter| counter.load(Ordering::Relaxed))
+    };
+    (load(&CPU_IPIS_SENT), load(&CPU_IPIS_HANDLED))
+}
+
 /// The CPUs currently online, as a bit mask (for `/proc/schedstat`).
 pub fn sched_online_cpu_mask() -> u64 {
     cpu_local::online_cpu_mask()

kernel/mm/page_table.rs

@@ -51,28 +51,101 @@ static PT_LOCK: Mutex<()> = Mutex::new(());
 const NO_PT_LOCK_OWNER: usize = usize::MAX;
 static PT_LOCK_OWNER_CPU: AtomicUsize = AtomicUsize::new(NO_PT_LOCK_OWNER);
 
+/// C3 E1 (#90): `PT_LOCK` statistics for `/proc/schedstat`. Observability
+/// only: Relaxed, and a wrap is harmless. Wait time is measured only for a
+/// contended `lock_pt`; hold time runs from acquisition to guard drop. Both
+/// are raw TSC deltas, since the guest tick clock lags host time under TCG.
+static PT_LOCK_ACQUIRED: AtomicU64 = AtomicU64::new(0);
+static PT_LOCK_CONTENDED: AtomicU64 = AtomicU64::new(0);
+static PT_LOCK_BUSY: AtomicU64 = AtomicU64::new(0);
+static PT_LOCK_WAIT_TSC: AtomicU64 = AtomicU64::new(0);
+static PT_LOCK_WAIT_TSC_MAX: AtomicU64 = AtomicU64::new(0);
+static PT_LOCK_HOLD_TSC: AtomicU64 = AtomicU64::new(0);
+static PT_LOCK_HOLD_TSC_MAX: AtomicU64 = AtomicU64::new(0);
+/// TSC at the current holder's acquisition, written and read only by it.
+static PT_LOCK_SINCE_TSC: AtomicU64 = AtomicU64::new(0);
+
+/// Snapshot of the `PT_LOCK` statistics (see [`pt_lock_stats`]).
+#[derive(Debug, Clone, Copy)]
+pub struct PtLockStats {
+    /// Acquisitions by `lock_pt` and successful `try_lock_pt`.
+    pub acquired: u64,
+    /// `lock_pt` calls that found the lock held (counted before they spin).
+    pub contended: u64,
+    /// `try_lock_pt` calls that found the lock held (the #PF Busy path).
+    pub busy: u64,
+    /// Sum and maximum of contended `lock_pt` spin time, in TSC cycles.
+    pub wait_tsc: u64,
+    pub wait_tsc_max: u64,
+    /// Sum and maximum of hold time, in TSC cycles.
+    pub hold_tsc: u64,
+    pub hold_tsc_max: u64,
+}
+
+/// Current `PT_LOCK` statistics; each field is read independently.
+pub fn pt_lock_stats() -> PtLockStats {
+    PtLockStats {
+        acquired: PT_LOCK_ACQUIRED.load(Ordering::Relaxed),
+        contended: PT_LOCK_CONTENDED.load(Ordering::Relaxed),
+        busy: PT_LOCK_BUSY.load(Ordering::Relaxed),
+        wait_tsc: PT_LOCK_WAIT_TSC.load(Ordering::Relaxed),
+        wait_tsc_max: PT_LOCK_WAIT_TSC_MAX.load(Ordering::Relaxed),
+        hold_tsc: PT_LOCK_HOLD_TSC.load(Ordering::Relaxed),
+        hold_tsc_max: PT_LOCK_HOLD_TSC_MAX.load(Ordering::Relaxed),
+    }
+}
+
+#[inline]
+fn read_tsc() -> u64 {
+    // SAFETY: RDTSC only reads the time-stamp counter.
+    unsafe { core::arch::x86_64::_rdtsc() }
+}
+
 struct PtLockGuard {
     _guard: spin::MutexGuard<'static, ()>,
 }
 
+impl PtLockGuard {
+    #[inline]
+    fn new(guard: spin::MutexGuard<'static, ()>) -> Self {
+        PT_LOCK_OWNER_CPU.store(cpu_local::current_cpu_id(), Ordering::Release);
+        PT_LOCK_ACQUIRED.fetch_add(1, Ordering::Relaxed);
+        PT_LOCK_SINCE_TSC.store(read_tsc(), Ordering::Relaxed);
+        Self { _guard: guard }
+    }
+}
+
 impl Drop for PtLockGuard {
     fn drop(&mut self) {
+        // Still the holder: `_guard` is released after this body.
+        let held = read_tsc().saturating_sub(PT_LOCK_SINCE_TSC.load(Ordering::Relaxed));
+        PT_LOCK_HOLD_TSC.fetch_add(held, Ordering::Relaxed);
+        PT_LOCK_HOLD_TSC_MAX.fetch_max(held, Ordering::Relaxed);
         PT_LOCK_OWNER_CPU.store(NO_PT_LOCK_OWNER, Ordering::Release);
     }
 }
 
 #[inline]
 fn lock_pt() -> PtLockGuard {
+    if let Some(guard) = PT_LOCK.try_lock() {
+        return PtLockGuard::new(guard);
+    }
+    PT_LOCK_CONTENDED.fetch_add(1, Ordering::Relaxed);
+    let start = read_tsc();
     let guard = PT_LOCK.lock();
-    PT_LOCK_OWNER_CPU.store(cpu_local::current_cpu_id(), Ordering::Release);
-    PtLockGuard { _guard: guard }
+    let waited = read_tsc().saturating_sub(start);
+    PT_LOCK_WAIT_TSC.fetch_add(waited, Ordering::Relaxed);
+    PT_LOCK_WAIT_TSC_MAX.fetch_max(waited, Ordering::Relaxed);
+    PtLockGuard::new(guard)
 }
 
 #[inline]
 fn try_lock_pt() -> Option<PtLockGuard> {
-    let guard = PT_LOCK.try_lock()?;
-    PT_LOCK_OWNER_CPU.store(cpu_local::current_cpu_id(), Ordering::Release);
-    Some(PtLockGuard { _guard: guard })
+    let Some(guard) = PT_LOCK.try_lock() else {
+        PT_LOCK_BUSY.fetch_add(1, Ordering::Relaxed);
+        return None;
+    };
+    Some(PtLockGuard::new(guard))
 }
 
 /// CPU that currently owns the global page-table lock, if any.
@@ -2122,6 +2195,45 @@ unsafe impl FrameAllocator<Size4KiB> for MmioPtRecorder<'_> {
     }
 }
 
+/// Serializes the hosted tests that take `PT_LOCK`: the other asserts the lock
+/// is free at its start and end.
+#[cfg(test)]
+static PT_LOCK_TEST_SERIAL: spin::Mutex<()> = spin::Mutex::new(());
+
+#[cfg(test)]
+mod pt_lock_stats_tests {
+    use super::*;
+    use std::{
+        thread,
+        time::{Duration, Instant},
+    };
+
+    /// C3 E1 (#90): a held `PT_LOCK` makes `try_lock_pt` busy and `lock_pt`
+    /// contended, and the wait and both holds are timed.
+    #[test]
+    fn busy_contention_wait_and_hold_are_counted() {
+        let _serial = PT_LOCK_TEST_SERIAL.lock();
+        let before = pt_lock_stats();
+        let holder = lock_pt();
+        assert!(thread::spawn(|| try_lock_pt().is_none()).join().unwrap());
+        let waiter = thread::spawn(|| drop(lock_pt()));
+        let deadline = Instant::now() + Duration::from_secs(5);
+        while pt_lock_stats().contended == before.contended && Instant::now() < deadline {
+            thread::yield_now();
+        }
+        thread::sleep(Duration::from_millis(5));
+        drop(holder);
+        waiter.join().unwrap();
+
+        let after = pt_lock_stats();
+        assert!(after.acquired >= before.acquired + 2);
+        assert!(after.contended > before.contended);
+        assert!(after.busy > before.busy);
+        assert!(after.wait_tsc > before.wait_tsc && after.wait_tsc_max > 0);
+        assert!(after.hold_tsc > before.hold_tsc && after.hold_tsc_max > 0);
+    }
+}
+
 #[cfg(test)]
 mod cow_replace_tests {
     use super::*;
@@ -2269,11 +2381,12 @@ mod kernel_stack_directory_tests {
 
 #[cfg(test)]
 mod pt_lock_tests {
-    use super::{pt_lock_owner_cpu, try_with_current_manager, with_pt_lock};
+    use super::{pt_lock_owner_cpu, try_with_current_manager, with_pt_lock, PT_LOCK_TEST_SERIAL};
     use x86_64::VirtAddr;
 
     #[test]
     fn try_manager_rejects_same_cpu_reentry() {
+        let _serial = PT_LOCK_TEST_SERIAL.lock();
         assert_eq!(pt_lock_owner_cpu(), None);
         with_pt_lock(|| {
             let owner = pt_lock_owner_cpu();

kernel/mm/tlb_shootdown.rs

@@ -54,6 +54,13 @@ pub struct TlbShootdownStats {
     pub pages_flushed: u64,
     /// R106-5: Number of times mailbox saturation forced a full-flush fallback
     pub coalesced_fallbacks: u64,
+    /// C3 E1 (#90): target scans that found a CPU running the modified CR3
+    pub targeted_shootdowns: u64,
+    /// C3 E1: target scans that fell back to every other online CPU (also
+    /// counted when there is none)
+    pub broadcast_fallbacks: u64,
+    /// C3 E1: shootdown IPIs sent, including ACK-timeout resends
+    pub shootdown_ipis: u64,
 }
 
 // Atomic statistics for SMP-safe updates
@@ -99,6 +106,9 @@ static CPU_ACTIVE_CR3: [AtomicU64; cpu_local::max_cpus()] =
 /// Statistics for optimized TLB shootdowns
 static STATS_TARGETED_SHOOTDOWNS: AtomicU64 = AtomicU64::new(0);
 static STATS_BROADCAST_FALLBACK: AtomicU64 = AtomicU64::new(0);
+/// C3 E1 (#90): shootdown IPIs sent; divided by the two counters above, the
+/// mean fanout of a remote dispatch.
+static STATS_SHOOTDOWN_IPIS: AtomicU64 = AtomicU64::new(0);
 
 /// Registered function used to send the TLB shootdown IPI
 /// Stored as usize to avoid function pointer in static
@@ -723,6 +733,7 @@ fn post_requests(targets: CpuMask, cr3: u64, start: u64, len: u64, generation: u
 fn send_ipis(targets: CpuMask, sender: TlbIpiSender) {
     for cpu in targets.iter() {
         sender(cpu);
+        STATS_SHOOTDOWN_IPIS.fetch_add(1, Ordering::Relaxed);
     }
 }
 
@@ -813,9 +824,7 @@ fn wait_for_acks_with_retry(targets: CpuMask, generation: u64, sender: TlbIpiSen
 
         if attempt < ACK_TIMEOUT_RETRIES {
             // Resend IPIs to unacked CPUs
-            for cpu in unacked.iter() {
-                sender(cpu);
-            }
+            send_ipis(unacked, sender);
         } else {
             // Final timeout - this is a critical error
             kprintln!(
@@ -1258,6 +1267,9 @@ pub fn get_stats() -> TlbShootdownStats {
         range_flushes: STATS_RANGE_FLUSHES.load(Ordering::Relaxed),
         pages_flushed: STATS_PAGES_FLUSHED.load(Ordering::Relaxed),
         coalesced_fallbacks: STATS_COALESCED_FALLBACKS.load(Ordering::Relaxed),
+        targeted_shootdowns: STATS_TARGETED_SHOOTDOWNS.load(Ordering::Relaxed),
+        broadcast_fallbacks: STATS_BROADCAST_FALLBACK.load(Ordering::Relaxed),
+        shootdown_ipis: STATS_SHOOTDOWN_IPIS.load(Ordering::Relaxed),
     }
 }