aarch64: interrupts:timer_interrupt_running intermittently reads the global tick counter as not advancing (~2% on -cpu cortex-a72)

[ryanbreen]

Summary

One boot in the 50-boot service-sequence battery on fix/prb-producer-custody (branch tip
f4ec3e60 plus the gate-tolerance-removal change) failed the aggregate boot-test score on a
single test:

[TEST:interrupts:timer_interrupt_running:FAIL:timer tick counter not advancing - interrupts not firing]
[TESTS_COMPLETE:107/107:FAILED:1]
[BOOT_TESTS:FAIL:1]

Classifier verdict, verbatim from the gate census:

BOOT_TEST_FAIL — boot test failure: [TEST:interrupts:timer_interrupt_running:FAIL:timer tick counter not advancing - interrupts not firing] (qemu_status=0)

BOOT_TEST_FAIL is a hard-failing bucket and has been one since it was introduced, so this red
is independent of the #635 tolerance removal that the same run was proving.

What the boot actually did

The boot was otherwise healthy and completed the whole service sequence:

• [init] Boot script completed, [spawn] path='/bin/bounce', 15 heartbeats after it
• all 107 boot tests ran; exactly one failed
• zero [INSTRUCTION_ABORT], zero [DATA_ABORT], zero KERNEL PANIC
• zero [RESUME_PC_REFUSED:], zero [RET_DISPATCH_REFUSED:]
• ctx596_divergence=2 (reported, not gated)

Four other timer tests PASSED in the same boot, on both sides of the failure:

225:[TEST:timer:timer_init:PASS]
248:[TEST:timer:timer_ticks:PASS]
255:[TEST:timer:timer_delay:PASS]
259:[TEST:timer:timer_monotonic:PASS]
270:[TEST:interrupts:timer_interrupt_running:FAIL:...]
352:[TEST:timer:timer_quantum_reset_aarch64:PASS]

So the global tick counter demonstrably advanced elsewhere in this same boot.

What the test measures

kernel/src/test_framework/registry.rs:3244 (test_timer_interrupt_running): read
crate::time::timer::get_ticks(), busy-spin until timer::rdtsc() has advanced
(timer::frequency_hz() * 15) / 1000 counter ticks, read get_ticks() again, and fail if the
second read is not strictly greater. TICKS is one global AtomicU64 incremented from the timer
interrupt stub (kernel/src/time/timer.rs:65).

Two mechanisms are consistent with the evidence and NEITHER is verified here:

1. the ~15 ms window really passed with no timer interrupt landing on any CPU;
2. the window was much shorter than 15 ms of real time because frequency_hz() returned a value
   that made wait_ticks small (at the limit, freq == 0 makes wait_ticks == 0 and the spin
   exits immediately, which fails deterministically).

Distinguishing them needs the actual ticks_before/ticks_after/freq/wait_ticks values,
which the test does not currently emit.

Reproduction and rate

• ./docker/qemu/run-aarch64-service-sequence-gate.sh --rebuild (25 boots per profile,
  -M virt,gic-version=3 -smp 4 -m 512, IOPS throttle 2000, 45 s timeout)
• occurred on -cpu cortex-a72 boot 10; -cpu max was 25/25 GREEN
• ./docker/qemu/run-aarch64-boot-test-strict.sh on the same kernel and the same
  -cpu cortex-a72 -smp 4 profile was 20/20 immediately afterwards

Observed rate on this kernel: 1 occurrence in 45 cortex-a72 boots (~2%), 0 in 25 max boots.

Preserved serial

docs/planning/t3g-prb/serials/prb-stage3-ss-gate-cortexa72-boot10-timer-not-advancing-20260823T115457Z.txt

Not established here

Whether this signature is branch-caused or pre-existing is NOT established by this run. It does
not appear in any serial preserved in this repository before today, but no prior campaign
preserved a green boot's serial either, so absence is not evidence. Settling it needs a
same-profile baseline soak (-cpu cortex-a72 -smp 4, IOPS 2000) on main at the same boot count.

Related

Same family of symptom as #536 (timer:timer_delay reading as failed under load), but a
different test and a different field signature.

[ryanbreen]

Re-scope: the oracle that produced this red was invalid. The issue stays open on an instrumented wait.

RCA is complete and converged (two independent slots, reconciled against source at main). It found
a real, mechanism-level defect — but the defect is in the test, and repairing it is not the same
as explaining the recorded red. Neither the title's "~2%" nor "reads the global tick counter as not
advancing" survives as a statement about a kernel defect.

