diag(gc): report incremental cycles that start and never finish (#7909)

A budgeted incremental cycle emits nothing until it COMPLETES — the `[gc]`
trace is written by `gc_finish_budgeted_cycle`. A cycle that is started and
then starved is therefore completely invisible: no trace line, no counter,
nothing, while the mutator pays the SATB mark barrier on every heap store,
every shadow-slot root store and every allocation for as long as it stays
open.

`gc-handoff/apps/asyncpipe.ts` is in exactly that state, which is why it reads
as "zero GC cycles, but a third of the leaf profile is collector machinery".
`PERRY_GC_DIAG=1` (existing knob, no new knob) now prints at the process-exit
boundary:

  [gc-incremental] cycle_starts=1 steps=15 completions=0 active_at_exit=true
                   mark_barrier_arms=1 mark_barrier_armed_us=37214
                   skips(reentrant=0 no_trigger=2 start_blocked=0 resume_blocked=0)
                   safepoints_blocked_by_budgeted=0 copying_minors=0
                   loop_polls=1 poll_arm_events=0 poll_armed_at_exit=0

One cycle started, fifteen steps, zero completions, still active at exit, the
mark barrier armed for 37 ms of a 127 ms program, and not one collection.

No behaviour change. The mechanism, and the measured negative on the obvious
fix (+51.4 % instructions, +57 % RSS, because the minors it unblocks are priced
by #7915), are written up in `gc-handoff/GC7909-NOTES.md`.

Claude-Session: https://claude.ai/code/session_012B8z92S82sCfqCrVqrFgS2

Author: Ralph Küpper

changelog.d/7923-gc-incremental-cycle-stall-instrument.md

@@ -0,0 +1,74 @@
+### `gc`: report incremental cycles that start and never finish (#7909)
+
+A budgeted incremental cycle emits nothing until it *completes* — the `[gc]`
+trace is written by `gc_finish_budgeted_cycle`. So a cycle that is started and
+then starved is completely invisible: no trace line, no counter, no diagnostic,
+while the mutator pays the SATB mark barrier on every heap store, every
+shadow-slot root store and every allocation (allocate-black) for as long as the
+cycle stays open.
+
+`gc-handoff/apps/asyncpipe.ts` is in exactly that state on `main`, and it is
+why the program reads as "zero GC cycles, but a third of the leaf profile is
+collector machinery". `PERRY_GC_DIAG=1` now prints, at the process-exit
+boundary:
+
+```
+[gc-incremental] cycle_starts=1 steps=15 completions=0 active_at_exit=true
+                 mark_barrier_arms=1 mark_barrier_armed_us=37214
+                 skips(reentrant=0 no_trigger=2 start_blocked=0 resume_blocked=0)
+                 safepoints_blocked_by_budgeted=0 copying_minors=0
+                 loop_polls=1 poll_arm_events=0 poll_armed_at_exit=0
+```
+
+One cycle started, fifteen steps, zero completions, still active at exit, the
+mark barrier armed for **37 ms of a 127 ms program**, and not one collection
+performed. No new env knob — this is the existing `PERRY_GC_DIAG`.
+
+#### The mechanism the numbers describe
+
+* `nursery_cap_active()` **is** `gc_moving_loop_polls_enabled()`, so the
+  young-generation scavenge cap (16 MB, `PERRY_GC_SCAVENGE_NURSERY_MB`) goes due
+  and — because nothing collects — stays due.
+* every microtask drain runs `gc_runtime_safepoint()`, which starts a budgeted
+  cycle as soon as *any* trigger is due, including that one.
+* the cycle it starts is `low_pause_non_moving` by construction, so it cannot
+  evacuate and cannot lower `copying_from_space_in_use_bytes()` — the quantity
+  the cap tests.
+* while it is active, `gc_safepoint_moving_minor` rejects every precise
+  safepoint at its `budgeted` entry guard, so the collector that *could* clear
+  the trigger never runs again.
+* and at the pump's cadence (2048 work units per drain, ~17 drains in the whole
+  program) it cannot finish.
+
+The alloc-point path already routes nursery pressure away from the budgeted
+stepper for exactly this reason; the host-safepoint path does not.
+
+#### What the loop poll had to do with it: nothing
+
+`PERRY_GC_MOVING_LOOP_POLLS=0` measures −14 % on that program, which read as
+"incremental work driven at back-edge polls". The new counters retire that:
+`poll_arm_events=0`, `loop_polls=1` — the back-edge poll is armed zero times and
+taken once (the startup seed release) in the whole run. The knob acts only
+through `nursery_cap_active()`. `PERRY_GC_SCAVENGE_NURSERY_MB=4096`, which moves
+the cap and nothing else, reproduces it to three digits: −11.81 % vs −11.81 %
+(instructions retired, best of 7).
+
+#### Fix deliberately NOT shipped here
+
+Giving the precise collector first refusal at the pump boundary removes the
+stall completely (`cycle_starts` 1 → 0, `mark_barrier_armed_us` 37 214 → 0,
+`copying_minors` 0 → 2, all 19 corpus programs byte-identical) and costs
+**+51.4 % instructions and +57 % RSS** on `asyncpipe`, because the two minors it
+unblocks are priced by #7915: one of them is a **134 ms minor that copied zero
+objects**, spending its time scanning 82 registered runtime mutable root
+scanners over 218 455 pointer roots. With no nursery trigger due the reorder is
+inert to three digits (1691.7 M vs 1692.0 M), so that is the price of
+collecting, not of the change. It is recorded in
+`gc-handoff/GC7909-NOTES.md` §4 and belongs after #7915, not before it.
+
+Tests: `an_active_budgeted_cycle_locks_out_the_moving_minor_and_keeps_the_barrier_armed`
+pins the composition and asserts its own subject was live (the trigger is due,
+the cycle really was started by the call under test, the block is attributed to
+the `budgeted` guard specifically, and the completion counter moves too — so
+`starts > completions` can be read as a stall rather than as a dead fixture);
+`arm_events_count_arms_and_the_word_is_reported` pins the poll-arming pair.

crates/perry-runtime/src/gc/barrier/mod.rs

@@ -761,6 +761,7 @@ pub(super) fn incremental_mark_barrier_enable(valid_ptrs: &ValidPointerSet, mino
     // its insertion barrier — a lost mark, i.e. a live object swept.
     let newly_active = INCREMENTAL_MARK_BARRIER_VALID_PTRS.with(|cell| cell.get().is_null());
     if newly_active {
+        super::instruments::note_mark_barrier_armed();
         PERRY_INCREMENTAL_MARK_BARRIER_ACTIVE_COUNT.fetch_add(1, Ordering::SeqCst);
     }
     INCREMENTAL_MARK_BARRIER_VALID_PTRS.with(|cell| cell.set(valid_ptrs as *const ValidPointerSet));
@@ -773,6 +774,7 @@ pub(super) fn incremental_mark_barrier_disable() {
         was_active
     });
     if was_active {
+        super::instruments::note_mark_barrier_disarmed();
         let _ = PERRY_INCREMENTAL_MARK_BARRIER_ACTIVE_COUNT.fetch_update(
             Ordering::SeqCst,
             Ordering::SeqCst,

crates/perry-runtime/src/gc/instruments.rs

@@ -58,3 +58,153 @@ pub(crate) fn note_loop_poll_reached() {
 pub fn loop_polls_reached() -> u64 {
     LOOP_POLLS.load(Ordering::Relaxed)
 }
+
+static INCREMENTAL_CYCLE_STARTS: AtomicU64 = AtomicU64::new(0);
+static INCREMENTAL_STEPS: AtomicU64 = AtomicU64::new(0);
+static INCREMENTAL_COMPLETIONS: AtomicU64 = AtomicU64::new(0);
+
+/// A budgeted (incremental) cycle was STARTED.
+#[inline]
+pub(crate) fn note_incremental_cycle_start() {
+    INCREMENTAL_CYCLE_STARTS.fetch_add(1, Ordering::Relaxed);
+}
+
+/// One budgeted step advanced an active incremental cycle. This counts the
+/// mutator-assist slices an allocating program pays *between* collections, so a
+/// run whose `[gc]` output is empty can still show what the incremental
+/// collector charged it.
+#[inline]
+pub(crate) fn note_incremental_step() {
+    INCREMENTAL_STEPS.fetch_add(1, Ordering::Relaxed);
+}
+
+/// A budgeted cycle reached its finisher.
+#[inline]
+pub(crate) fn note_incremental_completion() {
+    INCREMENTAL_COMPLETIONS.fetch_add(1, Ordering::Relaxed);
+}
+
+/// Budgeted incremental cycles started in this process.
+pub fn incremental_cycle_starts() -> u64 {
+    INCREMENTAL_CYCLE_STARTS.load(Ordering::Relaxed)
+}
+
+/// Budgeted incremental steps executed in this process.
+pub fn incremental_steps() -> u64 {
+    INCREMENTAL_STEPS.load(Ordering::Relaxed)
+}
+
+/// Budgeted incremental cycles completed in this process.
+pub fn incremental_completions() -> u64 {
+    INCREMENTAL_COMPLETIONS.load(Ordering::Relaxed)
+}
+
+static MARK_BARRIER_ARM_EVENTS: AtomicU64 = AtomicU64::new(0);
+static MARK_BARRIER_ARMED_US: AtomicU64 = AtomicU64::new(0);
+/// Microseconds-since-`process_epoch` at which the currently-open armed window
+/// started, `0` when no window is open. Lock-free on purpose: this runs inside
+/// the collector, where taking a lock is a hazard nobody should have to reason
+/// about for a counter.
+static MARK_BARRIER_ARMED_SINCE_US: AtomicU64 = AtomicU64::new(0);
+
+fn process_epoch_us() -> u64 {
+    static EPOCH: std::sync::OnceLock<std::time::Instant> = std::sync::OnceLock::new();
+    EPOCH
+        .get_or_init(std::time::Instant::now)
+        .elapsed()
+        .as_micros() as u64
+}
+
+/// The incremental (SATB) mark barrier became armed on some thread.
+///
+/// The barrier is not a per-cycle cost — it is a *per-microsecond* one. While
+/// it is armed, every heap-pointer store, every shadow-slot root store and
+/// every allocation (allocate-black) in the program pays for the cycle, so what
+/// a cost investigation needs is the wall time it stays armed, not how many
+/// cycles armed it. On `gc-handoff/apps/asyncpipe.ts` that is 37 ms of a 127 ms
+/// program spent shading for a cycle that never completes and never collects
+/// anything (#7909) — a number that was previously not observable at all.
+pub(crate) fn note_mark_barrier_armed() {
+    MARK_BARRIER_ARM_EVENTS.fetch_add(1, Ordering::Relaxed);
+    // `+1` so an arm at epoch microsecond 0 stays distinguishable from "closed".
+    let now = process_epoch_us().saturating_add(1);
+    let _ =
+        MARK_BARRIER_ARMED_SINCE_US.compare_exchange(0, now, Ordering::Relaxed, Ordering::Relaxed);
+}
+
+/// The incremental mark barrier was disarmed.
+pub(crate) fn note_mark_barrier_disarmed() {
+    let started = MARK_BARRIER_ARMED_SINCE_US.swap(0, Ordering::Relaxed);
+    if started != 0 {
+        let now = process_epoch_us().saturating_add(1);
+        MARK_BARRIER_ARMED_US.fetch_add(now.saturating_sub(started), Ordering::Relaxed);
+    }
+}
+
+/// How many times the incremental mark barrier was armed.
+pub fn mark_barrier_arm_events() -> u64 {
+    MARK_BARRIER_ARM_EVENTS.load(Ordering::Relaxed)
+}
+
+/// Microseconds the incremental mark barrier has been armed, including a window
+/// still open at the time of the call — a starved cycle's window never closes,
+/// and that is exactly the case this number exists to report.
+pub fn mark_barrier_armed_us() -> u64 {
+    let closed = MARK_BARRIER_ARMED_US.load(Ordering::Relaxed);
+    let started = MARK_BARRIER_ARMED_SINCE_US.load(Ordering::Relaxed);
+    let open = if started == 0 {
+        0
+    } else {
+        process_epoch_us().saturating_add(1).saturating_sub(started)
+    };
+    closed + open
+}
+
+static MOVING_SAFEPOINT_BLOCKED_BY_BUDGETED: AtomicU64 = AtomicU64::new(0);
+
+/// A precise safepoint was rejected because a budgeted cycle was active.
+#[inline]
+pub(crate) fn note_moving_safepoint_blocked_by_budgeted() {
+    MOVING_SAFEPOINT_BLOCKED_BY_BUDGETED.fetch_add(1, Ordering::Relaxed);
+}
+
+/// How many precise safepoints an active budgeted cycle rejected.
+pub fn moving_safepoints_blocked_by_budgeted() -> u64 {
+    MOVING_SAFEPOINT_BLOCKED_BY_BUDGETED.load(Ordering::Relaxed)
+}
+
+/// Why a budgeted step did no work. Every arm is a distinct reason a cycle can
+/// stall, and a stalled-but-active cycle keeps the mark barrier armed.
+#[derive(Clone, Copy)]
+pub(crate) enum BudgetedStepSkip {
+    Reentrant,
+    NoTrigger,
+    StartBlocked,
+    ResumeBlocked,
+}
+
+static SKIP_REENTRANT: AtomicU64 = AtomicU64::new(0);
+static SKIP_NO_TRIGGER: AtomicU64 = AtomicU64::new(0);
+static SKIP_START_BLOCKED: AtomicU64 = AtomicU64::new(0);
+static SKIP_RESUME_BLOCKED: AtomicU64 = AtomicU64::new(0);
+
+#[inline]
+pub(crate) fn note_budgeted_step_skip(reason: BudgetedStepSkip) {
+    match reason {
+        BudgetedStepSkip::Reentrant => &SKIP_REENTRANT,
+        BudgetedStepSkip::NoTrigger => &SKIP_NO_TRIGGER,
+        BudgetedStepSkip::StartBlocked => &SKIP_START_BLOCKED,
+        BudgetedStepSkip::ResumeBlocked => &SKIP_RESUME_BLOCKED,
+    }
+    .fetch_add(1, Ordering::Relaxed);
+}
+
+/// `(reentrant, no_trigger, start_blocked, resume_blocked)`.
+pub fn budgeted_step_skips() -> (u64, u64, u64, u64) {
+    (
+        SKIP_REENTRANT.load(Ordering::Relaxed),
+        SKIP_NO_TRIGGER.load(Ordering::Relaxed),
+        SKIP_START_BLOCKED.load(Ordering::Relaxed),
+        SKIP_RESUME_BLOCKED.load(Ordering::Relaxed),
+    )
+}

crates/perry-runtime/src/gc/mod.rs

@@ -1036,9 +1036,51 @@ pub extern "C" fn js_gc_release_current_thread_collection_side_allocations() {
     // safepoints the schedule actually saw. Inert (one cached-`Option` load) and
     // once-only when the mode is off.
     schedule::report_exit_summary();
+    emit_incremental_liveness_diag();
     emit_schedule_liveness_verdict();
 }
 
+/// `PERRY_GC_DIAG=1`: what the INCREMENTAL collector charged this run, whether
+/// or not any cycle completed (#7909).
+///
+/// Every other GC diagnostic is emitted per completed cycle, so a run that
+/// starts a budgeted cycle and never finishes it prints nothing at all — the
+/// `asyncpipe` shape, where the collector's own output is empty while a third
+/// of the leaf profile is collector machinery. `cycle_starts > completions`
+/// with a large `steps` is exactly that state, and it is only visible here.
+fn emit_incremental_liveness_diag() {
+    if !telemetry::gc_diag_enabled() {
+        return;
+    }
+    if !crate::native_handle::is_main_thread_or_unrecorded() {
+        return;
+    }
+    static EMITTED: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false);
+    if EMITTED.swap(true, std::sync::atomic::Ordering::SeqCst) {
+        return;
+    }
+    let (reentrant, no_trigger, start_blocked, resume_blocked) = instruments::budgeted_step_skips();
+    eprintln!(
+        "[gc-incremental] cycle_starts={} steps={} completions={} active_at_exit={} \
+         mark_barrier_arms={} mark_barrier_armed_us={} \
+         skips(reentrant={reentrant} no_trigger={no_trigger} start_blocked={start_blocked} \
+         resume_blocked={resume_blocked}) safepoints_blocked_by_budgeted={} \
+         copying_minors={} loop_polls={} poll_arm_events={} \
+         poll_armed_at_exit={}",
+        instruments::incremental_cycle_starts(),
+        instruments::incremental_steps(),
+        instruments::incremental_completions(),
+        policy::gc_budgeted_cycle_active(),
+        instruments::mark_barrier_arm_events(),
+        instruments::mark_barrier_armed_us(),
+        instruments::moving_safepoints_blocked_by_budgeted(),
+        instruments::copying_minor_cycles(),
+        instruments::loop_polls_reached(),
+        poll_arm::poll_arm_events(),
+        poll_arm::poll_armed_count(),
+    );
+}
+
 /// Print what the rate-1 schedule endpoint actually did, and **fail the
 /// process** when the answer is "nothing" (#7604).
 ///

crates/perry-runtime/src/gc/policy.rs

@@ -2573,6 +2573,14 @@ pub(crate) fn gc_safepoint_moving_minor() -> bool {
     if in_alloc || unsafe_zone || root_lock || budgeted {
         // Blocked right now — leave GC_SAFEPOINT_PENDING set so the next poll
         // retries; do not clear it here.
+        //
+        // #7909: `budgeted` is the arm that can be PERMANENT. A budgeted cycle
+        // started for nursery pressure that this pump's cadence cannot finish
+        // rejects every later safepoint here, forever, so it is counted apart
+        // from the transient arms.
+        if budgeted {
+            super::instruments::note_moving_safepoint_blocked_by_budgeted();
+        }
         return false;
     }
     // We are handling this safepoint (collect or find nothing due): clear the
@@ -3220,14 +3228,23 @@ fn gc_budgeted_step_work_units_inner_with_progress(
     }
 
     let Some(_guard) = BudgetedGcStepGuard::enter() else {
+        super::instruments::note_budgeted_step_skip(
+            super::instruments::BudgetedStepSkip::Reentrant,
+        );
         return gc_budgeted_skipped_result();
     };
 
     if !gc_budgeted_cycle_active() {
         if gc_budgeted_due_trigger().is_none() {
+            super::instruments::note_budgeted_step_skip(
+                super::instruments::BudgetedStepSkip::NoTrigger,
+            );
             return gc_idle_step_result();
         }
         if gc_budgeted_start_blocked() {
+            super::instruments::note_budgeted_step_skip(
+                super::instruments::BudgetedStepSkip::StartBlocked,
+            );
             return gc_budgeted_skipped_result();
         }
         let cycle = gc_start_budgeted_cycle_for_pressure(start_progress_kind)
@@ -3236,9 +3253,13 @@ fn gc_budgeted_step_work_units_inner_with_progress(
             *slot.borrow_mut() = Some(cycle);
         });
         GC_BUDGETED_CYCLE_ACTIVE.with(|active| active.set(true));
+        super::instruments::note_incremental_cycle_start();
     }
 
     if gc_budgeted_resume_blocked() {
+        super::instruments::note_budgeted_step_skip(
+            super::instruments::BudgetedStepSkip::ResumeBlocked,
+        );
         return gc_budgeted_skipped_result();
     }
 
@@ -3250,7 +3271,9 @@ fn gc_budgeted_step_work_units_inner_with_progress(
         };
 
         let step = cycle.state.step(GcWorkBudget::bounded(work_units));
+        super::instruments::note_incremental_step();
         if step.completed {
+            super::instruments::note_incremental_completion();
             BudgetedStepOutcome::Completed(slot.take().expect("active budgeted GC cycle exists"))
         } else {
             BudgetedStepOutcome::Result(gc_cycle_step_result(