irq_census judges each CPU by its largest counts, the console's routine lines go to stdout, and the LAPIC selftests' after-check waits for the timer it arms

issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md

@@ -0,0 +1,21 @@
+---
+status: open
+kind: defect
+opened: 2026-10-05
+---
+
+# The irq census summary takes a CPU's last stamped line as its newest read
+
+`common::irqcensus::observe` (`tests/common/irqcensus.rs`) keeps, per guest
+and CPU, the last `irq: cpuN` line the console carried, as if that line were
+the CPU's newest read. It is not. A process exit reads the counters before
+`log::emit` stamps its line, two exits on two CPUs run side by side, and the
+shards are merged by stamp, so the line stamped last can carry the older
+read. The suite's summary then counts that CPU short by what it took between
+the two reads. The judge `irq_census` (`tests/toyos.rs`) folds each CPU's
+lines with `Census::raise`, the largest count per source, for this reason.
+
+Owner: the harness, `observe` in `tests/common/irqcensus.rs`.
+
+**Exit:** `observe` folds each guest's CPU lines with `Census::raise`, and
+`SEEN`'s doc no longer says the last line is the whole boot.

kernel/src/arch/x86_64/boot.rs

@@ -144,7 +144,7 @@ pub fn start_other_cpus(platform: &Platform, args: &KernelArgs) {
 /// The interrupt-controller selftests an actuator asks for, once the timer ticks.
 #[cfg(feature = "boot-actuators")]
 pub fn interrupt_selftests() {
-    // Needs interrupts on and the timer already ticking: its last assertion is that the interrupt after the spurious one arrives.
+    // Needs interrupts on and the timer calibrated: each arms the one-shot and asserts an interrupt arrives after its probe.
     if crate::actuator::lapic_spurious_selftest() {
         idt::spurious::selftest();
     }

kernel/src/arch/x86_64/idt/spurious.rs

@@ -80,7 +80,6 @@ pub fn selftest() {
         crate::log!("LAPIC: spurious selftest FAILED — this CPU publishes no census block");
         return;
     };
-    let taken_before = crate::irq_census::deliveries_total(cpu).unwrap_or(0);
 
     // This platform's devices are all MSI/MSI-X and `TPR` is never written, so
     // nothing here raises a spurious interrupt without this call.
@@ -108,14 +107,17 @@ pub fn selftest() {
         return;
     }
 
-    // Confirms the CPU still takes interrupts afterward; any source works, since only a deaf CPU is ruled out.
+    // Confirms the CPU still takes interrupts afterward, by the one it arms here.
+    // The timer's own count and never a total: the hard-lockup sampler's NMI lands whatever `IF` holds.
+    let taken = crate::irq_census::deliveries(cpu, Source::Timer).unwrap_or(0);
+    apic::arm_within(kernel::sched::fair::QUANTUM_NS);
     let ran_on = crate::clock::settles(ARRIVES.nanos(), || {
-        crate::irq_census::deliveries_total(cpu).unwrap_or(taken_before) > taken_before
+        crate::irq_census::deliveries(cpu, Source::Timer).unwrap_or(taken) > taken
     });
     if !ran_on {
         crate::log!(
-            "LAPIC: spurious selftest FAILED — cpu{cpu} took no interrupt at all after the \
-             spurious one"
+            "LAPIC: spurious selftest FAILED — cpu{cpu} did not take the timer interrupt armed \
+             after the spurious one"
         );
         return;
     }

kernel/src/arch/x86_64/idt/unclaimed.rs

@@ -127,7 +127,6 @@ pub fn selftest() {
         crate::log!("LAPIC: unclaimed selftest FAILED — this CPU publishes no census block");
         return;
     };
-    let taken_before = crate::irq_census::deliveries_total(cpu).unwrap_or(0);
 
     apic::send_self(PROBE_VECTOR);
 
@@ -161,13 +160,16 @@ pub fn selftest() {
         return;
     }
 
+    // The timer's own count and never a total: the hard-lockup sampler's NMI lands whatever `IF` holds.
+    let taken = crate::irq_census::deliveries(cpu, Source::Timer).unwrap_or(0);
+    apic::arm_within(kernel::sched::fair::QUANTUM_NS);
     let ran_on = crate::clock::settles(ARRIVES.nanos(), || {
-        crate::irq_census::deliveries_total(cpu).unwrap_or(taken_before) > taken_before
+        crate::irq_census::deliveries(cpu, Source::Timer).unwrap_or(taken) > taken
     });
     if !ran_on {
         crate::log!(
-            "LAPIC: unclaimed selftest FAILED — cpu{cpu} took no interrupt at all after the \
-             unclaimed one"
+            "LAPIC: unclaimed selftest FAILED — cpu{cpu} did not take the timer interrupt armed \
+             after the unclaimed one"
         );
         return;
     }

kernel/src/irq_census.rs

@@ -56,9 +56,9 @@ impl Source {
     ];
 }
 
-/// Every source's count summed, bar `except`'s.
-fn sum_except(counts: &[u64; Source::COUNT], except: Option<Source>) -> u64 {
-    counts.iter().sum::<u64>() - except.map_or(0, |source| counts[source as usize])
+/// Every source's count summed, bar the NMI's.
+fn sum_bar_nmi(counts: &[u64; Source::COUNT]) -> u64 {
+    counts.iter().sum::<u64>() - counts[Source::Nmi as usize]
 }
 
 // Counted where each is taken, by the architecture's handlers
@@ -106,30 +106,24 @@ pub fn deliveries(cpu: u32, source: Source) -> Option<u64> {
     read(cpu).map(|counts| counts[source as usize])
 }
 
-/// Every CPU's total delivery count, or `None` if that CPU has never been built.
-#[cfg(feature = "boot-actuators")]
-pub fn deliveries_total(cpu: u32) -> Option<u64> {
-    read(cpu).map(|counts| sum_except(&counts, None))
-}
-
 /// **One CPU's progress: every interrupt it has taken except the NMI.**
 ///
 /// What `crate::hardlockup` compares one sample to the next, and the exclusion
-/// is the whole of why this is not [`deliveries_total`]: that sample arrives
-/// *as* an NMI and has already counted itself by the time it reads this, so a
-/// total including it moves on every sample and no CPU is ever stuck.
+/// is load-bearing: that sample arrives *as* an NMI and has already counted
+/// itself by the time it reads this, so a total including it moves on every
+/// sample and no CPU is ever stuck.
 ///
 /// One published pointer and relaxed loads: no lock, so the CPU sealing a
 /// record about a sibling can read this about it.
 pub fn taken_by(cpu: u32) -> Option<u64> {
-    read(cpu).map(|counts| sum_except(&counts, Some(Source::Nmi)))
+    read(cpu).map(|counts| sum_bar_nmi(&counts))
 }
 
 /// [`taken_by`] for the CPU asking, read straight off its own block — the one
 /// form a CPU inside an NMI may use, since it needs neither the published
 /// pointer array nor a bounds check on a `cpu_id` it is standing on.
 pub fn taken_here() -> u64 {
-    sum_except(&percpu::irq_counts_here(), Some(Source::Nmi))
+    sum_bar_nmi(&percpu::irq_counts_here())
 }
 
 /// Logs one `irq: cpuN <source>=…` line per online CPU; counts are cumulative since boot.

tests/checks.rs

@@ -486,6 +486,64 @@ mod checks {
         Ok(())
     }
 
+    /// [`irq_census`] over two exits stamped in the other order from their
+    /// reads. X, on cpu2, reads cpu1 and is held before it stamps; Y, on cpu3,
+    /// reads every CPU with one more `kick` on cpu1, stamps, loads the
+    /// issuer's 7 and is held before its swap. Two shootdowns later X stamps
+    /// cpu1, reads cpu2 and cpu3 at 9 deliveries and logs 9; Y's swap then
+    /// returns 9, so Y logs 7.
+    #[test]
+    fn irq_census_verdict() -> Result<(), String> {
+        let census = |at: &str, on: u32, cpu: u32, kick: u64, tlb: u64| {
+            let xhci = if cpu == 0 { 40 } else { 0 };
+            format!(
+                "[ {at} cpu{on} kernel] irq: cpu{cpu} timer=100 kick={kick} xhci={xhci} userdev=0 \
+                 sound=0 i8042=0 dmafault=0 hda=0 tlb={tlb} nmi=0 spurious=0 unclaimed=0\n"
+            )
+        };
+        let issued = |at: &str, on: u32, total: u64| {
+            format!(
+                "[ {at} cpu{on} kernel] tlb: shootdowns={total} wait=12us max=3us dlopen=0 pcid=0 \
+                 mmio=0 unmap={total} pipe=0 staged=0 bench=0\n"
+            )
+        };
+        let y_cpu2 = census("2.001", 3, 2, 2, 7);
+        let x_cpu3 = census("2.004", 2, 3, 2, 9);
+        let (x_issued, y_issued) = (issued("2.005", 2, 9), issued("2.006", 3, 7));
+        let good = [
+            census("2.000", 2, 0, 3, 0),
+            census("2.001", 3, 0, 3, 0),
+            census("2.001", 3, 1, 6, 7),
+            y_cpu2.clone(),
+            census("2.001", 3, 3, 2, 7),
+            census("2.004", 2, 1, 5, 7),
+            census("2.004", 2, 2, 2, 9),
+            x_cpu3.clone(),
+            x_issued.clone(),
+            y_issued.clone(),
+        ]
+        .concat();
+        irq_census(&good).map_err(|e| format!("two exits stamped out of read order were refused: {e}"))?;
+
+        let refused = |what: &str, capture: &str, says: &str| match irq_census(capture) {
+            Ok(()) => Err(format!("{what} was accepted")),
+            Err(e) if e.contains(says) => Ok(()),
+            Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")),
+        };
+        refused(
+            "an AP's device delivery on a line that is not that AP's last",
+            &good.replace(&y_cpu2, &y_cpu2.replace("xhci=0", "xhci=1")),
+            "addressed to physical destination 0",
+        )?;
+        refused(
+            "a delivery past the largest issued count",
+            &good.replace(&x_cpu3, &census("2.004", 2, 3, 2, 10)),
+            "without being counted",
+        )?;
+        refused("no issuer line", &good.replace(&x_issued, "").replace(&y_issued, ""), "said nothing")?;
+        Ok(())
+    }
+
     /// What the declaration itself has to be, before any of it means anything.
     /// Which shared-boot binaries need `SYS_DEBUG`, asked of their source.
     ///

tests/common/irqcensus.rs

@@ -4,7 +4,8 @@
 //! The guest prints `irq: cpuN timer=… kick=… …` per online CPU whenever a
 //! process exits, on `SYS_SHUTDOWN` and on the blocked-task dump
 //! (`kernel/src/irq_census.rs`). The counters are cumulative since boot, so the
-//! **last** line a capture holds for a CPU is that boot's whole census.
+//! largest count each source reaches on a CPU's lines is that boot's whole
+//! census ([`Census::raise`]).
 //!
 //! Two readers, and they are why this is a module rather than a closure:
 //! `irq_census_conservation` asks whether one boot's census is internally
@@ -89,6 +90,19 @@ impl Census {
         self.by_source[i]
     }
 
+    /// Raise each source to its count in `read`, another line of this CPU.
+    ///
+    /// **Lines are in stamp order, not read order.** A process exit reads the
+    /// counters before `log::emit` stamps its line, and two exits on two CPUs
+    /// run side by side, so a line stamped later can carry the earlier read.
+    /// The counters are monotonic, so the largest count per source is the
+    /// newest read whatever the order of the lines.
+    pub fn raise(&mut self, read: &Self) {
+        for (most, count) in self.by_source.iter_mut().zip(read.by_source) {
+            *most = (*most).max(count);
+        }
+    }
+
     /// Every interrupt this CPU took: the kernel keeps no total apart from its sources.
     pub fn total(&self) -> u64 {
         self.by_source.iter().sum()