[e2e] Decay the repro's poke pump instead of stopping at the budget - #3561
[e2e] Decay the repro's poke pump instead of stopping at the budget#3561VaguelySerious wants to merge 3 commits into
Conversation
A hard ceiling bought the lanes their green at the cost of coverage: every step-storm run on both local lanes spent the full 64-poke budget, so the back half of a ~160s run applied no out-of-band writes at all. Lowering attempt concurrency does not help — at c3 runs finish in 87-96s and still spend the whole budget. The pump now slows to `pokeIntervalMs * POKE_DECAY_FACTOR` (8) once the budget is spent rather than stopping, so loop gain stays below 1 while a slow run's later rounds keep receiving pressure. Verified locally at POKE_MAX=4 / 500ms / decay 10: a 26.1s run sent 8 pokes, 4 at full cadence and 4 across the remaining 24s, where unbounded sends ~52 and a hard stop sends 4. The lanes were never comparable on this axis to begin with: a Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (35-44 pokes per run) while localhost runs the full 750ms. The decayed rate is what puts the local lanes near the lane that found the production bug, rather than at 3x its write rate. Also records what the saturated lanes are NOT: world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes, because its semaphore parks a message before the delivery fetch and queue waiting never consumes the transport timeout. No retry amplification to find. The two default-concurrency smells that did surface (world-local's 1000 in-flight deliveries, world-postgres' 50 workers per process) are noted for their own change, not fixed here. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
With the pump's pressure restored, world-local `step-storm` lands at 194-203s and world-postgres at 168-175s against the harness' 240000 default — 83% of their own timeout — while the Vercel lane finishes the same storm in 85-100s. One slow runner at that margin turns a lane that reproduces into a lane full of `stuck`, which is the failure this branch exists to stop. The local script raises it to 480000. It is the one scale knob the script sets, because it is the one whose meaning depends on every replay of every run sharing a Node process rather than getting its own Fluid invocation; an exported value still wins, and a workflow_dispatch input still wins. Evidence the restored pressure is worth the timeout: on the decay config world-local produced a CORRUPTED_EVENT_LOG (wrun_01M00SW88YV76AXKXQFX4Y3V1X, 87 pokes over 200s), which three passes of the hard-cap config never did. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
🦋 Changeset detectedLatest commit: 5426321 The changes in this PR will be included in the next version bump. This PR includes changesets to release 0 packagesWhen changesets are added to this PR, you'll see the packages that this PR includes changesets for and the associated semver types Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
🧪 E2E Test Results✅ All tests passed E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ vercel-multi-region
|
📊 Workflow Benchmarkscommit Backend:
📈 STSO distribution (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: 172410ms over 1019 samples No ℹ️ Metric definitions & methodologyThe collapsed STSO distribution section above buckets every step gap of the sequential-steps run (not a sampled window), split by whether the step ending the gap ran inline — in the same warm process as the step before it, so the gap is pure framework overhead — or after a queue-hop — the first step of a fresh process, which pays queue dispatch, client reinit and event-log replay. Bars overlay the two runs: Best/P75/P90/P99 deltas compare against the most recent benchmark run on Metrics — TTFS: time to first step body (in-deployment start() → first step body, deployment clocks) · Fan-out TTFS: fan-out time to first step (in-deployment start() → first of the parallel step bodies to complete) · Fan-out TTLS: fan-out time to last step (in-deployment start() → last of the parallel step bodies to complete, i.e. when the Promise.all resolves) · STSO: step-to-step overhead (gap between consecutive step bodies) · WO: workflow overhead (whole-run time outside step bodies, in-deployment anchored) · SL: stream latency (in-deployment write → read propagation, readAt - writtenAt) · SO: stream overhead (end-to-end write+consume time beyond the modelled generation window) Scenarios — step: one trivial no-op step, no stream; no hooks, so the run stays in turbo mode (in-process fast path) · stream: one streaming step; no hooks, so the run stays in turbo mode (in-process fast path) · hook + stream: registers a hook before one step, which exits turbo mode (dispatch path) · 1020 steps: 1020 trivial sequential steps; STSO is measured between consecutive steps in the given step ranges, and WO is the whole-run overhead outside step bodies · Promise.all(100 steps): 100 trivial no-op steps started together in a single Promise.all; Fan-out TTFS is the first of them to complete and Fan-out TTLS the last, both from the in-deployment clientStart, so their gap is the spread the runtime adds across the fan-out · stream latency: parallel reader/writer steps on a dedicated stream; SL is the in-deployment write->read propagation (readAt - writtenAt) · stream overhead (text): writer streams 300 variable-length text token deltas paced at 100/s for 3s (a haiku-size LLM's token throughput) while a parallel reader drains the whole stream; SO is the end-to-end write+consume time beyond the 3s generation window (overhead/backpressure) · stream overhead (structured): same workload as stream overhead (text), but each delta is an AI-SDK-style structured object ({ type: 'text-delta', id, text }) instead of a raw string, so the SO gap vs the text scenario is the added serialization cost 🔴 marks a percentile over its target (within target is left unmarked). Targets (p75/p90/p99, ms) — TTFS 200/300/600 · SL 50/60/125 · SO 250/500/1000 All metrics are measured from deployment-side timestamps only. Runs are triggered by an in-deployment route that stamps the anchor ( Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the |
VaguelySerious
added
the
event-log-race-repro
Sim WorldSimulated world deterministic testing for races. Traces 🟠 Mint-ordered log — 3 fail of 41 total
Full trace: 🟢 Append-only log — 0 fail of 41 total
Full trace: |
Event Log Race Repro
Run History
Config
|
1 participant
Description
Follow-up to #3558, which landed the poke budget as a hard stop. That bought the local lanes their green at a real cost to coverage, and this PR pays it back.
The hard stop was binding, and it silenced the back half of every run. On both local lanes every
step-stormrun spent the full 64-poke budget, so a ~160s run applied no out-of-band writes after its first ~48s. Lowering attempt concurrency does not help: atconcurrency=3runs finish in 87-96s and still spend the whole budget.The pump now runs
POKE_MAX(64) pokes at full cadence and then decays to× POKE_DECAY_FACTOR(8) rather than stopping. Loop gain stays below 1 — which is what stopped the runaway to ~270 pokes per run where nothing finished — while a slow run's later rounds keep receiving pressure.It works, and the evidence is a corruption. On the decay config, world-local produced a genuine
CORRUPTED_EVENT_LOG(wrun_01M00SW88YV76AXKXQFX4Y3V1X, 87 pokes over 200s). Three consecutive passes of the merged hard-stop config produced none. This is the failure the harness exists to catch, so the difference is not cosmetic.Which then required a run timeout that fits the local lanes. With pressure restored,
step-stormlands at 194-203s (world-local) and 168-175s (world-postgres) against the harness' 240000 default — 83% of its own timeout — while Vercel finishes the same storm in 85-100s. One slow runner at that margin turns a lane that reproduces into a lane full ofstuck, which is exactly the failure #3558 set out to stop. The local script raises it to 480000; it is the one scale knob the script sets, because it is the one whose meaning depends on every replay of every run sharing a Node process instead of getting its own Fluid invocation. An exported value or aworkflow_dispatchinput still wins.Also worth recording, since it reframes the coverage question: the lanes were never comparable on pressure. A Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (37-49 pokes per run) where localhost runs the full 750ms. The local lanes were applying roughly 3x the out-of-band write rate of the lane that found the production bug; the decayed rate is what brings them near it rather than below it.
How did you test your changes?
Lane dispatches on this branch's code, at the default scale:
CORRUPTED_EVENT_LOGstep-stormstragglers stay at 18-38 of 48 branches, so the step-count amplifier the corruption depends on is still firing — the lanes are not green by way of doing less.Three lane passes on the decay config, for the corruption rate: world-local 17 completed + 1
CORRUPTED_EVENT_LOGout of 18step-stormruns, world-postgres 18/18 completed, Vercel 18/18 completed. Worst-case duration is 208s against the raised 480000 timeout, so the margin that forced the timeout change is now 2.3x rather than 1.2x.A separate coverage gap this surfaced, not addressed here
hook-stormon the local lanes barely exercises its recovery path, and the arithmetic says it cannot: the driver resumes branchindexatindex * hookResumeStaggerMs(400ms), so against a 2500ms watchdog only index 7 of 8 straggles — one per round. Observed world-local stragglers are 0-1 per run against Vercel'''s 18-24, because a Vercel resume also pays ~1.5s of network latency that pushes most indices past the deadline. So the localhook-stormlane runs almost entirely on the settle path, and the step-count amplifier the scenario exists to drive is mostly idle there.That is independent of anything in this PR or #3558 — it is what
width * staggerbarely exceedingwatchdogMsmeans once resumes are free. Fixing it is a scale-tuning decision (a larger localHOOK_RESUME_STAGGER_MS, or a shorter localWATCHDOG_MS) and wants its own before/after straggler numbers rather than a guess bundled in here.The decay arithmetic, locally at
POKE_MAX=4/500ms/ decay 10: a 26.1s run sent 8 pokes, 4 at full cadence and 4 across the remaining 24s. Unbounded sends ~52; a hard stop sends 4.node --test .github/scripts/render-event-log-race-repro-results.test.js— 21 pass, including the config line now naming the budget and its decay (poke budget 64 then /8), since a bound that changes coverage should not be invisible next to the cadence it bounds.Not in this PR
The saturated lanes are not a throughput bug in either World, and I went looking: under saturation world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes, because its semaphore parks a message before the delivery fetch so queue waiting never consumes the transport timeout. world-postgres'
step execution already in flightlines are duplicate deliveries being absorbed by the SDK, not work being wasted. Neither local World has world-vercel's per-run replay serialization, but that is opt-in there too (WORKFLOW_SEQUENTIAL_REPLAYS, #2193).Two default-concurrency smells remain worth their own change, with the honest caveat that I could not demonstrate harm from either: world-local defaults to 1000 in-flight deliveries while the comment above the constant says the limit exists to avoid overwhelming the process (a 5-run pass at that default completed clean on a 12-core laptop), and world-postgres to 50 embedded workers per process.
PR Checklist - Required to merge
pnpm changesetwas run to create a changelog for this PRgit commit --signoff)@vercel/workflowin a comment once the PR is ready, and the above checklist is complete🤖 Generated with Claude Code