perf(gc): drained-side-bytes pressure (#10268) triggers unproductive old-gen cycles — +33% on a regex loop, GC 0.3% -> 19.3% of wall

[proggeramlug]

What happened

05709427da perf(gc): keep drained side bytes in old-reclaim pressure (train 193, v0.5.1571, from #10268) makes a program that builds a large live set and then works over it run three old-generation collection cycles, one of them a full, where it previously ran none. The full frees 59 KB.

On a 1,000,000-iteration RegExp.prototype.test loop the cost is +2,749 instructions per iteration — a 33 % increase — and GC goes from 0.32 % of wall time to 19.3 %.

This was found while measuring #10166 and is not specific to regex: the loop allocates nothing per iteration. What it does is poll safepoints in a program whose live set (1M strings) was built before the loop started.

Measurements

perf stat -e instructions:u, perrymaster (AMD Ryzen 7 7700X, 16 logical cores), release builds from source with --no-auto-optimize, three runs per arm, spread under 0.01 %. The per-call figure subtracts a control program that builds the same million strings and runs no regex; that control is unchanged between the arms (1,314.2 M vs 1,314.3 M, +0.01 %), so the delta is in the loop, not in the setup.

revision		instructions per iteration
388d15a5db	the commit before	8,315
05709427da	this commit	11,064
b3534565d4	start of the same train	8,315
5400dba90c	train 192	8,315
26ef9c9973	train 193	11,064
46084f23e4	train 196	11,064
33690c563	main today	10,979

Bisected by release-building each revision and running the same probe; every revision before 05709427da reads 8,315 and every revision after reads 11,064.

PERRY_GC_DIAG=1, same probe, same host:

	before (388d15a5db)	after (05709427da)
gc-incremental cycle_starts	0	3
steps	0	4,485
completions	0	3
gc-time step_us	0	113,952
gc-time share_permille	32 (3.2 %)	193 (19.3 %)
wall	551 ms	690 ms

The full collection reports trigger=OldGenBytes kind=full steps=1495 units=3061760 wall_us=38243 **freed=59176** — it traced the whole live set and reclaimed 58 KB.

A sampling profile of the after arm shows where the instructions went: gc::verify::remember_retained_old_to_young_slots 2.3 %, gc::oldgen::IncrementalSweepState::step 2.1 %, gc::verify::remember_evacuated_old_to_young_slot 2.1 %, gc::trace::trace_heap_rewrite_slots 2.0 %, gc::trace::ValidPointerSetBuilder::step_arena_walk 1.9 % — none of which appear above 1.5 % on the before arm.

Why it happens

The commit adds what a non-full collection released since the last full into the old-reclaim pressure term, so that the pacing band holds the live reading down. Its own evidence is a lazily-parsed record loop, where the external side term was genuinely what pushed old-reclaim over its band, and where the change removed six of seven fulls.

This probe is the opposite shape: a large live set, almost no external side bytes, and a long loop that polls safepoints without allocating. There the added term pushes old-reclaim pressure over its band rather than under it, and the collections it triggers are unproductive — 59 KB freed for a full pass over a 52 MB live arena (arena_live=52418768).

That is the failure mode #9589 recorded: a sweep must be priced by the bytes it frees, not by occupancy or by a pressure term that does not predict them.

Reproducer

Save as probe.ts and compile with perry compile probe.ts --no-auto-optimize -o probe:

const vals: string[] = [];
for (let i = 0; i < 1000000; i++) vals.push((i % 2 ? "record_" : "!bad_") + i);
const re = /^[a-z]+_[0-9]+$/;
let c = 0;
for (let i = 0; i < vals.length; i++) if (re.test(vals[i])) c++;
console.log(c);

The control, for the subtraction, replaces re.test(vals[i]) with vals[i].length > 0.

perf stat -e instructions:u ./probe
PERRY_GC_DIAG=1 ./probe 2>&1 | grep -E "gc-incremental|gc-time"

Both arms print 500000, so nothing here is a correctness difference.

What I am not claiming

I have not established which workloads depend on the change's intended effect, so this is not a revert request. The question for whoever owns the pacing work is whether the drained-side-bytes term can be scoped to the case it was measured on — a live external side term that a parse-boundary minor actually drains — rather than added to old-reclaim pressure unconditionally. records_array_1m:sparse should keep its 7-fulls-to-1 win; this probe should keep its zero cycles.

[proggeramlug]

The trigger follows per-call scratch churn, not reclaimable garbage

More evidence on the mechanism, from an unrelated branch. #10372 stops RegExp calls from building match scratch per call: instead of a MatchBuffers constructed, charged to the operation's MemoryBudget and released on every call, one per-thread cell is lent to each search and charged once per call for what it lends.

That branch does not touch GC pacing at all, yet on the identical probe it does not trigger the cycles:

same probe, same host	gc-incremental	gc-time step_us	share_permille	wall
main today (33690c563)	cycle_starts=3 steps=4485 completions=3	113,068	193	681 ms
#10372	cycle_starts=0 steps=0 completions=0	0	58	369 ms

So what pushes old-reclaim pressure over its band here is the charge-and-release churn of per-call scratch, not the presence of reclaimable old-generation garbage — the live set is the same 52 MB of strings in both arms, and neither arm has anything worth collecting. The drained-side-bytes term reads that churn as pressure.

This also means the two effects are separable, and #10372's headline number contains both: against today's main it reads −55.4 % per call, but against 92eadb77ab (before this regression) the same change measured −41.8 %. Roughly 2,700 instructions per call of the difference is this issue, not that change. Fixing the pacing term should leave #10372 at its own −41.8 %, and should restore the ~2,700 for every other workload of this shape that has no scratch-churn accident to hide behind.

[proggeramlug]

Fix up in #10377: the three regex scratch owners report their release through a transient path that lowers the live reading without entering the drained term. On the reproducer the probe goes 10,979 → 8,219 instructions per call and gc-incremental returns to cycle_starts=0 completions=0, GC 193‰ → 32‰ of wall — the readings from before #10268 landed.

#10268's cadence is untouched by construction: the JSON tape, Map/Set buffers and the node-api delta all keep the existing path, so the tape workload cannot observe the change. A probe modelled on records_array_1m:sparse reads identically on main and on the branch (cycle_starts=1 steps=7 completions=0, no fulls).

Full suite 3955 passed / 0 failed; the regression test is sabotage-proved. If the pacing owner would rather fix it at the term's definition — bounding the reconstruction by what a collection actually observed live, rather than by who reports the release — that subsumes this and I'd rather it landed instead.

[proggeramlug]

#10377 is withdrawn: it regresses regex-replace-callback by 8.3 % at n=700,000 and 16.4 % at n=1,000,000, with GC share rising 567‰ → 747‰ on 79 % fewer cycles. Fewer cycles meet a bigger live heap, so each marks more and the armed-barrier window between them taxes every write. The transient churn it removed was accidentally acting as an allocation-rate proxy — the only signal tracking how fast the program made garbage.

This issue stands: the reproducer still pays three old-gen cycles and a full that traces a 52 MB arena to free 59 KB, on bytes no collection ever saw live. What changes is the acceptance bar for a fix — it must be measured on regex-replace-callback at n ≥ 700,000 as well as on the reproducer here, because a small live set is exactly the regime where removing the false pressure is free. The fix needs to keep a churn signal rather than only delete a wrong one. Details on #10377.

[proggeramlug]

Fixed on main by #10372 — closing

Re-measured on e6dcb6274d (v0.5.1587), which carries #10372 (perex 0.1.7 plus the lent match scratch). The reproducer from the issue body:

	before (33690c563)	now (e6dcb6274d)
instructions per call	10,979	4,792
gc-incremental	cycle_starts=3 completions=3	cycle_starts=0 completions=0
GC share of wall	193‰	52‰

The three old-generation cycles are gone, including the full that traced a 52 MB live arena to free 59 KB.

No pacing change was needed. #10372 stopped find_near from building a MatchBuffers per call and lending it from a per-thread cell instead, which removed the per-call gc_note_external_side_alloc / _free pair at source. The drained term never sees that churn now, so the false pressure this issue is about cannot accumulate on the regex path. The fix landed for an unrelated reason — per-call cost — and took this with it.

The accounting quirk remains, in principle, and should stay unfixed until something exhibits it

gc_note_external_side_free still adds to GC_EXTERNAL_SIDE_DRAINED_SINCE_FULL for every release, including mutator-side releases of allocations that were never retained past the operation. That is still wrong in meaning — the drained term exists to reconstruct bytes a cheap collection released earlier than a full would have, and a same-call release is not early. Map/Set buffers and the JSON tape still report through it.

I have no workload that exhibits it, and the one attempt to fix it blind was withdrawn (#10377) after it regressed regex-replace-callback by 8.3 % at n=700,000 and 16.4 % at n=1,000,000. The mechanism there is worth keeping on the record: removing the false pressure made old-reclaim fire later, so each cycle met a bigger live heap — fewer cycles, more marking in each, and a longer armed mark-barrier window taxing every write between them. The transient churn was accidentally serving as an allocation-rate proxy, the only signal tracking how fast the program produced garbage.

If this reopens, the acceptance bar is: measured on regex-replace-callback at n ≥ 700,000 as well as on the reproducer above. A small live set is exactly the regime where removing the false pressure is free, so the reproducer alone cannot show the cost. And the replacement must add a signal, not only delete a wrong one.

Related result, for anyone arriving here from the GC side

On current main every collection this workload runs is productive: at n=700,000, 38 fulls freeing a median 180 MB and 151 minors freeing a median 154 MB, none freeing zero. Before #10372 the median collection at n=200,000 freed 0 bytes. The 667‰ GC share that workload still shows at 700k is real collection of real garbage — the remaining cost there is allocation volume (~3.3 KB per match on a workload whose per-match data is ~10 bytes), which is #10164/#10165's problem, not a pacing one.