Trace ring's unfiltered window on a dispatching CPU is 15-30 ms, not seconds: CTX_DIAG/DEFER_REQUEUE dominate it

[ryanbreen]

The reading

The failure-trace-capture PR-3 emitter's [BXCAP:RING] section reports the
live window of the capturing CPU's trace ring. On its first boots, from
--features boot_tests,capture_selftest strict-gate runs at 3000 ms of guest
uptime on an aarch64 cortex-a72 -smp 4 guest:

[BXCAP:RING cpu=2 writes=475557 dropped=474533 kept=1024 span_us=29958 enabled=1]
[BXCAP:RING cpu=3 writes=478191 dropped=477167 kept=1024 span_us=15410 enabled=1]

15 to 30 milliseconds of history, with ~477k events already overwritten by
3 seconds of uptime.

Why this is not a contradiction of #852 / PR-2

PR-2's [RING_SPAN:cpu=0:...] self-check measures CPU 0's ring filtered to
TIMER_TICK events, and reports ~1500 ms after its sampling fix. That is
the right measurement for the question PR-2 asked -- whether sampling widened
the tick history -- and it is accurate.

The unfiltered window is a different quantity. The CTX_DIAG_* and
DEFER_REQUEUE_* families (0xff39-0xff48) emit roughly a dozen ring
events per dispatch, and on a CPU that is dispatching steadily they dominate
the 1024-entry buffer. TIMER_TICK entries survive across ~1.5 s because they
are sparse; everything around them is 15-30 ms deep.

Why it matters to the rest of the program

PR-4 wires the capture to the terminal edges, and a fault's EV tail is read
from whichever CPU faulted -- not from CPU 0, and not filtered. So the
pre-fault timeline a fault capture carries today is 15-30 ms wide on a busy
CPU, not the seconds the plan's section 2.2 arithmetic assumes.

Options, none taken here:

• Raise TRACE_BUFFER_SIZE (plan section 8, Q4: 1024 -> 4096 costs 16 CPUs x
  64 KiB = 1 MiB of .bss and buys 4x with no information loss).
• Sample or gate the CTX_DIAG_* / DEFER_REQUEUE_* families the way PR-2
  sampled TIMER_TICK. They are diagnostic instrumentation from the aarch64: the outgoing-thread previous_thread marker is cleared without requeuing (Ready-shape strand, 1/50 SS-gate boots) — and the naive rollback turns it into #576 #607/aarch64: a kernel-STACK resume PC is reached (dispatch-path unproven, R41) — [INSTRUCTION_ABORT] FAR==ELR==x30==x29, ESR=0x8600000e IFSC=0xe, 3/200 clean SS-gate boots on both CPU profiles #635
  campaigns, not a permanent contract.
• Give EV a type filter so a fault capture emits the newest N events of the
  types a reader wants, rather than the newest N of any type.

Evidence

docs/planning/green-program/failure-capture/serials/pr3/aarch64-selftest-complete.txt
and aarch64-selftest-sched-lock-held.txt in this repo carry [BXCAP:RING]
lines from real boots. Round doc: docs/planning/green-program/failure-capture/PR-3-2026-09-05.md
section 6.4.

[ryanbreen]

Scheduler diagnostic sampling is implemented and pushed in 504d366 on tracing/855-ring-window; #855 remains open because the requested 1500 ms target is unmet.

• TRACE_DIAG_SAMPLE stays 1024; separate TRACE_SCHED_DIAG_SAMPLE is 16384.
• Factor 8192 strict x3: 921, 895, 901 ms (exit 1).
• Factor 16384 strict x3: 896, 938, 936 ms (exit 1).
• GDB at capture entry: SCHED_DIAG now occupies only 6, 9, 6 of 1024 peer slots; switch-entry plus queue-state events occupy 772, 722, 784 slots, and reschedule IPI events occupy 196, 248, 192 slots. Further SCHED_DIAG-only tuning stopped based on this evidence.
• The scheduler ratchet passes 9/9, including guard deletion; production-profile gate exits 0. Both claim-lint modes exit 0. Beast x86 no-regression gate exits 0 at 504d366, including 55/55 structure suites. Validation evidence is pushed in 134343d. Both final claim-lint modes exit 0.

Follow-up tracked here: determine retention policy for the ordinary switch/queue/IPI providers. No target reduction or ring-size change was made. Current failed serials, GDB dump, decoded counts and round document: docs/planning/green-program/tracing/SCHED-DIAG-855-2026-09-07.md and docs/planning/green-program/tracing/serials/855/. The previous failed evidence is retained.

[ryanbreen]