1. What the test actually asserted on aarch64

crate::time::timer::TICKS has exactly one write site, time::timer::timer_interrupt()
(kernel/src/time/timer.rs:65-66), and on aarch64 that write is reached only through the
if cpu_id == 0 arm of arch_impl::aarch64::timer_interrupt::timer_interrupt_handler
(kernel/src/arch_impl/aarch64/timer_interrupt.rs:725-727). The test thread is an ordinary unpinned
kthread (test_framework/executor.rs spawns a plain kthread_run per subsystem; the scheduler
routes it to least_loaded_cpu() over all online CPUs), and four CPUs are online before
[BOOT_TESTS:START].

So test_timer_interrupt_running, while describing itself as "the most important interrupt test —
it proves interrupts are actually being delivered", was asserting:

CPU 0's timer-interrupt stream contained no gap spanning a 15 ms interval of host wall-clock

measured by spinning on unserialized CNTVCT_EL0, which under QEMU TCG advances whether or not that
vCPU thread executed an instruction — the tree already says so in test_timer_delay's own hardening
comment. That is a maximum-latency bound on a peer CPU, on a platform that offers no such bound.

It was simultaneously fail-open in the direction that matters: a completely dead timer on CPU 1, 2
or 3 passed it. That is now proven by mutation, not argued — freezing one peer CPU's tick counter
reddens the repaired test and did not redden the old one.

2. What is not established, and why this issue is not being closed

Four dynamic causes for the recorded red survive, and the preserved serial records none of the fields
that separate them:

	candidate	kernel defect?
(a)	CPU 0 spent ≥15 ms with DAIF.I set	yes
(b)	the CPU-0 vCPU thread was not scheduled by the host for ≥15 ms	no — host
(c)	the test ran with IRQs left masked by the immediately preceding irq_enable_disable test	yes
(d)	genuine transient virtual-timer/GIC PPI delivery failure on CPU 0	yes

Two of those four are live kernel defects. If (a) or (c) produced this red, then repairing the oracle
to read the executing CPU's own counter would make the test pass on a different CPU and silently
retire a real defect. That is exactly why the repair ships with the record rather than instead of
it, and why this issue stays open.

Also dropped en route: the Timer frequency: 62500000 Hz lead in the failing serial is a red
herring. 62.5 MHz is the ordinary cortex-a72 value (the in-repo green a72 serial reports the same,
as does every boot of a fresh 25-boot a72 run), the frequency cancels out of the test's window
arithmetic, and freq == 0 would fail every boot rather than one in forty-five. A filesystem-overlap
correlation lead did not survive recomputation (1/25, not 0/25, and the overlapping green boot
passed).

3. Rate: 0 in 44 is a bound, not proof of absence

A same-profile repro on main (f8cf13f5, -M virt,gic-version=3 -cpu cortex-a72 -smp 4 -m 512,
IOPS 2000, the gate's own script and defaults) produced zero occurrences of this signature across
44 completed boots, including the exact boot index the original report hit. One further boot was
SIGKILLed by unrelated concurrent QEMU activity on the host and is excluded as inconclusive rather
than counted either way.

P(0 | 2.2%, 44) ≈ 0.37, so this is entirely compatible with the rate being unchanged. It bounds the
rate; it does not refute or confirm anything. The closing bar remains the repo's own N₉₅ for this
signature — ≥148 completed post-fix cortex-a72 boots at zero, rounded to 200, on a quiesced host,
with ≥100 max boots alongside since the mechanism predicts max is equally exposed and was simply
under-sampled (0/25 there proves little: P(0 | 2.2%, 25) ≈ 0.57).

4. What has changed on the branch

The aarch64 arm is repaired fail-closed and strictly stronger than before. Nothing is loosened: the
window is not widened, the test is not retried on failure, and no failure rate is admitted.

• A masked entry is refused, never repaired — with its own distinct failure reason. Silently
  calling enable_interrupts() there is precisely what would bury candidate (c).
• The measurement is pinned with the same RAII preempt guard test_timer_delay uses, so the CPU
  whose counter is asserted is the CPU that executed the window, with IRQs left live.
• It asserts the executing CPU's own TIMER_TICK_COUNT slot, and every CPU that was online
  when the window opened, within a hard liveness deadline — liveness being the invariant the kernel
  can guarantee, where the 15 ms latency bound was not. This closes the verified fail-open hole.
• Host starvation is credited only on test_timer_delay's discipline: a large adjacent CNTVCT
  sample gap across which this CPU's IRQ_TOTAL and SYNC_EXCEPTION_COUNT are both unchanged.
  Attempts are bounded and exhausting them is its own distinct failure. It never passes on starvation.
• The x86_64 arm is untouched and was verified, not assumed: interrupts::timer::timer_interrupt_handler
  increments TICKS from every CPU with no cpu_id gate, so reading the global counter there is
  already a whole-machine liveness assertion.

5. The record that makes the next occurrence decisive

On failure only, from ordinary test-thread context (never from timer_interrupt_handler or any other
IRQ path), the test now emits one [TIMER_LIVENESS_RECORD:aarch64] marker carrying: cpu_id, the
online and not-advanced CPU masks, DAIF at entry and exit, frequency, deadline, start/end CNTVCT,
elapsed µs, sample count and largest adjacent gap, credited host stall, local and CPU-0 per-CPU tick
counters before/after, global TICKS before/after, IRQ_TOTAL and SYNC_EXCEPTION_COUNT for both
CPUs before/after, the active timer's control/compare pair, and GICR enable/pending for the timer PPI
on both CPUs.

Each field decides something:

• local tick advanced, CPU-0 tick did not ⇒ the old cross-CPU oracle defect, red was false;
• large sample gap with no local IRQ and no sync exception ⇒ host starvation (b), not ours;
• DAIF.I set at entry ⇒ candidate (c), an interrupt-state restoration defect — files immediately;
• DAIF clear, continuous guest execution, timer enabled/unmasked/expired, GICR reporting the timer
  PPI pending, no local tick ⇒ candidate (d), a real delivery defect;
• timer disabled/masked or a nonsensical CVAL ⇒ a re-arm/programming defect.

The refusal, the whole-machine arm and the record emission are each proven by a single planted
mutation, restored after: a planted masked entry produces the refusal and its record; a frozen peer
CPU 1 reddens the whole-machine arm with not_advanced_mask=0x2 after running the full deadline; a
frozen local slot produces reason=local-cpu-tick-stalled with not_advanced_mask naming the
executing CPU. Unmutated, the test passes in its real profile (108/108 boot tests, a ~1.2 ms window
where the old spin took 15 ms).

6. Collateral filed separately

The analysis surfaced an unrelated correctness defect and it is now #657: get_monotonic_time()
returns TICKS as milliseconds while arm_timer re-arms relatively with no catch-up, so every CPU-0
stall permanently removes that interval from the kernel clock — and the strand oracle measures its
dwell and silence fields in exactly that clock, so it under-counts precisely when the system is
stalled.

7. Disposition

Open. Not a mechanism close, not a rate close. The gate has no tolerance for this signature and
gains none; BOOT_TEST_FAIL stays a hard-failing bucket. The next occurrence is expected to name its
own cause.

[ryanbreen]

Follow-up correction to the #658 instrument-fix summary (review findings F3/F4)

Two claims in my earlier comment need correction:

• x86_64 is any-CPU, not whole-machine liveness. kernel/src/interrupts/timer.rs increments the global TICKS counter on every CPU with no cpu_id gate. Observing that counter advance proves only that some CPU ticked; a dead timer on a peer CPU can still pass. This x86 fail-open hole predates test(aarch64): fail-closed timer-liveness oracle and decisive #644 failure record #658, was not introduced or fixed by the aarch64 repair, and is now tracked in x86_64 test_timer_interrupt_running is any-CPU liveness, not whole-machine — dead peer-CPU timer passes it #659.
• The old-code half of the peer-freeze mutation claim was initially an inference, not an observed run. I have now re-run one identical kernel-level mutation—suppressing CPU 1 own TIMER_TICK_COUNT increment at the single handler write site—against both implementations. The repaired current test failed with not_advanced_mask=0x2 and [TEST:interrupts:timer_interrupt_running:FAIL:an online CPU timer tick did not advance on ARM64 - interrupts not firing]. The actual pre-fix function from commit f75b1be1 passed under the same mutation with [TEST:interrupts:timer_interrupt_running:PASS] and [BOOT_TESTS:PASS] (108/108). Thus the observed result matches the earlier inference, but only this re-run makes the old-code PASS an evidence-backed claim.

Issue #644 remains open; this comment corrects the record rather than rewriting the original history.