Closing note (the prior comment on this thread, from mid-round, is superseded -- it reported the 1500 ms target as unmet at the TRACE_SCHED_DIAG_SAMPLE plateau; the round continued past that point).

Final state on tracing/855-ring-window (pushed, 3c2a4b2a):

• Sampled the three diagnostic families the ring's flood traced to (2/2 named in this issue plus one found mid-round): CTX_DIAG_*/DEFER_REQUEUE_* (TRACE_DIAG_SAMPLE=1024, context_switch.rs) and SCHED_DIAG_* (TRACE_SCHED_DIAG_SAMPLE=8192, scheduler.rs, found mid-round -- the issue's own 0xff39-0xff48 range included it but the first pass missed it).
• Sampling alone plateaued at ~900 ms against legitimate, non-diagnostic scheduler traffic (CTX_SWITCH_ENTRY, SCHED_QUEUE_STATE, reschedule IPIs) that must not be sampled -- confirmed via a live GDB probe, not assumed.
• Closed the remaining gap with the issue's own Option 1: TRACE_BUFFER_SIZE 1024 -> 2048 (256 KiB additional .bss on each architecture, independently confirmed via llvm-nm -S).

Accepted evidence, three strict-gate boots:

[RING_SPAN_UNFILTERED:cpu=2:span_ms=1801:writes=4250:dropped=2202]
[RING_SPAN_UNFILTERED:cpu=3:span_ms=1638:writes=4275:dropped=2227]
[RING_SPAN_UNFILTERED:cpu=3:span_ms=1793:writes=4203:dropped=2155]

1638-1801 ms against the 1000 ms floor. All gates green: both new structure ratchets (12/12, 10/10), aarch64 strict x3, aarch64 production profile, beast x86 (no-regression, -smp 1 has no non-diagnostic SCHED_DIAG/CTX_DIAG traffic to measure), both claim-lint modes.

Round doc, independently re-verified rather than only reported: docs/planning/green-program/tracing/855-RING-WINDOW-2026-09-06.md. Raw evidence, including the intermediate plateau's failing serials and the GDB dump that explains it: docs/planning/green-program/tracing/serials/855/.

[ryanbreen]

Landed via #915 (merge commit 891ae034f8c0bb5de0b9ad400cf6524a7e92645c).

Before (this issue's own reading, --features boot_tests,capture_selftest,
[BXCAP:RING], unfiltered window on a dispatching CPU):

[BXCAP:RING cpu=2 writes=475557 dropped=474533 kept=1024 span_us=29958 enabled=1]
[BXCAP:RING cpu=3 writes=478191 dropped=477167 kept=1024 span_us=15410 enabled=1]

15-30 ms.

After (the new [RING_SPAN_UNFILTERED:...] self-check, same
measurement point, three accepted strict-gate boots plus a fourth landing
boot):

[RING_SPAN_UNFILTERED:cpu=2:span_ms=1801:writes=4250:dropped=2202]
[RING_SPAN_UNFILTERED:cpu=3:span_ms=1638:writes=4275:dropped=2227]
[RING_SPAN_UNFILTERED:cpu=3:span_ms=1793:writes=4203:dropped=2155]
[RING_SPAN_UNFILTERED:cpu=2:span_ms=1894:writes=3945:dropped=1897]

1638-1894 ms across the four boots, above the 1000 ms floor this issue's
own dispatch brief set and above the 1500 ms margin target, with RED
reproduced unmodified on main (33.6 ms, same emitter) as the
mutation-to-red proof.

.bss delta: TRACE_BUFFERS grew from 0x40400 (263,168 bytes) to
0x80400 (525,312 bytes), llvm-nm -S-confirmed on the built kernel
binary -- a TRACE_BUFFER_SIZE 1024 -> 2048 change, +262,144 bytes
(256 KiB), arch-neutral (kernel/src/tracing/buffer.rs is shared).

Sampling three diagnostic ring-write families
(CTX_DIAG_*/DEFER_REQUEUE_*, context_switch.rs; SCHED_DIAG_*,
scheduler.rs, a third family this issue's own reading did not name) did
the rest of the work; each keeps a registered drop counter
([BXCAP:CNT]), and legitimate non-diagnostic scheduler traffic
(CTX_SWITCH_ENTRY, SCHED_QUEUE_STATE, the resched-IPI events) is
outside each sampling guard.

Full accounting, including a same-day review pass that fixed a same-CPU-only
ring-read race and cache-line false sharing in the new oracle before this
landed: the round doc.

Not closing the atlas Tracing row to HIGH: five other open issues
(#522, #537, #588, #628, #816, #847) still live under kernel/src/tracing/;
see the round doc's post-merge sweep section.