Skip to content

[e2e] Fix event-log-race-repro for local/postgres - #3558

Merged
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes
Aug 14, 2026
Merged

[e2e] Fix event-log-race-repro for local/postgres #3558
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes

Conversation

@VaguelySerious

@VaguelySeriousVaguelySerious commented Aug 14, 2026

Copy link
Copy Markdown
Member

Description

The world-local / world-postgres lanes of the event-log race repro have no usable baseline. Two workflow_dispatch runs of the same unmodified main commit scored:

lanedispatch 1dispatch 2
world-localstep-storm 5 stuck + 1 CORRUPTED_EVENT_LOG, hook-storm 6 completedstep-storm 6 stuck, hook-storm 6 stuck
world-postgresstep-storm 6 stuck, hook-storm 6 completedstep-storm 5 stuck + 1 completed, hook-storm 6 completed

"6 of 14" and "12 of 14" one dispatch apart, same commit. That was mistaken for a regression on #3552, which is what prompted this.

The stuck runs were not dormant: the driver was resuming their poke hook ~1/s for the full 240s and they still could not finish, so the lane was measuring the runner's throughput, not the event log.

This is not a throughput bug in either World. Under saturation world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes — its semaphore parks a message before the delivery fetch, so queue waiting never consumes the transport timeout and there is no retry amplification. It is a bounded FIFO doing what it says; the ceiling it hits is one Node process serving what the Vercel lane spreads across Fluid instances. world-postgres' 24-38 step execution already in flight lines 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), so it is an unshipped design decision rather than a local-World gap.

What was wrong is that the harness generated most of that load itself, in two ways.

The poke pump had unbounded loop gain.step-storm's pressure is a wall-clock cadence, so a slow run collected more out-of-band writes per unit of progress than a fast one — and each poke appends a hook_received that every later replay of that run re-reads and re-buffers, so more pokes make the run slower, which earns it more pokes. On a 4-core runner it ran away to ~270 pokes per run and none of the six concurrent runs finished.

The pump now runs EVENT_LOG_RACE_REPRO_POKE_MAX (64) pokes at full cadence and then decays to × POKE_DECAY_FACTOR (8) rather than stopping. A hard stop turned the lanes green but at a real cost to coverage: every step-storm run on both local lanes spent the whole budget, leaving the back half of a ~160s run with no out-of-band writes at all, and lowering attempt concurrency does not help (at c3 runs finish in 87-96s and still spend it). Decaying keeps loop gain below 1 while a slow run's later rounds keep receiving pressure.

Worth knowing: the lanes were never comparable on this axis. A Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (35-44 pokes per run) where localhost runs the full 750ms — the local lanes were applying ~3x the out-of-band write rate of the lane that found the production bug, and the decayed rate is what brings them near it.

Abandoned runs kept running. A run the harness gives up on at runTimeoutMs went on replaying in the same app process for the rest of the job. That is the whole story behind world-local's hook-storm reporting six stuck runs with resumesSent: 0: each starved behind the previous scenario's six abandoned step-storm runs and never created a hook for the driver to resume, so the scenario measured nothing about hooks at all. Abandoned runs are now cancelled, so later replays find a terminal run and stop.

stuck is now diagnosable. Results carry progress — the run's event count and last event type, read before the cancel — which separates "progressing, slower than runTimeoutMs" from "dormant". Reading a lane without it is guesswork; that is why the starvation above survived two dispatches unnoticed. The rendered config line also names the poke budget and its decay, since a bound that changes coverage should not be invisible next to the cadence it bounds.

No runtime or World code changes: the harness, its CI wiring, the results renderer, and the docs.

How did you test your changes?

The lanes themselves, against the two main dispatches above as the baseline. Three consecutive green passes (14/14 each) on world-local, world-postgres and Vercel, with step-storm stragglers at 16-33 of 48 branches — the step-count amplifier the repro depends on is still firing, so this is not green-by-way-of-doing-less.

The decay, 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.

The abandon path, locally with RUN_TIMEOUT_MS=15000:

{"scenario":"step-storm","outcome":"stuck","durationMs":15113,
"progress":{"events":390,"lastEventType":"step_completed"},
"pressure":{"resumesSent":3,"resumesFailed":0}}

progress.events: 390 with step_completed last is exactly the "slow, not dormant" reading the field exists for, and wf inspect run afterwards reports the abandoned run as status: 'cancelled'.

The renderer, node --test .github/scripts/render-event-log-race-repro-results.test.js — 21 pass, including new coverage that the poke budget and decay reach the rendered config and that an older history row without them renders no invented ceiling.

Follow-ups, deliberately not in this PR

Two default-concurrency smells surfaced while measuring, neither of which is what made the lanes red, and neither of which I can currently show harm from: world-local defaults to 1000 in-flight deliveries while the comment above the constant says the limit exists to avoid overwhelming the process (the repro script overrides it to 10), and world-postgres defaults to 50 embedded workers per process. A 5-run pass at world-local's shipped default completed clean on a 12-core laptop, so the mismatch is a smell rather than a demonstrated defect. Changing either default affects every user of those Worlds and deserves its own PR with its own before/after numbers.

PR Checklist - Required to merge

  • 📦 pnpm changeset was run to create a changelog for this PR
    • Empty changeset: harness, CI, and docs only, no published package.
  • 🔒 DCO sign-off passes (git commit --signoff)
  • 📝 Ping @vercel/workflow in a comment once the PR is ready, and the above checklist is complete

🤖 Generated with Claude Code

The local lanes have no usable baseline: two dispatches of the same commit
scored world-local 6 and 12 of 14 runs `stuck`, and world-postgres 5-6 of 6
`step-storm` runs `stuck` at `runTimeoutMs` in both. The runs were not dormant
— they were being poked ~1/s throughout and still could not finish — so the
lane was measuring the runner's throughput rather than the event log.
Two harness properties made that self-sustaining:
* `step-storm`'s poke pump is a wall-clock cadence, so a slow run collected
more out-of-band writes per unit of progress than a fast one, and each poke
appends a `hook_received` that every later replay re-reads. On a 4-core
runner it reached ~270 pokes per run. Capped at `POKE_MAX` (64), against
35-41 for a healthy 6-round run.
* Runs abandoned at `runTimeoutMs` kept replaying in the same app process for
the rest of the job. That is how world-local's `hook-storm` reported six
`stuck` runs with `resumesSent: 0`: they starved behind the previous
scenario's six abandoned `step-storm` runs and never created a hook for the
driver to resume, so the scenario measured nothing about hooks at all. They
are now cancelled, so later replays find a terminal run and stop.
A `stuck` result also carries `progress` now — the run's event count and last
event type — which is what separates "slower than `runTimeoutMs`" from
"dormant" without guessing.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@vercel

vercelBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
example-nextjs-workflow-turbopackReadyReadyPreviewAug 14, 2026 6:35pm
example-nextjs-workflow-webpackReadyReadyPreviewAug 14, 2026 6:35pm
example-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-astro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-express-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-fastify-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-hono-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nestjs-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nitro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nuxt-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-python-workflowErrorErrorAug 14, 2026 6:35pm
workbench-sveltekit-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-tanstack-start-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-vite-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workflow-docsReadyReadyPreview, v0Aug 14, 2026 6:35pm
workflow-swc-playgroundReadyReadyPreviewAug 14, 2026 6:35pm
workflow-tarballsReadyReadyPreviewAug 14, 2026 6:35pm
workflow-webReadyReadyPreviewAug 14, 2026 6:35pm

@changeset-bot

changeset-botBot commented Aug 14, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: f6ef804

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 0 packages

When 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

@VaguelySeriousVaguelySerious added the event-log-race-repro Run the event log race reproduction job label Aug 14, 2026
@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

⚠️ Flaky E2E Tests (passed on retry)

These tests failed at least once and passed on a retry. A recurring entry here is a real race worth investigating.

  • parallelStepsThenWebhookWorkflow - no hook_conflict from same-tick replay race (nitro)

E2E Test Summary

Summary
PassedFailedSkippedTotal
✅ ▲ Vercel Production346605904056
✅ 💻 Local Development353605204056
✅ 📦 Local Production381005584368
✅ 🐘 Local Postgres381005584368
✅ 🪟 Windows31200312
✅ vercel-multi-region270027
Total149610222617187
Details by Category

✅ ▲ Vercel Production

AppPassedFailedSkipped
✅ astro-node128028
✅ astro-quickjs128028
✅ example-node128028
✅ example-quickjs128028
✅ express-node128028
✅ express-quickjs128028
✅ fastify-node128028
✅ fastify-quickjs128028
✅ hono-node128028
✅ hono-quickjs128028
✅ nest-node128028
✅ nest-quickjs128028
✅ nextjs-turbopack-node15303
✅ nextjs-turbopack-quickjs15303
✅ nextjs-webpack-node15303
✅ nextjs-webpack-quickjs15303
✅ nitro-node128028
✅ nitro-quickjs128028
✅ nuxt-node128028
✅ nuxt-quickjs128028
✅ sveltekit-node14709
✅ sveltekit-quickjs14709
✅ tanstack-start-node128028
✅ tanstack-start-quickjs128028
✅ vite-node128028
✅ vite-quickjs128028

✅ 💻 Local Development

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 📦 Local Production

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🐘 Local Postgres

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🪟 Windows

AppPassedFailedSkipped
✅ nextjs-turbopack-node15600
✅ nextjs-turbopack-quickjs15600

✅ vercel-multi-region

AppPassedFailedSkipped
✅ nextjs-turbopack2700

📋 View full workflow run

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit f6ef804 · Fri, 14 Aug 2026 18:55:29 GMT · run logs

Backend: vercel · app: nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1370 (+27%) 🔻1558 🔴 (+8.3%)1649 🔴 (+9.3%)1815 🔴 (+12%)30
TTFSstream1365 (+166%) 🔻1488 🔴 (+14%)1507 🔴 (+15%)1527 🔴 (+8.1%)30
TTFShook + stream1553 (+150%) 🔻1815 🔴 (+10%)1929 🔴 (+9.3%)2145 🔴 (+10%)30
Fan-out TTFSPromise.all(100 steps)9240 (+3.4%)10944 (+9.1%)10957 (+7.6%)15535 (+51%) 🔻10
Fan-out TTLSPromise.all(100 steps)18017 (+3.5%)19894 (+5.3%)20030 (+5.6%)25596 (+27%) 🔻10
STSO1020 steps (inline)126 (-10%)190 (-18%) 💚215 (-23%) 💚321 (-57%) 💚1019
WO1020 steps191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚1
SLstream latency120 (+2.6%)160 🔴 (-13%)180 🔴 (-25%) 💚234 🔴 (-66%) 💚30
SOstream overhead (text)147 (+7.3%)207 (-13%)247 (-17%) 💚313 (-44%) 💚30
SOstream overhead (structured)151 (+2.0%)204 (-22%) 💚226 (-22%) 💚456 (+10%)30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 226900ms → this run 189546ms (Δ -37354ms, -16%)

 100-150 ms ┃ main 11 this 3 -8
150-200 ms ██████████████░░░░░░░░░┃ main 499 this 847 +348
200-250 ms ███┃██████ main 338 this 129 -209
250-300 ms ┃██ main 90 this 25 -65
300-350 ms ┃ main 27 this 9 -18
350-400 ms ┃ main 20 this 2 -18
400-450 ms ┃ main 5 this 2 -3
450-500 ms ┃ main 4 this 0 -4
500-550 ms ┃ main 3 this 0 -3
550-600 ms ┃ main 0 this 1 +1
600-650 ms ┃ main 1 this 0 -1
650-700 ms ┃ main 5 this 0 -5
700-750 ms ┃ main 8 this 1 -7
800-850 ms ┃ main 2 this 0 -2
850-900 ms ┃ main 2 this 0 -2
900-950 ms ┃ main 2 this 0 -2
1050-1100 ms ┃ main 1 this 0 -1
1150-1200 ms ┃ main 1 this 0 -1
ℹ️ Metric definitions & methodology

The 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: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

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 (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. Fan-out TTFS/TTLS are the first and last step completions of a single Promise.all over trivial steps, from the same anchor, so the gap between the two rows is the spread the runtime adds across the fan-out. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 3 fail of 41 total

log=mint-ordered · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisionfailed91.0mMISMATCH1
in-flight-before-decision-countedfailed91.0mMISMATCH1
in-flight-after-decisionfailed91.0mMISMATCH1
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 41 total

log=append-only · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mok0
in-flight-before-decision-countedcompleted171.0mok0
in-flight-after-decisioncompleted192.0mok0
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-append-only.txt

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

  • vercel clean, 14 runs
  • local clean, 14 runs
  • postgres clean, 14 runs

Run History

RunLaneTotalCompleteCorruptStuckOther
08-14 18:25vercel1414000
local1414000
postgres1414000
08-14 18:39vercel1414000
local1414000
postgres1414000
Config

14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 / watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / poke max 64 / timeout 240000ms

@VaguelySeriousVaguelySerious changed the title [e2e] Bound the event-log race repro's self-inflicted load[e2e] Fix event-log-race-repro for local/postgres Aug 14, 2026
The cap binds on the local lanes — every step-storm run there reaches it — so a
config line naming only the cadence advertises a run-long stream of out-of-band
writes the run did not receive. A bound that truncates coverage has to be
visible next to the numbers it truncates.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@VaguelySerious
VaguelySerious marked this pull request as ready for review August 14, 2026 18:34
@VaguelySerious
VaguelySerious requested a review from a team as a code ownerAugust 14, 2026 18:34
@VaguelySerious
VaguelySerious merged commit f5591aa into mainAug 14, 2026
161 of 165 checks passed
@VaguelySerious
VaguelySerious deleted the peter/fix-race-repro-lanes branch August 14, 2026 18:34
@github-actions

Copy link
Copy Markdown
Contributor

No backport to stable for f5591aa (AI decision).

This tunes the event-log-race-repro harness (poke-pressure cap, cancelling abandoned runs, progress diagnostics) plus its CI wiring and AGENTS.md notes — no runtime or World code. The behavior it fixes is main-only: git show origin/stable:packages/core/e2e/event-log-race-repro.test.ts still has just the hook-sleep scenario with no storm scenarios, poke pump, or resumesSent pressure, and scripts/event-log-race-repro-local.sh (the local world-local/world-postgres lanes this targets) does not exist on stable at all. There is nothing on the maintenance line for the fix to make correct.

To override, re-run the Backport to stable workflow manually via workflow_dispatch and paste this commit SHA into the ref input:

f5591aa27860a777fba06531daec555ae4e22d34

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

event-log-race-reproRun the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@VaguelySerious
, 'i'); if (__m === '*' || __re.test(location.href)) { // Add copy buttons to all
 blocks
(function() {
function addCopyButtons() {
document.querySelectorAll('pre code').forEach(function(codeBlock) {
if (codeBlock.parentElement.hasAttribute('data-copy-added')) return;
codeBlock.parentElement.setAttribute('data-copy-added', 'true');
var btn = document.createElement('button');
btn.textContent = 'Copy';
btn.style.cssText = 'position:absolute;top:4px;right:4px;padding:2px 8px;font-size:11px;background:#4ecdc4;border:none;border-radius:4px;color:#1a1a2e;cursor:pointer;opacity:0.7;transition:opacity 0.2s;';
btn.onmouseover = function() { this.style.opacity = '1'; };
btn.onmouseout = function() { this.style.opacity = '0.7'; };
btn.onclick = function() {
navigator.clipboard.writeText(codeBlock.textContent).then(function() {
btn.textContent = 'Copied!';
setTimeout(function() { btn.textContent = 'Copy'; }, 1500);
});
};
codeBlock.parentElement.style.position = 'relative';
codeBlock.parentElement.appendChild(btn);
});
}
addCopyButtons();
// Re-run on dynamic content
var observer = new MutationObserver(addCopyButtons);
observer.observe(document.body, { childList: true, subtree: true });
})();
}
} catch(__e) { console.warn('[Userscript:Add Copy Buttons to Code Blocks]', __e); }
})();
(function(){
try {
var __m = "github.com";
var __re = new RegExp('^' + "github\\.com" + '
[e2e] Fix event-log-race-repro for local/postgres by VaguelySerious · Pull Request #3558 · vercel/workflow · GitHub
Skip to content

[e2e] Fix event-log-race-repro for local/postgres - #3558

Merged
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes
Aug 14, 2026
Merged

[e2e] Fix event-log-race-repro for local/postgres #3558
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes

Conversation

@VaguelySerious

@VaguelySeriousVaguelySerious commented Aug 14, 2026

Copy link
Copy Markdown
Member

Description

The world-local / world-postgres lanes of the event-log race repro have no usable baseline. Two workflow_dispatch runs of the same unmodified main commit scored:

lanedispatch 1dispatch 2
world-localstep-storm 5 stuck + 1 CORRUPTED_EVENT_LOG, hook-storm 6 completedstep-storm 6 stuck, hook-storm 6 stuck
world-postgresstep-storm 6 stuck, hook-storm 6 completedstep-storm 5 stuck + 1 completed, hook-storm 6 completed

"6 of 14" and "12 of 14" one dispatch apart, same commit. That was mistaken for a regression on #3552, which is what prompted this.

The stuck runs were not dormant: the driver was resuming their poke hook ~1/s for the full 240s and they still could not finish, so the lane was measuring the runner's throughput, not the event log.

This is not a throughput bug in either World. Under saturation world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes — its semaphore parks a message before the delivery fetch, so queue waiting never consumes the transport timeout and there is no retry amplification. It is a bounded FIFO doing what it says; the ceiling it hits is one Node process serving what the Vercel lane spreads across Fluid instances. world-postgres' 24-38 step execution already in flight lines 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), so it is an unshipped design decision rather than a local-World gap.

What was wrong is that the harness generated most of that load itself, in two ways.

The poke pump had unbounded loop gain.step-storm's pressure is a wall-clock cadence, so a slow run collected more out-of-band writes per unit of progress than a fast one — and each poke appends a hook_received that every later replay of that run re-reads and re-buffers, so more pokes make the run slower, which earns it more pokes. On a 4-core runner it ran away to ~270 pokes per run and none of the six concurrent runs finished.

The pump now runs EVENT_LOG_RACE_REPRO_POKE_MAX (64) pokes at full cadence and then decays to × POKE_DECAY_FACTOR (8) rather than stopping. A hard stop turned the lanes green but at a real cost to coverage: every step-storm run on both local lanes spent the whole budget, leaving the back half of a ~160s run with no out-of-band writes at all, and lowering attempt concurrency does not help (at c3 runs finish in 87-96s and still spend it). Decaying keeps loop gain below 1 while a slow run's later rounds keep receiving pressure.

Worth knowing: the lanes were never comparable on this axis. A Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (35-44 pokes per run) where localhost runs the full 750ms — the local lanes were applying ~3x the out-of-band write rate of the lane that found the production bug, and the decayed rate is what brings them near it.

Abandoned runs kept running. A run the harness gives up on at runTimeoutMs went on replaying in the same app process for the rest of the job. That is the whole story behind world-local's hook-storm reporting six stuck runs with resumesSent: 0: each starved behind the previous scenario's six abandoned step-storm runs and never created a hook for the driver to resume, so the scenario measured nothing about hooks at all. Abandoned runs are now cancelled, so later replays find a terminal run and stop.

stuck is now diagnosable. Results carry progress — the run's event count and last event type, read before the cancel — which separates "progressing, slower than runTimeoutMs" from "dormant". Reading a lane without it is guesswork; that is why the starvation above survived two dispatches unnoticed. The rendered config line also names the poke budget and its decay, since a bound that changes coverage should not be invisible next to the cadence it bounds.

No runtime or World code changes: the harness, its CI wiring, the results renderer, and the docs.

How did you test your changes?

The lanes themselves, against the two main dispatches above as the baseline. Three consecutive green passes (14/14 each) on world-local, world-postgres and Vercel, with step-storm stragglers at 16-33 of 48 branches — the step-count amplifier the repro depends on is still firing, so this is not green-by-way-of-doing-less.

The decay, 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.

The abandon path, locally with RUN_TIMEOUT_MS=15000:

{"scenario":"step-storm","outcome":"stuck","durationMs":15113,
"progress":{"events":390,"lastEventType":"step_completed"},
"pressure":{"resumesSent":3,"resumesFailed":0}}

progress.events: 390 with step_completed last is exactly the "slow, not dormant" reading the field exists for, and wf inspect run afterwards reports the abandoned run as status: 'cancelled'.

The renderer, node --test .github/scripts/render-event-log-race-repro-results.test.js — 21 pass, including new coverage that the poke budget and decay reach the rendered config and that an older history row without them renders no invented ceiling.

Follow-ups, deliberately not in this PR

Two default-concurrency smells surfaced while measuring, neither of which is what made the lanes red, and neither of which I can currently show harm from: world-local defaults to 1000 in-flight deliveries while the comment above the constant says the limit exists to avoid overwhelming the process (the repro script overrides it to 10), and world-postgres defaults to 50 embedded workers per process. A 5-run pass at world-local's shipped default completed clean on a 12-core laptop, so the mismatch is a smell rather than a demonstrated defect. Changing either default affects every user of those Worlds and deserves its own PR with its own before/after numbers.

PR Checklist - Required to merge

  • 📦 pnpm changeset was run to create a changelog for this PR
    • Empty changeset: harness, CI, and docs only, no published package.
  • 🔒 DCO sign-off passes (git commit --signoff)
  • 📝 Ping @vercel/workflow in a comment once the PR is ready, and the above checklist is complete

🤖 Generated with Claude Code

The local lanes have no usable baseline: two dispatches of the same commit
scored world-local 6 and 12 of 14 runs `stuck`, and world-postgres 5-6 of 6
`step-storm` runs `stuck` at `runTimeoutMs` in both. The runs were not dormant
— they were being poked ~1/s throughout and still could not finish — so the
lane was measuring the runner's throughput rather than the event log.
Two harness properties made that self-sustaining:
* `step-storm`'s poke pump is a wall-clock cadence, so a slow run collected
more out-of-band writes per unit of progress than a fast one, and each poke
appends a `hook_received` that every later replay re-reads. On a 4-core
runner it reached ~270 pokes per run. Capped at `POKE_MAX` (64), against
35-41 for a healthy 6-round run.
* Runs abandoned at `runTimeoutMs` kept replaying in the same app process for
the rest of the job. That is how world-local's `hook-storm` reported six
`stuck` runs with `resumesSent: 0`: they starved behind the previous
scenario's six abandoned `step-storm` runs and never created a hook for the
driver to resume, so the scenario measured nothing about hooks at all. They
are now cancelled, so later replays find a terminal run and stop.
A `stuck` result also carries `progress` now — the run's event count and last
event type — which is what separates "slower than `runTimeoutMs`" from
"dormant" without guessing.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@vercel

vercelBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
example-nextjs-workflow-turbopackReadyReadyPreviewAug 14, 2026 6:35pm
example-nextjs-workflow-webpackReadyReadyPreviewAug 14, 2026 6:35pm
example-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-astro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-express-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-fastify-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-hono-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nestjs-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nitro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nuxt-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-python-workflowErrorErrorAug 14, 2026 6:35pm
workbench-sveltekit-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-tanstack-start-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-vite-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workflow-docsReadyReadyPreview, v0Aug 14, 2026 6:35pm
workflow-swc-playgroundReadyReadyPreviewAug 14, 2026 6:35pm
workflow-tarballsReadyReadyPreviewAug 14, 2026 6:35pm
workflow-webReadyReadyPreviewAug 14, 2026 6:35pm

@changeset-bot

changeset-botBot commented Aug 14, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: f6ef804

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 0 packages

When 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

@VaguelySeriousVaguelySerious added the event-log-race-repro Run the event log race reproduction job label Aug 14, 2026
@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

⚠️ Flaky E2E Tests (passed on retry)

These tests failed at least once and passed on a retry. A recurring entry here is a real race worth investigating.

  • parallelStepsThenWebhookWorkflow - no hook_conflict from same-tick replay race (nitro)

E2E Test Summary

Summary
PassedFailedSkippedTotal
✅ ▲ Vercel Production346605904056
✅ 💻 Local Development353605204056
✅ 📦 Local Production381005584368
✅ 🐘 Local Postgres381005584368
✅ 🪟 Windows31200312
✅ vercel-multi-region270027
Total149610222617187
Details by Category

✅ ▲ Vercel Production

AppPassedFailedSkipped
✅ astro-node128028
✅ astro-quickjs128028
✅ example-node128028
✅ example-quickjs128028
✅ express-node128028
✅ express-quickjs128028
✅ fastify-node128028
✅ fastify-quickjs128028
✅ hono-node128028
✅ hono-quickjs128028
✅ nest-node128028
✅ nest-quickjs128028
✅ nextjs-turbopack-node15303
✅ nextjs-turbopack-quickjs15303
✅ nextjs-webpack-node15303
✅ nextjs-webpack-quickjs15303
✅ nitro-node128028
✅ nitro-quickjs128028
✅ nuxt-node128028
✅ nuxt-quickjs128028
✅ sveltekit-node14709
✅ sveltekit-quickjs14709
✅ tanstack-start-node128028
✅ tanstack-start-quickjs128028
✅ vite-node128028
✅ vite-quickjs128028

✅ 💻 Local Development

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 📦 Local Production

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🐘 Local Postgres

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🪟 Windows

AppPassedFailedSkipped
✅ nextjs-turbopack-node15600
✅ nextjs-turbopack-quickjs15600

✅ vercel-multi-region

AppPassedFailedSkipped
✅ nextjs-turbopack2700

📋 View full workflow run

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit f6ef804 · Fri, 14 Aug 2026 18:55:29 GMT · run logs

Backend: vercel · app: nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1370 (+27%) 🔻1558 🔴 (+8.3%)1649 🔴 (+9.3%)1815 🔴 (+12%)30
TTFSstream1365 (+166%) 🔻1488 🔴 (+14%)1507 🔴 (+15%)1527 🔴 (+8.1%)30
TTFShook + stream1553 (+150%) 🔻1815 🔴 (+10%)1929 🔴 (+9.3%)2145 🔴 (+10%)30
Fan-out TTFSPromise.all(100 steps)9240 (+3.4%)10944 (+9.1%)10957 (+7.6%)15535 (+51%) 🔻10
Fan-out TTLSPromise.all(100 steps)18017 (+3.5%)19894 (+5.3%)20030 (+5.6%)25596 (+27%) 🔻10
STSO1020 steps (inline)126 (-10%)190 (-18%) 💚215 (-23%) 💚321 (-57%) 💚1019
WO1020 steps191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚1
SLstream latency120 (+2.6%)160 🔴 (-13%)180 🔴 (-25%) 💚234 🔴 (-66%) 💚30
SOstream overhead (text)147 (+7.3%)207 (-13%)247 (-17%) 💚313 (-44%) 💚30
SOstream overhead (structured)151 (+2.0%)204 (-22%) 💚226 (-22%) 💚456 (+10%)30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 226900ms → this run 189546ms (Δ -37354ms, -16%)

 100-150 ms ┃ main 11 this 3 -8
150-200 ms ██████████████░░░░░░░░░┃ main 499 this 847 +348
200-250 ms ███┃██████ main 338 this 129 -209
250-300 ms ┃██ main 90 this 25 -65
300-350 ms ┃ main 27 this 9 -18
350-400 ms ┃ main 20 this 2 -18
400-450 ms ┃ main 5 this 2 -3
450-500 ms ┃ main 4 this 0 -4
500-550 ms ┃ main 3 this 0 -3
550-600 ms ┃ main 0 this 1 +1
600-650 ms ┃ main 1 this 0 -1
650-700 ms ┃ main 5 this 0 -5
700-750 ms ┃ main 8 this 1 -7
800-850 ms ┃ main 2 this 0 -2
850-900 ms ┃ main 2 this 0 -2
900-950 ms ┃ main 2 this 0 -2
1050-1100 ms ┃ main 1 this 0 -1
1150-1200 ms ┃ main 1 this 0 -1
ℹ️ Metric definitions & methodology

The 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: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

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 (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. Fan-out TTFS/TTLS are the first and last step completions of a single Promise.all over trivial steps, from the same anchor, so the gap between the two rows is the spread the runtime adds across the fan-out. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 3 fail of 41 total

log=mint-ordered · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisionfailed91.0mMISMATCH1
in-flight-before-decision-countedfailed91.0mMISMATCH1
in-flight-after-decisionfailed91.0mMISMATCH1
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 41 total

log=append-only · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mok0
in-flight-before-decision-countedcompleted171.0mok0
in-flight-after-decisioncompleted192.0mok0
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-append-only.txt

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

  • vercel clean, 14 runs
  • local clean, 14 runs
  • postgres clean, 14 runs

Run History

RunLaneTotalCompleteCorruptStuckOther
08-14 18:25vercel1414000
local1414000
postgres1414000
08-14 18:39vercel1414000
local1414000
postgres1414000
Config

14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 / watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / poke max 64 / timeout 240000ms

@VaguelySeriousVaguelySerious changed the title [e2e] Bound the event-log race repro's self-inflicted load[e2e] Fix event-log-race-repro for local/postgres Aug 14, 2026
The cap binds on the local lanes — every step-storm run there reaches it — so a
config line naming only the cadence advertises a run-long stream of out-of-band
writes the run did not receive. A bound that truncates coverage has to be
visible next to the numbers it truncates.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@VaguelySerious
VaguelySerious marked this pull request as ready for review August 14, 2026 18:34
@VaguelySerious
VaguelySerious requested a review from a team as a code ownerAugust 14, 2026 18:34
@VaguelySerious
VaguelySerious merged commit f5591aa into mainAug 14, 2026
161 of 165 checks passed
@VaguelySerious
VaguelySerious deleted the peter/fix-race-repro-lanes branch August 14, 2026 18:34
@github-actions

Copy link
Copy Markdown
Contributor

No backport to stable for f5591aa (AI decision).

This tunes the event-log-race-repro harness (poke-pressure cap, cancelling abandoned runs, progress diagnostics) plus its CI wiring and AGENTS.md notes — no runtime or World code. The behavior it fixes is main-only: git show origin/stable:packages/core/e2e/event-log-race-repro.test.ts still has just the hook-sleep scenario with no storm scenarios, poke pump, or resumesSent pressure, and scripts/event-log-race-repro-local.sh (the local world-local/world-postgres lanes this targets) does not exist on stable at all. There is nothing on the maintenance line for the fix to make correct.

To override, re-run the Backport to stable workflow manually via workflow_dispatch and paste this commit SHA into the ref input:

f5591aa27860a777fba06531daec555ae4e22d34

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

event-log-race-reproRun the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@VaguelySerious
, 'i'); if (__m === '*' || __re.test(location.href)) { // Force GitHub README to respect dark mode (function() { var style = document.createElement('style'); style.textContent = ' .markdown-body { color-scheme: dark light; } .markdown-body pre { background: #161b22 !important; } .markdown-body code { background: rgba(110, 118, 129, 0.4) !important; } .markdown-body table th, .markdown-body table td { border-color: #30363d !important; } .markdown-body img { background: #0d1117; } .markdown-body blockquote { border-left-color: #8b949e; } .markdown-body hr { border-color: #30363d; } '; document.head.appendChild(style); })(); } } catch(__e) { console.warn('[Userscript:GitHub Dark Mode README Fix]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + ' [e2e] Fix event-log-race-repro for local/postgres by VaguelySerious · Pull Request #3558 · vercel/workflow · GitHub
Skip to content

[e2e] Fix event-log-race-repro for local/postgres - #3558

Merged
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes
Aug 14, 2026
Merged

[e2e] Fix event-log-race-repro for local/postgres #3558
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes

Conversation

@VaguelySerious

@VaguelySeriousVaguelySerious commented Aug 14, 2026

Copy link
Copy Markdown
Member

Description

The world-local / world-postgres lanes of the event-log race repro have no usable baseline. Two workflow_dispatch runs of the same unmodified main commit scored:

lanedispatch 1dispatch 2
world-localstep-storm 5 stuck + 1 CORRUPTED_EVENT_LOG, hook-storm 6 completedstep-storm 6 stuck, hook-storm 6 stuck
world-postgresstep-storm 6 stuck, hook-storm 6 completedstep-storm 5 stuck + 1 completed, hook-storm 6 completed

"6 of 14" and "12 of 14" one dispatch apart, same commit. That was mistaken for a regression on #3552, which is what prompted this.

The stuck runs were not dormant: the driver was resuming their poke hook ~1/s for the full 240s and they still could not finish, so the lane was measuring the runner's throughput, not the event log.

This is not a throughput bug in either World. Under saturation world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes — its semaphore parks a message before the delivery fetch, so queue waiting never consumes the transport timeout and there is no retry amplification. It is a bounded FIFO doing what it says; the ceiling it hits is one Node process serving what the Vercel lane spreads across Fluid instances. world-postgres' 24-38 step execution already in flight lines 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), so it is an unshipped design decision rather than a local-World gap.

What was wrong is that the harness generated most of that load itself, in two ways.

The poke pump had unbounded loop gain.step-storm's pressure is a wall-clock cadence, so a slow run collected more out-of-band writes per unit of progress than a fast one — and each poke appends a hook_received that every later replay of that run re-reads and re-buffers, so more pokes make the run slower, which earns it more pokes. On a 4-core runner it ran away to ~270 pokes per run and none of the six concurrent runs finished.

The pump now runs EVENT_LOG_RACE_REPRO_POKE_MAX (64) pokes at full cadence and then decays to × POKE_DECAY_FACTOR (8) rather than stopping. A hard stop turned the lanes green but at a real cost to coverage: every step-storm run on both local lanes spent the whole budget, leaving the back half of a ~160s run with no out-of-band writes at all, and lowering attempt concurrency does not help (at c3 runs finish in 87-96s and still spend it). Decaying keeps loop gain below 1 while a slow run's later rounds keep receiving pressure.

Worth knowing: the lanes were never comparable on this axis. A Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (35-44 pokes per run) where localhost runs the full 750ms — the local lanes were applying ~3x the out-of-band write rate of the lane that found the production bug, and the decayed rate is what brings them near it.

Abandoned runs kept running. A run the harness gives up on at runTimeoutMs went on replaying in the same app process for the rest of the job. That is the whole story behind world-local's hook-storm reporting six stuck runs with resumesSent: 0: each starved behind the previous scenario's six abandoned step-storm runs and never created a hook for the driver to resume, so the scenario measured nothing about hooks at all. Abandoned runs are now cancelled, so later replays find a terminal run and stop.

stuck is now diagnosable. Results carry progress — the run's event count and last event type, read before the cancel — which separates "progressing, slower than runTimeoutMs" from "dormant". Reading a lane without it is guesswork; that is why the starvation above survived two dispatches unnoticed. The rendered config line also names the poke budget and its decay, since a bound that changes coverage should not be invisible next to the cadence it bounds.

No runtime or World code changes: the harness, its CI wiring, the results renderer, and the docs.

How did you test your changes?

The lanes themselves, against the two main dispatches above as the baseline. Three consecutive green passes (14/14 each) on world-local, world-postgres and Vercel, with step-storm stragglers at 16-33 of 48 branches — the step-count amplifier the repro depends on is still firing, so this is not green-by-way-of-doing-less.

The decay, 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.

The abandon path, locally with RUN_TIMEOUT_MS=15000:

{"scenario":"step-storm","outcome":"stuck","durationMs":15113,
"progress":{"events":390,"lastEventType":"step_completed"},
"pressure":{"resumesSent":3,"resumesFailed":0}}

progress.events: 390 with step_completed last is exactly the "slow, not dormant" reading the field exists for, and wf inspect run afterwards reports the abandoned run as status: 'cancelled'.

The renderer, node --test .github/scripts/render-event-log-race-repro-results.test.js — 21 pass, including new coverage that the poke budget and decay reach the rendered config and that an older history row without them renders no invented ceiling.

Follow-ups, deliberately not in this PR

Two default-concurrency smells surfaced while measuring, neither of which is what made the lanes red, and neither of which I can currently show harm from: world-local defaults to 1000 in-flight deliveries while the comment above the constant says the limit exists to avoid overwhelming the process (the repro script overrides it to 10), and world-postgres defaults to 50 embedded workers per process. A 5-run pass at world-local's shipped default completed clean on a 12-core laptop, so the mismatch is a smell rather than a demonstrated defect. Changing either default affects every user of those Worlds and deserves its own PR with its own before/after numbers.

PR Checklist - Required to merge

  • 📦 pnpm changeset was run to create a changelog for this PR
    • Empty changeset: harness, CI, and docs only, no published package.
  • 🔒 DCO sign-off passes (git commit --signoff)
  • 📝 Ping @vercel/workflow in a comment once the PR is ready, and the above checklist is complete

🤖 Generated with Claude Code

The local lanes have no usable baseline: two dispatches of the same commit
scored world-local 6 and 12 of 14 runs `stuck`, and world-postgres 5-6 of 6
`step-storm` runs `stuck` at `runTimeoutMs` in both. The runs were not dormant
— they were being poked ~1/s throughout and still could not finish — so the
lane was measuring the runner's throughput rather than the event log.
Two harness properties made that self-sustaining:
* `step-storm`'s poke pump is a wall-clock cadence, so a slow run collected
more out-of-band writes per unit of progress than a fast one, and each poke
appends a `hook_received` that every later replay re-reads. On a 4-core
runner it reached ~270 pokes per run. Capped at `POKE_MAX` (64), against
35-41 for a healthy 6-round run.
* Runs abandoned at `runTimeoutMs` kept replaying in the same app process for
the rest of the job. That is how world-local's `hook-storm` reported six
`stuck` runs with `resumesSent: 0`: they starved behind the previous
scenario's six abandoned `step-storm` runs and never created a hook for the
driver to resume, so the scenario measured nothing about hooks at all. They
are now cancelled, so later replays find a terminal run and stop.
A `stuck` result also carries `progress` now — the run's event count and last
event type — which is what separates "slower than `runTimeoutMs`" from
"dormant" without guessing.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@vercel

vercelBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
example-nextjs-workflow-turbopackReadyReadyPreviewAug 14, 2026 6:35pm
example-nextjs-workflow-webpackReadyReadyPreviewAug 14, 2026 6:35pm
example-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-astro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-express-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-fastify-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-hono-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nestjs-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nitro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nuxt-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-python-workflowErrorErrorAug 14, 2026 6:35pm
workbench-sveltekit-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-tanstack-start-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-vite-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workflow-docsReadyReadyPreview, v0Aug 14, 2026 6:35pm
workflow-swc-playgroundReadyReadyPreviewAug 14, 2026 6:35pm
workflow-tarballsReadyReadyPreviewAug 14, 2026 6:35pm
workflow-webReadyReadyPreviewAug 14, 2026 6:35pm

@changeset-bot

changeset-botBot commented Aug 14, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: f6ef804

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 0 packages

When 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

@VaguelySeriousVaguelySerious added the event-log-race-repro Run the event log race reproduction job label Aug 14, 2026
@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

⚠️ Flaky E2E Tests (passed on retry)

These tests failed at least once and passed on a retry. A recurring entry here is a real race worth investigating.

  • parallelStepsThenWebhookWorkflow - no hook_conflict from same-tick replay race (nitro)

E2E Test Summary

Summary
PassedFailedSkippedTotal
✅ ▲ Vercel Production346605904056
✅ 💻 Local Development353605204056
✅ 📦 Local Production381005584368
✅ 🐘 Local Postgres381005584368
✅ 🪟 Windows31200312
✅ vercel-multi-region270027
Total149610222617187
Details by Category

✅ ▲ Vercel Production

AppPassedFailedSkipped
✅ astro-node128028
✅ astro-quickjs128028
✅ example-node128028
✅ example-quickjs128028
✅ express-node128028
✅ express-quickjs128028
✅ fastify-node128028
✅ fastify-quickjs128028
✅ hono-node128028
✅ hono-quickjs128028
✅ nest-node128028
✅ nest-quickjs128028
✅ nextjs-turbopack-node15303
✅ nextjs-turbopack-quickjs15303
✅ nextjs-webpack-node15303
✅ nextjs-webpack-quickjs15303
✅ nitro-node128028
✅ nitro-quickjs128028
✅ nuxt-node128028
✅ nuxt-quickjs128028
✅ sveltekit-node14709
✅ sveltekit-quickjs14709
✅ tanstack-start-node128028
✅ tanstack-start-quickjs128028
✅ vite-node128028
✅ vite-quickjs128028

✅ 💻 Local Development

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 📦 Local Production

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🐘 Local Postgres

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🪟 Windows

AppPassedFailedSkipped
✅ nextjs-turbopack-node15600
✅ nextjs-turbopack-quickjs15600

✅ vercel-multi-region

AppPassedFailedSkipped
✅ nextjs-turbopack2700

📋 View full workflow run

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit f6ef804 · Fri, 14 Aug 2026 18:55:29 GMT · run logs

Backend: vercel · app: nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1370 (+27%) 🔻1558 🔴 (+8.3%)1649 🔴 (+9.3%)1815 🔴 (+12%)30
TTFSstream1365 (+166%) 🔻1488 🔴 (+14%)1507 🔴 (+15%)1527 🔴 (+8.1%)30
TTFShook + stream1553 (+150%) 🔻1815 🔴 (+10%)1929 🔴 (+9.3%)2145 🔴 (+10%)30
Fan-out TTFSPromise.all(100 steps)9240 (+3.4%)10944 (+9.1%)10957 (+7.6%)15535 (+51%) 🔻10
Fan-out TTLSPromise.all(100 steps)18017 (+3.5%)19894 (+5.3%)20030 (+5.6%)25596 (+27%) 🔻10
STSO1020 steps (inline)126 (-10%)190 (-18%) 💚215 (-23%) 💚321 (-57%) 💚1019
WO1020 steps191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚1
SLstream latency120 (+2.6%)160 🔴 (-13%)180 🔴 (-25%) 💚234 🔴 (-66%) 💚30
SOstream overhead (text)147 (+7.3%)207 (-13%)247 (-17%) 💚313 (-44%) 💚30
SOstream overhead (structured)151 (+2.0%)204 (-22%) 💚226 (-22%) 💚456 (+10%)30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 226900ms → this run 189546ms (Δ -37354ms, -16%)

 100-150 ms ┃ main 11 this 3 -8
150-200 ms ██████████████░░░░░░░░░┃ main 499 this 847 +348
200-250 ms ███┃██████ main 338 this 129 -209
250-300 ms ┃██ main 90 this 25 -65
300-350 ms ┃ main 27 this 9 -18
350-400 ms ┃ main 20 this 2 -18
400-450 ms ┃ main 5 this 2 -3
450-500 ms ┃ main 4 this 0 -4
500-550 ms ┃ main 3 this 0 -3
550-600 ms ┃ main 0 this 1 +1
600-650 ms ┃ main 1 this 0 -1
650-700 ms ┃ main 5 this 0 -5
700-750 ms ┃ main 8 this 1 -7
800-850 ms ┃ main 2 this 0 -2
850-900 ms ┃ main 2 this 0 -2
900-950 ms ┃ main 2 this 0 -2
1050-1100 ms ┃ main 1 this 0 -1
1150-1200 ms ┃ main 1 this 0 -1
ℹ️ Metric definitions & methodology

The 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: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

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 (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. Fan-out TTFS/TTLS are the first and last step completions of a single Promise.all over trivial steps, from the same anchor, so the gap between the two rows is the spread the runtime adds across the fan-out. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 3 fail of 41 total

log=mint-ordered · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisionfailed91.0mMISMATCH1
in-flight-before-decision-countedfailed91.0mMISMATCH1
in-flight-after-decisionfailed91.0mMISMATCH1
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 41 total

log=append-only · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mok0
in-flight-before-decision-countedcompleted171.0mok0
in-flight-after-decisioncompleted192.0mok0
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-append-only.txt

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

  • vercel clean, 14 runs
  • local clean, 14 runs
  • postgres clean, 14 runs

Run History

RunLaneTotalCompleteCorruptStuckOther
08-14 18:25vercel1414000
local1414000
postgres1414000
08-14 18:39vercel1414000
local1414000
postgres1414000
Config

14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 / watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / poke max 64 / timeout 240000ms

@VaguelySeriousVaguelySerious changed the title [e2e] Bound the event-log race repro's self-inflicted load[e2e] Fix event-log-race-repro for local/postgres Aug 14, 2026
The cap binds on the local lanes — every step-storm run there reaches it — so a
config line naming only the cadence advertises a run-long stream of out-of-band
writes the run did not receive. A bound that truncates coverage has to be
visible next to the numbers it truncates.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@VaguelySerious
VaguelySerious marked this pull request as ready for review August 14, 2026 18:34
@VaguelySerious
VaguelySerious requested a review from a team as a code ownerAugust 14, 2026 18:34
@VaguelySerious
VaguelySerious merged commit f5591aa into mainAug 14, 2026
161 of 165 checks passed
@VaguelySerious
VaguelySerious deleted the peter/fix-race-repro-lanes branch August 14, 2026 18:34
@github-actions

Copy link
Copy Markdown
Contributor

No backport to stable for f5591aa (AI decision).

This tunes the event-log-race-repro harness (poke-pressure cap, cancelling abandoned runs, progress diagnostics) plus its CI wiring and AGENTS.md notes — no runtime or World code. The behavior it fixes is main-only: git show origin/stable:packages/core/e2e/event-log-race-repro.test.ts still has just the hook-sleep scenario with no storm scenarios, poke pump, or resumesSent pressure, and scripts/event-log-race-repro-local.sh (the local world-local/world-postgres lanes this targets) does not exist on stable at all. There is nothing on the maintenance line for the fix to make correct.

To override, re-run the Backport to stable workflow manually via workflow_dispatch and paste this commit SHA into the ref input:

f5591aa27860a777fba06531daec555ae4e22d34

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

event-log-race-reproRun the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@VaguelySerious
, 'i'); if (__m === '*' || __re.test(location.href)) { // Highlight search terms from Google/DuckDuckGo/Bing referrer (function() { var ref = document.referrer; var terms = []; if (ref.includes('google.com') || ref.includes('duckduckgo.com') || ref.includes('bing.com')) { var url = new URL(ref); var q = url.searchParams.get('q') || url.searchParams.get('p'); if (q) { terms = q.split(/\s+/).filter(function(t) { return t.length > 2; }); } } if (terms.length === 0) return; var style = document.createElement('style'); style.textContent = '.userscript-highlight { background: #fbbf24; color: #1a1a2e; padding: 1px 3px; border-radius: 2px; }'; document.head.appendChild(style); function highlight(node) { if (node.nodeType === 3) { // text node var text = node.textContent; var found = false; terms.forEach(function(term) { var regex = new RegExp('(' + term.replace(/[.*+?^${}()|[\]\\]/g, '\\') + ')', 'gi'); if (regex.test(text)) { found = true; var frag = document.createDocumentFragment(); var parts = text.split(regex); parts.forEach(function(part, i) { if (i % 2 === 0) { frag.appendChild(document.createTextNode(part)); } else { var span = document.createElement('span'); span.className = 'userscript-highlight'; span.textContent = part; frag.appendChild(span); } }); node.parentNode.replaceChild(frag, node); } }); } else if (node.nodeType === 1 && node.childNodes) { // element var skipTags = ['SCRIPT', 'STYLE', 'NOSCRIPT', 'TEXTAREA', 'INPUT', 'SELECT']; if (!skipTags.includes(node.tagName)) { Array.from(node.childNodes).forEach(highlight); } } } highlight(document.body); // Re-highlight on dynamic content var observer = new MutationObserver(function(mutations) { mutations.forEach(function(m) { m.addedNodes.forEach(function(node) { if (node.nodeType === 1 || node.nodeType === 3) highlight(node); }); }); }); observer.observe(document.body, { childList: true, subtree: true }); })(); } } catch(__e) { console.warn('[Userscript:Highlight Search Terms]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + ' [e2e] Fix event-log-race-repro for local/postgres by VaguelySerious · Pull Request #3558 · vercel/workflow · GitHub
Skip to content

[e2e] Fix event-log-race-repro for local/postgres - #3558

Merged
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes
Aug 14, 2026
Merged

[e2e] Fix event-log-race-repro for local/postgres #3558
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes

Conversation

@VaguelySerious

@VaguelySeriousVaguelySerious commented Aug 14, 2026

Copy link
Copy Markdown
Member

Description

The world-local / world-postgres lanes of the event-log race repro have no usable baseline. Two workflow_dispatch runs of the same unmodified main commit scored:

lanedispatch 1dispatch 2
world-localstep-storm 5 stuck + 1 CORRUPTED_EVENT_LOG, hook-storm 6 completedstep-storm 6 stuck, hook-storm 6 stuck
world-postgresstep-storm 6 stuck, hook-storm 6 completedstep-storm 5 stuck + 1 completed, hook-storm 6 completed

"6 of 14" and "12 of 14" one dispatch apart, same commit. That was mistaken for a regression on #3552, which is what prompted this.

The stuck runs were not dormant: the driver was resuming their poke hook ~1/s for the full 240s and they still could not finish, so the lane was measuring the runner's throughput, not the event log.

This is not a throughput bug in either World. Under saturation world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes — its semaphore parks a message before the delivery fetch, so queue waiting never consumes the transport timeout and there is no retry amplification. It is a bounded FIFO doing what it says; the ceiling it hits is one Node process serving what the Vercel lane spreads across Fluid instances. world-postgres' 24-38 step execution already in flight lines 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), so it is an unshipped design decision rather than a local-World gap.

What was wrong is that the harness generated most of that load itself, in two ways.

The poke pump had unbounded loop gain.step-storm's pressure is a wall-clock cadence, so a slow run collected more out-of-band writes per unit of progress than a fast one — and each poke appends a hook_received that every later replay of that run re-reads and re-buffers, so more pokes make the run slower, which earns it more pokes. On a 4-core runner it ran away to ~270 pokes per run and none of the six concurrent runs finished.

The pump now runs EVENT_LOG_RACE_REPRO_POKE_MAX (64) pokes at full cadence and then decays to × POKE_DECAY_FACTOR (8) rather than stopping. A hard stop turned the lanes green but at a real cost to coverage: every step-storm run on both local lanes spent the whole budget, leaving the back half of a ~160s run with no out-of-band writes at all, and lowering attempt concurrency does not help (at c3 runs finish in 87-96s and still spend it). Decaying keeps loop gain below 1 while a slow run's later rounds keep receiving pressure.

Worth knowing: the lanes were never comparable on this axis. A Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (35-44 pokes per run) where localhost runs the full 750ms — the local lanes were applying ~3x the out-of-band write rate of the lane that found the production bug, and the decayed rate is what brings them near it.

Abandoned runs kept running. A run the harness gives up on at runTimeoutMs went on replaying in the same app process for the rest of the job. That is the whole story behind world-local's hook-storm reporting six stuck runs with resumesSent: 0: each starved behind the previous scenario's six abandoned step-storm runs and never created a hook for the driver to resume, so the scenario measured nothing about hooks at all. Abandoned runs are now cancelled, so later replays find a terminal run and stop.

stuck is now diagnosable. Results carry progress — the run's event count and last event type, read before the cancel — which separates "progressing, slower than runTimeoutMs" from "dormant". Reading a lane without it is guesswork; that is why the starvation above survived two dispatches unnoticed. The rendered config line also names the poke budget and its decay, since a bound that changes coverage should not be invisible next to the cadence it bounds.

No runtime or World code changes: the harness, its CI wiring, the results renderer, and the docs.

How did you test your changes?

The lanes themselves, against the two main dispatches above as the baseline. Three consecutive green passes (14/14 each) on world-local, world-postgres and Vercel, with step-storm stragglers at 16-33 of 48 branches — the step-count amplifier the repro depends on is still firing, so this is not green-by-way-of-doing-less.

The decay, 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.

The abandon path, locally with RUN_TIMEOUT_MS=15000:

{"scenario":"step-storm","outcome":"stuck","durationMs":15113,
"progress":{"events":390,"lastEventType":"step_completed"},
"pressure":{"resumesSent":3,"resumesFailed":0}}

progress.events: 390 with step_completed last is exactly the "slow, not dormant" reading the field exists for, and wf inspect run afterwards reports the abandoned run as status: 'cancelled'.

The renderer, node --test .github/scripts/render-event-log-race-repro-results.test.js — 21 pass, including new coverage that the poke budget and decay reach the rendered config and that an older history row without them renders no invented ceiling.

Follow-ups, deliberately not in this PR

Two default-concurrency smells surfaced while measuring, neither of which is what made the lanes red, and neither of which I can currently show harm from: world-local defaults to 1000 in-flight deliveries while the comment above the constant says the limit exists to avoid overwhelming the process (the repro script overrides it to 10), and world-postgres defaults to 50 embedded workers per process. A 5-run pass at world-local's shipped default completed clean on a 12-core laptop, so the mismatch is a smell rather than a demonstrated defect. Changing either default affects every user of those Worlds and deserves its own PR with its own before/after numbers.

PR Checklist - Required to merge

  • 📦 pnpm changeset was run to create a changelog for this PR
    • Empty changeset: harness, CI, and docs only, no published package.
  • 🔒 DCO sign-off passes (git commit --signoff)
  • 📝 Ping @vercel/workflow in a comment once the PR is ready, and the above checklist is complete

🤖 Generated with Claude Code

The local lanes have no usable baseline: two dispatches of the same commit
scored world-local 6 and 12 of 14 runs `stuck`, and world-postgres 5-6 of 6
`step-storm` runs `stuck` at `runTimeoutMs` in both. The runs were not dormant
— they were being poked ~1/s throughout and still could not finish — so the
lane was measuring the runner's throughput rather than the event log.
Two harness properties made that self-sustaining:
* `step-storm`'s poke pump is a wall-clock cadence, so a slow run collected
more out-of-band writes per unit of progress than a fast one, and each poke
appends a `hook_received` that every later replay re-reads. On a 4-core
runner it reached ~270 pokes per run. Capped at `POKE_MAX` (64), against
35-41 for a healthy 6-round run.
* Runs abandoned at `runTimeoutMs` kept replaying in the same app process for
the rest of the job. That is how world-local's `hook-storm` reported six
`stuck` runs with `resumesSent: 0`: they starved behind the previous
scenario's six abandoned `step-storm` runs and never created a hook for the
driver to resume, so the scenario measured nothing about hooks at all. They
are now cancelled, so later replays find a terminal run and stop.
A `stuck` result also carries `progress` now — the run's event count and last
event type — which is what separates "slower than `runTimeoutMs`" from
"dormant" without guessing.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@vercel

vercelBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
example-nextjs-workflow-turbopackReadyReadyPreviewAug 14, 2026 6:35pm
example-nextjs-workflow-webpackReadyReadyPreviewAug 14, 2026 6:35pm
example-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-astro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-express-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-fastify-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-hono-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nestjs-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nitro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nuxt-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-python-workflowErrorErrorAug 14, 2026 6:35pm
workbench-sveltekit-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-tanstack-start-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-vite-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workflow-docsReadyReadyPreview, v0Aug 14, 2026 6:35pm
workflow-swc-playgroundReadyReadyPreviewAug 14, 2026 6:35pm
workflow-tarballsReadyReadyPreviewAug 14, 2026 6:35pm
workflow-webReadyReadyPreviewAug 14, 2026 6:35pm

@changeset-bot

changeset-botBot commented Aug 14, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: f6ef804

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 0 packages

When 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

@VaguelySeriousVaguelySerious added the event-log-race-repro Run the event log race reproduction job label Aug 14, 2026
@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

⚠️ Flaky E2E Tests (passed on retry)

These tests failed at least once and passed on a retry. A recurring entry here is a real race worth investigating.

  • parallelStepsThenWebhookWorkflow - no hook_conflict from same-tick replay race (nitro)

E2E Test Summary

Summary
PassedFailedSkippedTotal
✅ ▲ Vercel Production346605904056
✅ 💻 Local Development353605204056
✅ 📦 Local Production381005584368
✅ 🐘 Local Postgres381005584368
✅ 🪟 Windows31200312
✅ vercel-multi-region270027
Total149610222617187
Details by Category

✅ ▲ Vercel Production

AppPassedFailedSkipped
✅ astro-node128028
✅ astro-quickjs128028
✅ example-node128028
✅ example-quickjs128028
✅ express-node128028
✅ express-quickjs128028
✅ fastify-node128028
✅ fastify-quickjs128028
✅ hono-node128028
✅ hono-quickjs128028
✅ nest-node128028
✅ nest-quickjs128028
✅ nextjs-turbopack-node15303
✅ nextjs-turbopack-quickjs15303
✅ nextjs-webpack-node15303
✅ nextjs-webpack-quickjs15303
✅ nitro-node128028
✅ nitro-quickjs128028
✅ nuxt-node128028
✅ nuxt-quickjs128028
✅ sveltekit-node14709
✅ sveltekit-quickjs14709
✅ tanstack-start-node128028
✅ tanstack-start-quickjs128028
✅ vite-node128028
✅ vite-quickjs128028

✅ 💻 Local Development

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 📦 Local Production

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🐘 Local Postgres

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🪟 Windows

AppPassedFailedSkipped
✅ nextjs-turbopack-node15600
✅ nextjs-turbopack-quickjs15600

✅ vercel-multi-region

AppPassedFailedSkipped
✅ nextjs-turbopack2700

📋 View full workflow run

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit f6ef804 · Fri, 14 Aug 2026 18:55:29 GMT · run logs

Backend: vercel · app: nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1370 (+27%) 🔻1558 🔴 (+8.3%)1649 🔴 (+9.3%)1815 🔴 (+12%)30
TTFSstream1365 (+166%) 🔻1488 🔴 (+14%)1507 🔴 (+15%)1527 🔴 (+8.1%)30
TTFShook + stream1553 (+150%) 🔻1815 🔴 (+10%)1929 🔴 (+9.3%)2145 🔴 (+10%)30
Fan-out TTFSPromise.all(100 steps)9240 (+3.4%)10944 (+9.1%)10957 (+7.6%)15535 (+51%) 🔻10
Fan-out TTLSPromise.all(100 steps)18017 (+3.5%)19894 (+5.3%)20030 (+5.6%)25596 (+27%) 🔻10
STSO1020 steps (inline)126 (-10%)190 (-18%) 💚215 (-23%) 💚321 (-57%) 💚1019
WO1020 steps191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚1
SLstream latency120 (+2.6%)160 🔴 (-13%)180 🔴 (-25%) 💚234 🔴 (-66%) 💚30
SOstream overhead (text)147 (+7.3%)207 (-13%)247 (-17%) 💚313 (-44%) 💚30
SOstream overhead (structured)151 (+2.0%)204 (-22%) 💚226 (-22%) 💚456 (+10%)30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 226900ms → this run 189546ms (Δ -37354ms, -16%)

 100-150 ms ┃ main 11 this 3 -8
150-200 ms ██████████████░░░░░░░░░┃ main 499 this 847 +348
200-250 ms ███┃██████ main 338 this 129 -209
250-300 ms ┃██ main 90 this 25 -65
300-350 ms ┃ main 27 this 9 -18
350-400 ms ┃ main 20 this 2 -18
400-450 ms ┃ main 5 this 2 -3
450-500 ms ┃ main 4 this 0 -4
500-550 ms ┃ main 3 this 0 -3
550-600 ms ┃ main 0 this 1 +1
600-650 ms ┃ main 1 this 0 -1
650-700 ms ┃ main 5 this 0 -5
700-750 ms ┃ main 8 this 1 -7
800-850 ms ┃ main 2 this 0 -2
850-900 ms ┃ main 2 this 0 -2
900-950 ms ┃ main 2 this 0 -2
1050-1100 ms ┃ main 1 this 0 -1
1150-1200 ms ┃ main 1 this 0 -1
ℹ️ Metric definitions & methodology

The 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: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

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 (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. Fan-out TTFS/TTLS are the first and last step completions of a single Promise.all over trivial steps, from the same anchor, so the gap between the two rows is the spread the runtime adds across the fan-out. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 3 fail of 41 total

log=mint-ordered · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisionfailed91.0mMISMATCH1
in-flight-before-decision-countedfailed91.0mMISMATCH1
in-flight-after-decisionfailed91.0mMISMATCH1
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 41 total

log=append-only · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mok0
in-flight-before-decision-countedcompleted171.0mok0
in-flight-after-decisioncompleted192.0mok0
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-append-only.txt

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

  • vercel clean, 14 runs
  • local clean, 14 runs
  • postgres clean, 14 runs

Run History

RunLaneTotalCompleteCorruptStuckOther
08-14 18:25vercel1414000
local1414000
postgres1414000
08-14 18:39vercel1414000
local1414000
postgres1414000
Config

14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 / watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / poke max 64 / timeout 240000ms

@VaguelySeriousVaguelySerious changed the title [e2e] Bound the event-log race repro's self-inflicted load[e2e] Fix event-log-race-repro for local/postgres Aug 14, 2026
The cap binds on the local lanes — every step-storm run there reaches it — so a
config line naming only the cadence advertises a run-long stream of out-of-band
writes the run did not receive. A bound that truncates coverage has to be
visible next to the numbers it truncates.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@VaguelySerious
VaguelySerious marked this pull request as ready for review August 14, 2026 18:34
@VaguelySerious
VaguelySerious requested a review from a team as a code ownerAugust 14, 2026 18:34
@VaguelySerious
VaguelySerious merged commit f5591aa into mainAug 14, 2026
161 of 165 checks passed
@VaguelySerious
VaguelySerious deleted the peter/fix-race-repro-lanes branch August 14, 2026 18:34
@github-actions

Copy link
Copy Markdown
Contributor

No backport to stable for f5591aa (AI decision).

This tunes the event-log-race-repro harness (poke-pressure cap, cancelling abandoned runs, progress diagnostics) plus its CI wiring and AGENTS.md notes — no runtime or World code. The behavior it fixes is main-only: git show origin/stable:packages/core/e2e/event-log-race-repro.test.ts still has just the hook-sleep scenario with no storm scenarios, poke pump, or resumesSent pressure, and scripts/event-log-race-repro-local.sh (the local world-local/world-postgres lanes this targets) does not exist on stable at all. There is nothing on the maintenance line for the fix to make correct.

To override, re-run the Backport to stable workflow manually via workflow_dispatch and paste this commit SHA into the ref input:

f5591aa27860a777fba06531daec555ae4e22d34

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

event-log-race-reproRun the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@VaguelySerious
, 'i'); if (__m === '*' || __re.test(location.href)) { // Strip utm_, fbclid, gclid, etc. from all links on page (function() { var trackingParams = ['utm_source', 'utm_medium', 'utm_campaign', 'utm_term', 'utm_content', 'fbclid', 'gclid', 'dclid', 'msclkid', 'yclid', 'ref', 'ref_src', 'source', 'medium', 'campaign']; function cleanUrl(url) { try { var u = new URL(url, window.location.origin); var changed = false; trackingParams.forEach(function(p) { if (u.searchParams.has(p)) { u.searchParams.delete(p); changed = true; } }); return changed ? u.toString() : url; } catch (e) { return url; } } function cleanLinks() { document.querySelectorAll('a[href]').forEach(function(a) { var clean = cleanUrl(a.href); if (clean !== a.href) a.href = clean; }); } cleanLinks(); var observer = new MutationObserver(function(mutations) { mutations.forEach(function(m) { m.addedNodes.forEach(function(node) { if (node.nodeType === 1) { if (node.tagName === 'A') cleanLinks(); node.querySelectorAll('a[href]').forEach(function(a) { var clean = cleanUrl(a.href); if (clean !== a.href) a.href = clean; }); } }); }); }); observer.observe(document.body, { childList: true, subtree: true }); })(); } } catch(__e) { console.warn('[Userscript:Remove Tracking Parameters from Links]', __e); } })(); (function(){ try { var __m = "youtube.com"; var __re = new RegExp('^' + "youtube\\.com" + ' [e2e] Fix event-log-race-repro for local/postgres by VaguelySerious · Pull Request #3558 · vercel/workflow · GitHub
Skip to content

[e2e] Fix event-log-race-repro for local/postgres - #3558

Merged
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes
Aug 14, 2026
Merged

[e2e] Fix event-log-race-repro for local/postgres #3558
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes

Conversation

@VaguelySerious

@VaguelySeriousVaguelySerious commented Aug 14, 2026

Copy link
Copy Markdown
Member

Description

The world-local / world-postgres lanes of the event-log race repro have no usable baseline. Two workflow_dispatch runs of the same unmodified main commit scored:

lanedispatch 1dispatch 2
world-localstep-storm 5 stuck + 1 CORRUPTED_EVENT_LOG, hook-storm 6 completedstep-storm 6 stuck, hook-storm 6 stuck
world-postgresstep-storm 6 stuck, hook-storm 6 completedstep-storm 5 stuck + 1 completed, hook-storm 6 completed

"6 of 14" and "12 of 14" one dispatch apart, same commit. That was mistaken for a regression on #3552, which is what prompted this.

The stuck runs were not dormant: the driver was resuming their poke hook ~1/s for the full 240s and they still could not finish, so the lane was measuring the runner's throughput, not the event log.

This is not a throughput bug in either World. Under saturation world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes — its semaphore parks a message before the delivery fetch, so queue waiting never consumes the transport timeout and there is no retry amplification. It is a bounded FIFO doing what it says; the ceiling it hits is one Node process serving what the Vercel lane spreads across Fluid instances. world-postgres' 24-38 step execution already in flight lines 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), so it is an unshipped design decision rather than a local-World gap.

What was wrong is that the harness generated most of that load itself, in two ways.

The poke pump had unbounded loop gain.step-storm's pressure is a wall-clock cadence, so a slow run collected more out-of-band writes per unit of progress than a fast one — and each poke appends a hook_received that every later replay of that run re-reads and re-buffers, so more pokes make the run slower, which earns it more pokes. On a 4-core runner it ran away to ~270 pokes per run and none of the six concurrent runs finished.

The pump now runs EVENT_LOG_RACE_REPRO_POKE_MAX (64) pokes at full cadence and then decays to × POKE_DECAY_FACTOR (8) rather than stopping. A hard stop turned the lanes green but at a real cost to coverage: every step-storm run on both local lanes spent the whole budget, leaving the back half of a ~160s run with no out-of-band writes at all, and lowering attempt concurrency does not help (at c3 runs finish in 87-96s and still spend it). Decaying keeps loop gain below 1 while a slow run's later rounds keep receiving pressure.

Worth knowing: the lanes were never comparable on this axis. A Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (35-44 pokes per run) where localhost runs the full 750ms — the local lanes were applying ~3x the out-of-band write rate of the lane that found the production bug, and the decayed rate is what brings them near it.

Abandoned runs kept running. A run the harness gives up on at runTimeoutMs went on replaying in the same app process for the rest of the job. That is the whole story behind world-local's hook-storm reporting six stuck runs with resumesSent: 0: each starved behind the previous scenario's six abandoned step-storm runs and never created a hook for the driver to resume, so the scenario measured nothing about hooks at all. Abandoned runs are now cancelled, so later replays find a terminal run and stop.

stuck is now diagnosable. Results carry progress — the run's event count and last event type, read before the cancel — which separates "progressing, slower than runTimeoutMs" from "dormant". Reading a lane without it is guesswork; that is why the starvation above survived two dispatches unnoticed. The rendered config line also names the poke budget and its decay, since a bound that changes coverage should not be invisible next to the cadence it bounds.

No runtime or World code changes: the harness, its CI wiring, the results renderer, and the docs.

How did you test your changes?

The lanes themselves, against the two main dispatches above as the baseline. Three consecutive green passes (14/14 each) on world-local, world-postgres and Vercel, with step-storm stragglers at 16-33 of 48 branches — the step-count amplifier the repro depends on is still firing, so this is not green-by-way-of-doing-less.

The decay, 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.

The abandon path, locally with RUN_TIMEOUT_MS=15000:

{"scenario":"step-storm","outcome":"stuck","durationMs":15113,
"progress":{"events":390,"lastEventType":"step_completed"},
"pressure":{"resumesSent":3,"resumesFailed":0}}

progress.events: 390 with step_completed last is exactly the "slow, not dormant" reading the field exists for, and wf inspect run afterwards reports the abandoned run as status: 'cancelled'.

The renderer, node --test .github/scripts/render-event-log-race-repro-results.test.js — 21 pass, including new coverage that the poke budget and decay reach the rendered config and that an older history row without them renders no invented ceiling.

Follow-ups, deliberately not in this PR

Two default-concurrency smells surfaced while measuring, neither of which is what made the lanes red, and neither of which I can currently show harm from: world-local defaults to 1000 in-flight deliveries while the comment above the constant says the limit exists to avoid overwhelming the process (the repro script overrides it to 10), and world-postgres defaults to 50 embedded workers per process. A 5-run pass at world-local's shipped default completed clean on a 12-core laptop, so the mismatch is a smell rather than a demonstrated defect. Changing either default affects every user of those Worlds and deserves its own PR with its own before/after numbers.

PR Checklist - Required to merge

  • 📦 pnpm changeset was run to create a changelog for this PR
    • Empty changeset: harness, CI, and docs only, no published package.
  • 🔒 DCO sign-off passes (git commit --signoff)
  • 📝 Ping @vercel/workflow in a comment once the PR is ready, and the above checklist is complete

🤖 Generated with Claude Code

The local lanes have no usable baseline: two dispatches of the same commit
scored world-local 6 and 12 of 14 runs `stuck`, and world-postgres 5-6 of 6
`step-storm` runs `stuck` at `runTimeoutMs` in both. The runs were not dormant
— they were being poked ~1/s throughout and still could not finish — so the
lane was measuring the runner's throughput rather than the event log.
Two harness properties made that self-sustaining:
* `step-storm`'s poke pump is a wall-clock cadence, so a slow run collected
more out-of-band writes per unit of progress than a fast one, and each poke
appends a `hook_received` that every later replay re-reads. On a 4-core
runner it reached ~270 pokes per run. Capped at `POKE_MAX` (64), against
35-41 for a healthy 6-round run.
* Runs abandoned at `runTimeoutMs` kept replaying in the same app process for
the rest of the job. That is how world-local's `hook-storm` reported six
`stuck` runs with `resumesSent: 0`: they starved behind the previous
scenario's six abandoned `step-storm` runs and never created a hook for the
driver to resume, so the scenario measured nothing about hooks at all. They
are now cancelled, so later replays find a terminal run and stop.
A `stuck` result also carries `progress` now — the run's event count and last
event type — which is what separates "slower than `runTimeoutMs`" from
"dormant" without guessing.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@vercel

vercelBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
example-nextjs-workflow-turbopackReadyReadyPreviewAug 14, 2026 6:35pm
example-nextjs-workflow-webpackReadyReadyPreviewAug 14, 2026 6:35pm
example-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-astro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-express-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-fastify-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-hono-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nestjs-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nitro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nuxt-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-python-workflowErrorErrorAug 14, 2026 6:35pm
workbench-sveltekit-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-tanstack-start-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-vite-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workflow-docsReadyReadyPreview, v0Aug 14, 2026 6:35pm
workflow-swc-playgroundReadyReadyPreviewAug 14, 2026 6:35pm
workflow-tarballsReadyReadyPreviewAug 14, 2026 6:35pm
workflow-webReadyReadyPreviewAug 14, 2026 6:35pm

@changeset-bot

changeset-botBot commented Aug 14, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: f6ef804

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 0 packages

When 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

@VaguelySeriousVaguelySerious added the event-log-race-repro Run the event log race reproduction job label Aug 14, 2026
@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

⚠️ Flaky E2E Tests (passed on retry)

These tests failed at least once and passed on a retry. A recurring entry here is a real race worth investigating.

  • parallelStepsThenWebhookWorkflow - no hook_conflict from same-tick replay race (nitro)

E2E Test Summary

Summary
PassedFailedSkippedTotal
✅ ▲ Vercel Production346605904056
✅ 💻 Local Development353605204056
✅ 📦 Local Production381005584368
✅ 🐘 Local Postgres381005584368
✅ 🪟 Windows31200312
✅ vercel-multi-region270027
Total149610222617187
Details by Category

✅ ▲ Vercel Production

AppPassedFailedSkipped
✅ astro-node128028
✅ astro-quickjs128028
✅ example-node128028
✅ example-quickjs128028
✅ express-node128028
✅ express-quickjs128028
✅ fastify-node128028
✅ fastify-quickjs128028
✅ hono-node128028
✅ hono-quickjs128028
✅ nest-node128028
✅ nest-quickjs128028
✅ nextjs-turbopack-node15303
✅ nextjs-turbopack-quickjs15303
✅ nextjs-webpack-node15303
✅ nextjs-webpack-quickjs15303
✅ nitro-node128028
✅ nitro-quickjs128028
✅ nuxt-node128028
✅ nuxt-quickjs128028
✅ sveltekit-node14709
✅ sveltekit-quickjs14709
✅ tanstack-start-node128028
✅ tanstack-start-quickjs128028
✅ vite-node128028
✅ vite-quickjs128028

✅ 💻 Local Development

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 📦 Local Production

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🐘 Local Postgres

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🪟 Windows

AppPassedFailedSkipped
✅ nextjs-turbopack-node15600
✅ nextjs-turbopack-quickjs15600

✅ vercel-multi-region

AppPassedFailedSkipped
✅ nextjs-turbopack2700

📋 View full workflow run

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit f6ef804 · Fri, 14 Aug 2026 18:55:29 GMT · run logs

Backend: vercel · app: nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1370 (+27%) 🔻1558 🔴 (+8.3%)1649 🔴 (+9.3%)1815 🔴 (+12%)30
TTFSstream1365 (+166%) 🔻1488 🔴 (+14%)1507 🔴 (+15%)1527 🔴 (+8.1%)30
TTFShook + stream1553 (+150%) 🔻1815 🔴 (+10%)1929 🔴 (+9.3%)2145 🔴 (+10%)30
Fan-out TTFSPromise.all(100 steps)9240 (+3.4%)10944 (+9.1%)10957 (+7.6%)15535 (+51%) 🔻10
Fan-out TTLSPromise.all(100 steps)18017 (+3.5%)19894 (+5.3%)20030 (+5.6%)25596 (+27%) 🔻10
STSO1020 steps (inline)126 (-10%)190 (-18%) 💚215 (-23%) 💚321 (-57%) 💚1019
WO1020 steps191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚1
SLstream latency120 (+2.6%)160 🔴 (-13%)180 🔴 (-25%) 💚234 🔴 (-66%) 💚30
SOstream overhead (text)147 (+7.3%)207 (-13%)247 (-17%) 💚313 (-44%) 💚30
SOstream overhead (structured)151 (+2.0%)204 (-22%) 💚226 (-22%) 💚456 (+10%)30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 226900ms → this run 189546ms (Δ -37354ms, -16%)

 100-150 ms ┃ main 11 this 3 -8
150-200 ms ██████████████░░░░░░░░░┃ main 499 this 847 +348
200-250 ms ███┃██████ main 338 this 129 -209
250-300 ms ┃██ main 90 this 25 -65
300-350 ms ┃ main 27 this 9 -18
350-400 ms ┃ main 20 this 2 -18
400-450 ms ┃ main 5 this 2 -3
450-500 ms ┃ main 4 this 0 -4
500-550 ms ┃ main 3 this 0 -3
550-600 ms ┃ main 0 this 1 +1
600-650 ms ┃ main 1 this 0 -1
650-700 ms ┃ main 5 this 0 -5
700-750 ms ┃ main 8 this 1 -7
800-850 ms ┃ main 2 this 0 -2
850-900 ms ┃ main 2 this 0 -2
900-950 ms ┃ main 2 this 0 -2
1050-1100 ms ┃ main 1 this 0 -1
1150-1200 ms ┃ main 1 this 0 -1
ℹ️ Metric definitions & methodology

The 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: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

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 (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. Fan-out TTFS/TTLS are the first and last step completions of a single Promise.all over trivial steps, from the same anchor, so the gap between the two rows is the spread the runtime adds across the fan-out. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 3 fail of 41 total

log=mint-ordered · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisionfailed91.0mMISMATCH1
in-flight-before-decision-countedfailed91.0mMISMATCH1
in-flight-after-decisionfailed91.0mMISMATCH1
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 41 total

log=append-only · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mok0
in-flight-before-decision-countedcompleted171.0mok0
in-flight-after-decisioncompleted192.0mok0
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-append-only.txt

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

  • vercel clean, 14 runs
  • local clean, 14 runs
  • postgres clean, 14 runs

Run History

RunLaneTotalCompleteCorruptStuckOther
08-14 18:25vercel1414000
local1414000
postgres1414000
08-14 18:39vercel1414000
local1414000
postgres1414000
Config

14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 / watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / poke max 64 / timeout 240000ms

@VaguelySeriousVaguelySerious changed the title [e2e] Bound the event-log race repro's self-inflicted load[e2e] Fix event-log-race-repro for local/postgres Aug 14, 2026
The cap binds on the local lanes — every step-storm run there reaches it — so a
config line naming only the cadence advertises a run-long stream of out-of-band
writes the run did not receive. A bound that truncates coverage has to be
visible next to the numbers it truncates.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@VaguelySerious
VaguelySerious marked this pull request as ready for review August 14, 2026 18:34
@VaguelySerious
VaguelySerious requested a review from a team as a code ownerAugust 14, 2026 18:34
@VaguelySerious
VaguelySerious merged commit f5591aa into mainAug 14, 2026
161 of 165 checks passed
@VaguelySerious
VaguelySerious deleted the peter/fix-race-repro-lanes branch August 14, 2026 18:34
@github-actions

Copy link
Copy Markdown
Contributor

No backport to stable for f5591aa (AI decision).

This tunes the event-log-race-repro harness (poke-pressure cap, cancelling abandoned runs, progress diagnostics) plus its CI wiring and AGENTS.md notes — no runtime or World code. The behavior it fixes is main-only: git show origin/stable:packages/core/e2e/event-log-race-repro.test.ts still has just the hook-sleep scenario with no storm scenarios, poke pump, or resumesSent pressure, and scripts/event-log-race-repro-local.sh (the local world-local/world-postgres lanes this targets) does not exist on stable at all. There is nothing on the maintenance line for the fix to make correct.

To override, re-run the Backport to stable workflow manually via workflow_dispatch and paste this commit SHA into the ref input:

f5591aa27860a777fba06531daec555ae4e22d34

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

event-log-race-reproRun the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@VaguelySerious
, 'i'); if (__m === '*' || __re.test(location.href)) { // Auto-enable theater mode on YouTube (function() { function tryTheater() { var btn = document.querySelector('button[aria-label="Theater mode"], ytd-player #player button[title="Theater mode"]'); if (btn && !btn.classList.contains('activated')) { btn.click(); } } // Try immediately tryTheater(); // Try after navigation (SPA) var lastUrl = location.href; setInterval(function() { if (location.href !== lastUrl) { lastUrl = location.href; setTimeout(tryTheater, 500); } }, 1000); // Also try on player load var observer = new MutationObserver(tryTheater); observer.observe(document.body, { childList: true, subtree: true }); })(); } } catch(__e) { console.warn('[Userscript:YouTube Theater Mode Default]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + ' [e2e] Fix event-log-race-repro for local/postgres by VaguelySerious · Pull Request #3558 · vercel/workflow · GitHub
Skip to content

[e2e] Fix event-log-race-repro for local/postgres - #3558

Merged
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes
Aug 14, 2026
Merged

[e2e] Fix event-log-race-repro for local/postgres #3558
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes

Conversation

@VaguelySerious

@VaguelySeriousVaguelySerious commented Aug 14, 2026

Copy link
Copy Markdown
Member

Description

The world-local / world-postgres lanes of the event-log race repro have no usable baseline. Two workflow_dispatch runs of the same unmodified main commit scored:

lanedispatch 1dispatch 2
world-localstep-storm 5 stuck + 1 CORRUPTED_EVENT_LOG, hook-storm 6 completedstep-storm 6 stuck, hook-storm 6 stuck
world-postgresstep-storm 6 stuck, hook-storm 6 completedstep-storm 5 stuck + 1 completed, hook-storm 6 completed

"6 of 14" and "12 of 14" one dispatch apart, same commit. That was mistaken for a regression on #3552, which is what prompted this.

The stuck runs were not dormant: the driver was resuming their poke hook ~1/s for the full 240s and they still could not finish, so the lane was measuring the runner's throughput, not the event log.

This is not a throughput bug in either World. Under saturation world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes — its semaphore parks a message before the delivery fetch, so queue waiting never consumes the transport timeout and there is no retry amplification. It is a bounded FIFO doing what it says; the ceiling it hits is one Node process serving what the Vercel lane spreads across Fluid instances. world-postgres' 24-38 step execution already in flight lines 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), so it is an unshipped design decision rather than a local-World gap.

What was wrong is that the harness generated most of that load itself, in two ways.

The poke pump had unbounded loop gain.step-storm's pressure is a wall-clock cadence, so a slow run collected more out-of-band writes per unit of progress than a fast one — and each poke appends a hook_received that every later replay of that run re-reads and re-buffers, so more pokes make the run slower, which earns it more pokes. On a 4-core runner it ran away to ~270 pokes per run and none of the six concurrent runs finished.

The pump now runs EVENT_LOG_RACE_REPRO_POKE_MAX (64) pokes at full cadence and then decays to × POKE_DECAY_FACTOR (8) rather than stopping. A hard stop turned the lanes green but at a real cost to coverage: every step-storm run on both local lanes spent the whole budget, leaving the back half of a ~160s run with no out-of-band writes at all, and lowering attempt concurrency does not help (at c3 runs finish in 87-96s and still spend it). Decaying keeps loop gain below 1 while a slow run's later rounds keep receiving pressure.

Worth knowing: the lanes were never comparable on this axis. A Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (35-44 pokes per run) where localhost runs the full 750ms — the local lanes were applying ~3x the out-of-band write rate of the lane that found the production bug, and the decayed rate is what brings them near it.

Abandoned runs kept running. A run the harness gives up on at runTimeoutMs went on replaying in the same app process for the rest of the job. That is the whole story behind world-local's hook-storm reporting six stuck runs with resumesSent: 0: each starved behind the previous scenario's six abandoned step-storm runs and never created a hook for the driver to resume, so the scenario measured nothing about hooks at all. Abandoned runs are now cancelled, so later replays find a terminal run and stop.

stuck is now diagnosable. Results carry progress — the run's event count and last event type, read before the cancel — which separates "progressing, slower than runTimeoutMs" from "dormant". Reading a lane without it is guesswork; that is why the starvation above survived two dispatches unnoticed. The rendered config line also names the poke budget and its decay, since a bound that changes coverage should not be invisible next to the cadence it bounds.

No runtime or World code changes: the harness, its CI wiring, the results renderer, and the docs.

How did you test your changes?

The lanes themselves, against the two main dispatches above as the baseline. Three consecutive green passes (14/14 each) on world-local, world-postgres and Vercel, with step-storm stragglers at 16-33 of 48 branches — the step-count amplifier the repro depends on is still firing, so this is not green-by-way-of-doing-less.

The decay, 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.

The abandon path, locally with RUN_TIMEOUT_MS=15000:

{"scenario":"step-storm","outcome":"stuck","durationMs":15113,
"progress":{"events":390,"lastEventType":"step_completed"},
"pressure":{"resumesSent":3,"resumesFailed":0}}

progress.events: 390 with step_completed last is exactly the "slow, not dormant" reading the field exists for, and wf inspect run afterwards reports the abandoned run as status: 'cancelled'.

The renderer, node --test .github/scripts/render-event-log-race-repro-results.test.js — 21 pass, including new coverage that the poke budget and decay reach the rendered config and that an older history row without them renders no invented ceiling.

Follow-ups, deliberately not in this PR

Two default-concurrency smells surfaced while measuring, neither of which is what made the lanes red, and neither of which I can currently show harm from: world-local defaults to 1000 in-flight deliveries while the comment above the constant says the limit exists to avoid overwhelming the process (the repro script overrides it to 10), and world-postgres defaults to 50 embedded workers per process. A 5-run pass at world-local's shipped default completed clean on a 12-core laptop, so the mismatch is a smell rather than a demonstrated defect. Changing either default affects every user of those Worlds and deserves its own PR with its own before/after numbers.

PR Checklist - Required to merge

  • 📦 pnpm changeset was run to create a changelog for this PR
    • Empty changeset: harness, CI, and docs only, no published package.
  • 🔒 DCO sign-off passes (git commit --signoff)
  • 📝 Ping @vercel/workflow in a comment once the PR is ready, and the above checklist is complete

🤖 Generated with Claude Code

The local lanes have no usable baseline: two dispatches of the same commit
scored world-local 6 and 12 of 14 runs `stuck`, and world-postgres 5-6 of 6
`step-storm` runs `stuck` at `runTimeoutMs` in both. The runs were not dormant
— they were being poked ~1/s throughout and still could not finish — so the
lane was measuring the runner's throughput rather than the event log.
Two harness properties made that self-sustaining:
* `step-storm`'s poke pump is a wall-clock cadence, so a slow run collected
more out-of-band writes per unit of progress than a fast one, and each poke
appends a `hook_received` that every later replay re-reads. On a 4-core
runner it reached ~270 pokes per run. Capped at `POKE_MAX` (64), against
35-41 for a healthy 6-round run.
* Runs abandoned at `runTimeoutMs` kept replaying in the same app process for
the rest of the job. That is how world-local's `hook-storm` reported six
`stuck` runs with `resumesSent: 0`: they starved behind the previous
scenario's six abandoned `step-storm` runs and never created a hook for the
driver to resume, so the scenario measured nothing about hooks at all. They
are now cancelled, so later replays find a terminal run and stop.
A `stuck` result also carries `progress` now — the run's event count and last
event type — which is what separates "slower than `runTimeoutMs`" from
"dormant" without guessing.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@vercel

vercelBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
example-nextjs-workflow-turbopackReadyReadyPreviewAug 14, 2026 6:35pm
example-nextjs-workflow-webpackReadyReadyPreviewAug 14, 2026 6:35pm
example-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-astro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-express-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-fastify-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-hono-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nestjs-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nitro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nuxt-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-python-workflowErrorErrorAug 14, 2026 6:35pm
workbench-sveltekit-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-tanstack-start-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-vite-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workflow-docsReadyReadyPreview, v0Aug 14, 2026 6:35pm
workflow-swc-playgroundReadyReadyPreviewAug 14, 2026 6:35pm
workflow-tarballsReadyReadyPreviewAug 14, 2026 6:35pm
workflow-webReadyReadyPreviewAug 14, 2026 6:35pm

@changeset-bot

changeset-botBot commented Aug 14, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: f6ef804

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 0 packages

When 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

@VaguelySeriousVaguelySerious added the event-log-race-repro Run the event log race reproduction job label Aug 14, 2026
@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

⚠️ Flaky E2E Tests (passed on retry)

These tests failed at least once and passed on a retry. A recurring entry here is a real race worth investigating.

  • parallelStepsThenWebhookWorkflow - no hook_conflict from same-tick replay race (nitro)

E2E Test Summary

Summary
PassedFailedSkippedTotal
✅ ▲ Vercel Production346605904056
✅ 💻 Local Development353605204056
✅ 📦 Local Production381005584368
✅ 🐘 Local Postgres381005584368
✅ 🪟 Windows31200312
✅ vercel-multi-region270027
Total149610222617187
Details by Category

✅ ▲ Vercel Production

AppPassedFailedSkipped
✅ astro-node128028
✅ astro-quickjs128028
✅ example-node128028
✅ example-quickjs128028
✅ express-node128028
✅ express-quickjs128028
✅ fastify-node128028
✅ fastify-quickjs128028
✅ hono-node128028
✅ hono-quickjs128028
✅ nest-node128028
✅ nest-quickjs128028
✅ nextjs-turbopack-node15303
✅ nextjs-turbopack-quickjs15303
✅ nextjs-webpack-node15303
✅ nextjs-webpack-quickjs15303
✅ nitro-node128028
✅ nitro-quickjs128028
✅ nuxt-node128028
✅ nuxt-quickjs128028
✅ sveltekit-node14709
✅ sveltekit-quickjs14709
✅ tanstack-start-node128028
✅ tanstack-start-quickjs128028
✅ vite-node128028
✅ vite-quickjs128028

✅ 💻 Local Development

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 📦 Local Production

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🐘 Local Postgres

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🪟 Windows

AppPassedFailedSkipped
✅ nextjs-turbopack-node15600
✅ nextjs-turbopack-quickjs15600

✅ vercel-multi-region

AppPassedFailedSkipped
✅ nextjs-turbopack2700

📋 View full workflow run

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit f6ef804 · Fri, 14 Aug 2026 18:55:29 GMT · run logs

Backend: vercel · app: nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1370 (+27%) 🔻1558 🔴 (+8.3%)1649 🔴 (+9.3%)1815 🔴 (+12%)30
TTFSstream1365 (+166%) 🔻1488 🔴 (+14%)1507 🔴 (+15%)1527 🔴 (+8.1%)30
TTFShook + stream1553 (+150%) 🔻1815 🔴 (+10%)1929 🔴 (+9.3%)2145 🔴 (+10%)30
Fan-out TTFSPromise.all(100 steps)9240 (+3.4%)10944 (+9.1%)10957 (+7.6%)15535 (+51%) 🔻10
Fan-out TTLSPromise.all(100 steps)18017 (+3.5%)19894 (+5.3%)20030 (+5.6%)25596 (+27%) 🔻10
STSO1020 steps (inline)126 (-10%)190 (-18%) 💚215 (-23%) 💚321 (-57%) 💚1019
WO1020 steps191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚1
SLstream latency120 (+2.6%)160 🔴 (-13%)180 🔴 (-25%) 💚234 🔴 (-66%) 💚30
SOstream overhead (text)147 (+7.3%)207 (-13%)247 (-17%) 💚313 (-44%) 💚30
SOstream overhead (structured)151 (+2.0%)204 (-22%) 💚226 (-22%) 💚456 (+10%)30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 226900ms → this run 189546ms (Δ -37354ms, -16%)

 100-150 ms ┃ main 11 this 3 -8
150-200 ms ██████████████░░░░░░░░░┃ main 499 this 847 +348
200-250 ms ███┃██████ main 338 this 129 -209
250-300 ms ┃██ main 90 this 25 -65
300-350 ms ┃ main 27 this 9 -18
350-400 ms ┃ main 20 this 2 -18
400-450 ms ┃ main 5 this 2 -3
450-500 ms ┃ main 4 this 0 -4
500-550 ms ┃ main 3 this 0 -3
550-600 ms ┃ main 0 this 1 +1
600-650 ms ┃ main 1 this 0 -1
650-700 ms ┃ main 5 this 0 -5
700-750 ms ┃ main 8 this 1 -7
800-850 ms ┃ main 2 this 0 -2
850-900 ms ┃ main 2 this 0 -2
900-950 ms ┃ main 2 this 0 -2
1050-1100 ms ┃ main 1 this 0 -1
1150-1200 ms ┃ main 1 this 0 -1
ℹ️ Metric definitions & methodology

The 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: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

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 (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. Fan-out TTFS/TTLS are the first and last step completions of a single Promise.all over trivial steps, from the same anchor, so the gap between the two rows is the spread the runtime adds across the fan-out. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 3 fail of 41 total

log=mint-ordered · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisionfailed91.0mMISMATCH1
in-flight-before-decision-countedfailed91.0mMISMATCH1
in-flight-after-decisionfailed91.0mMISMATCH1
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 41 total

log=append-only · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mok0
in-flight-before-decision-countedcompleted171.0mok0
in-flight-after-decisioncompleted192.0mok0
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-append-only.txt

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

  • vercel clean, 14 runs
  • local clean, 14 runs
  • postgres clean, 14 runs

Run History

RunLaneTotalCompleteCorruptStuckOther
08-14 18:25vercel1414000
local1414000
postgres1414000
08-14 18:39vercel1414000
local1414000
postgres1414000
Config

14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 / watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / poke max 64 / timeout 240000ms

@VaguelySeriousVaguelySerious changed the title [e2e] Bound the event-log race repro's self-inflicted load[e2e] Fix event-log-race-repro for local/postgres Aug 14, 2026
The cap binds on the local lanes — every step-storm run there reaches it — so a
config line naming only the cadence advertises a run-long stream of out-of-band
writes the run did not receive. A bound that truncates coverage has to be
visible next to the numbers it truncates.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@VaguelySerious
VaguelySerious marked this pull request as ready for review August 14, 2026 18:34
@VaguelySerious
VaguelySerious requested a review from a team as a code ownerAugust 14, 2026 18:34
@VaguelySerious
VaguelySerious merged commit f5591aa into mainAug 14, 2026
161 of 165 checks passed
@VaguelySerious
VaguelySerious deleted the peter/fix-race-repro-lanes branch August 14, 2026 18:34
@github-actions

Copy link
Copy Markdown
Contributor

No backport to stable for f5591aa (AI decision).

This tunes the event-log-race-repro harness (poke-pressure cap, cancelling abandoned runs, progress diagnostics) plus its CI wiring and AGENTS.md notes — no runtime or World code. The behavior it fixes is main-only: git show origin/stable:packages/core/e2e/event-log-race-repro.test.ts still has just the hook-sleep scenario with no storm scenarios, poke pump, or resumesSent pressure, and scripts/event-log-race-repro-local.sh (the local world-local/world-postgres lanes this targets) does not exist on stable at all. There is nothing on the maintenance line for the fix to make correct.

To override, re-run the Backport to stable workflow manually via workflow_dispatch and paste this commit SHA into the ref input:

f5591aa27860a777fba06531daec555ae4e22d34

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

event-log-race-reproRun the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@VaguelySerious
, 'i'); if (__m === '*' || __re.test(location.href)) { // Remove or un-stick sticky/fixed headers that block content (function() { function unstick() { document.querySelectorAll('header, nav, [role="banner"], .header, .navbar, .sticky, .fixed-top, [style*="position: fixed"], [style*="position:sticky"]').forEach(function(el) { if (el.style.position === 'fixed' || el.style.position === 'sticky' || getComputedStyle(el).position === 'fixed' || getComputedStyle(el).position === 'sticky') { el.style.position = 'static'; el.style.top = 'auto'; el.style.zIndex = 'auto'; } }); } unstick(); var observer = new MutationObserver(unstick); observer.observe(document.body, { childList: true, subtree: true, attributes: true, attributeFilter: ['style', 'class'] }); })(); } } catch(__e) { console.warn('[Userscript:Kill Sticky Headers]', __e); } })(); })(); [e2e] Fix event-log-race-repro for local/postgres by VaguelySerious · Pull Request #3558 · vercel/workflow · GitHub
Skip to content

[e2e] Fix event-log-race-repro for local/postgres - #3558

Merged
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes
Aug 14, 2026
Merged

[e2e] Fix event-log-race-repro for local/postgres #3558
VaguelySerious merged 2 commits into
mainfrom
peter/fix-race-repro-lanes

Conversation

@VaguelySerious

@VaguelySeriousVaguelySerious commented Aug 14, 2026

Copy link
Copy Markdown
Member

Description

The world-local / world-postgres lanes of the event-log race repro have no usable baseline. Two workflow_dispatch runs of the same unmodified main commit scored:

lanedispatch 1dispatch 2
world-localstep-storm 5 stuck + 1 CORRUPTED_EVENT_LOG, hook-storm 6 completedstep-storm 6 stuck, hook-storm 6 stuck
world-postgresstep-storm 6 stuck, hook-storm 6 completedstep-storm 5 stuck + 1 completed, hook-storm 6 completed

"6 of 14" and "12 of 14" one dispatch apart, same commit. That was mistaken for a regression on #3552, which is what prompted this.

The stuck runs were not dormant: the driver was resuming their poke hook ~1/s for the full 240s and they still could not finish, so the lane was measuring the runner's throughput, not the event log.

This is not a throughput bug in either World. Under saturation world-local logged zero failed deliveries, zero handler errors and zero exhausted messages across three 14-run passes — its semaphore parks a message before the delivery fetch, so queue waiting never consumes the transport timeout and there is no retry amplification. It is a bounded FIFO doing what it says; the ceiling it hits is one Node process serving what the Vercel lane spreads across Fluid instances. world-postgres' 24-38 step execution already in flight lines 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), so it is an unshipped design decision rather than a local-World gap.

What was wrong is that the harness generated most of that load itself, in two ways.

The poke pump had unbounded loop gain.step-storm's pressure is a wall-clock cadence, so a slow run collected more out-of-band writes per unit of progress than a fast one — and each poke appends a hook_received that every later replay of that run re-reads and re-buffers, so more pokes make the run slower, which earns it more pokes. On a 4-core runner it ran away to ~270 pokes per run and none of the six concurrent runs finished.

The pump now runs EVENT_LOG_RACE_REPRO_POKE_MAX (64) pokes at full cadence and then decays to × POKE_DECAY_FACTOR (8) rather than stopping. A hard stop turned the lanes green but at a real cost to coverage: every step-storm run on both local lanes spent the whole budget, leaving the back half of a ~160s run with no out-of-band writes at all, and lowering attempt concurrency does not help (at c3 runs finish in 87-96s and still spend it). Decaying keeps loop gain below 1 while a slow run's later rounds keep receiving pressure.

Worth knowing: the lanes were never comparable on this axis. A Vercel resume pays a network round trip, so that lane's pump achieves an effective ~2.3s interval (35-44 pokes per run) where localhost runs the full 750ms — the local lanes were applying ~3x the out-of-band write rate of the lane that found the production bug, and the decayed rate is what brings them near it.

Abandoned runs kept running. A run the harness gives up on at runTimeoutMs went on replaying in the same app process for the rest of the job. That is the whole story behind world-local's hook-storm reporting six stuck runs with resumesSent: 0: each starved behind the previous scenario's six abandoned step-storm runs and never created a hook for the driver to resume, so the scenario measured nothing about hooks at all. Abandoned runs are now cancelled, so later replays find a terminal run and stop.

stuck is now diagnosable. Results carry progress — the run's event count and last event type, read before the cancel — which separates "progressing, slower than runTimeoutMs" from "dormant". Reading a lane without it is guesswork; that is why the starvation above survived two dispatches unnoticed. The rendered config line also names the poke budget and its decay, since a bound that changes coverage should not be invisible next to the cadence it bounds.

No runtime or World code changes: the harness, its CI wiring, the results renderer, and the docs.

How did you test your changes?

The lanes themselves, against the two main dispatches above as the baseline. Three consecutive green passes (14/14 each) on world-local, world-postgres and Vercel, with step-storm stragglers at 16-33 of 48 branches — the step-count amplifier the repro depends on is still firing, so this is not green-by-way-of-doing-less.

The decay, 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.

The abandon path, locally with RUN_TIMEOUT_MS=15000:

{"scenario":"step-storm","outcome":"stuck","durationMs":15113,
"progress":{"events":390,"lastEventType":"step_completed"},
"pressure":{"resumesSent":3,"resumesFailed":0}}

progress.events: 390 with step_completed last is exactly the "slow, not dormant" reading the field exists for, and wf inspect run afterwards reports the abandoned run as status: 'cancelled'.

The renderer, node --test .github/scripts/render-event-log-race-repro-results.test.js — 21 pass, including new coverage that the poke budget and decay reach the rendered config and that an older history row without them renders no invented ceiling.

Follow-ups, deliberately not in this PR

Two default-concurrency smells surfaced while measuring, neither of which is what made the lanes red, and neither of which I can currently show harm from: world-local defaults to 1000 in-flight deliveries while the comment above the constant says the limit exists to avoid overwhelming the process (the repro script overrides it to 10), and world-postgres defaults to 50 embedded workers per process. A 5-run pass at world-local's shipped default completed clean on a 12-core laptop, so the mismatch is a smell rather than a demonstrated defect. Changing either default affects every user of those Worlds and deserves its own PR with its own before/after numbers.

PR Checklist - Required to merge

  • 📦 pnpm changeset was run to create a changelog for this PR
    • Empty changeset: harness, CI, and docs only, no published package.
  • 🔒 DCO sign-off passes (git commit --signoff)
  • 📝 Ping @vercel/workflow in a comment once the PR is ready, and the above checklist is complete

🤖 Generated with Claude Code

The local lanes have no usable baseline: two dispatches of the same commit
scored world-local 6 and 12 of 14 runs `stuck`, and world-postgres 5-6 of 6
`step-storm` runs `stuck` at `runTimeoutMs` in both. The runs were not dormant
— they were being poked ~1/s throughout and still could not finish — so the
lane was measuring the runner's throughput rather than the event log.
Two harness properties made that self-sustaining:
* `step-storm`'s poke pump is a wall-clock cadence, so a slow run collected
more out-of-band writes per unit of progress than a fast one, and each poke
appends a `hook_received` that every later replay re-reads. On a 4-core
runner it reached ~270 pokes per run. Capped at `POKE_MAX` (64), against
35-41 for a healthy 6-round run.
* Runs abandoned at `runTimeoutMs` kept replaying in the same app process for
the rest of the job. That is how world-local's `hook-storm` reported six
`stuck` runs with `resumesSent: 0`: they starved behind the previous
scenario's six abandoned `step-storm` runs and never created a hook for the
driver to resume, so the scenario measured nothing about hooks at all. They
are now cancelled, so later replays find a terminal run and stop.
A `stuck` result also carries `progress` now — the run's event count and last
event type — which is what separates "slower than `runTimeoutMs`" from
"dormant" without guessing.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@vercel

vercelBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
example-nextjs-workflow-turbopackReadyReadyPreviewAug 14, 2026 6:35pm
example-nextjs-workflow-webpackReadyReadyPreviewAug 14, 2026 6:35pm
example-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-astro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-express-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-fastify-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-hono-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nestjs-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nitro-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-nuxt-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-python-workflowErrorErrorAug 14, 2026 6:35pm
workbench-sveltekit-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-tanstack-start-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workbench-vite-workflowReadyReadyPreviewAug 14, 2026 6:35pm
workflow-docsReadyReadyPreview, v0Aug 14, 2026 6:35pm
workflow-swc-playgroundReadyReadyPreviewAug 14, 2026 6:35pm
workflow-tarballsReadyReadyPreviewAug 14, 2026 6:35pm
workflow-webReadyReadyPreviewAug 14, 2026 6:35pm

@changeset-bot

changeset-botBot commented Aug 14, 2026

Copy link
Copy Markdown

🦋 Changeset detected

Latest commit: f6ef804

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 0 packages

When 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

@VaguelySeriousVaguelySerious added the event-log-race-repro Run the event log race reproduction job label Aug 14, 2026
@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

All tests passed

⚠️ Flaky E2E Tests (passed on retry)

These tests failed at least once and passed on a retry. A recurring entry here is a real race worth investigating.

  • parallelStepsThenWebhookWorkflow - no hook_conflict from same-tick replay race (nitro)

E2E Test Summary

Summary
PassedFailedSkippedTotal
✅ ▲ Vercel Production346605904056
✅ 💻 Local Development353605204056
✅ 📦 Local Production381005584368
✅ 🐘 Local Postgres381005584368
✅ 🪟 Windows31200312
✅ vercel-multi-region270027
Total149610222617187
Details by Category

✅ ▲ Vercel Production

AppPassedFailedSkipped
✅ astro-node128028
✅ astro-quickjs128028
✅ example-node128028
✅ example-quickjs128028
✅ express-node128028
✅ express-quickjs128028
✅ fastify-node128028
✅ fastify-quickjs128028
✅ hono-node128028
✅ hono-quickjs128028
✅ nest-node128028
✅ nest-quickjs128028
✅ nextjs-turbopack-node15303
✅ nextjs-turbopack-quickjs15303
✅ nextjs-webpack-node15303
✅ nextjs-webpack-quickjs15303
✅ nitro-node128028
✅ nitro-quickjs128028
✅ nuxt-node128028
✅ nuxt-quickjs128028
✅ sveltekit-node14709
✅ sveltekit-quickjs14709
✅ tanstack-start-node128028
✅ tanstack-start-quickjs128028
✅ vite-node128028
✅ vite-quickjs128028

✅ 💻 Local Development

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 📦 Local Production

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🐘 Local Postgres

AppPassedFailedSkipped
✅ astro-stable-node130026
✅ astro-stable-quickjs130026
✅ express-stable-node130026
✅ express-stable-quickjs130026
✅ fastify-stable-node130026
✅ fastify-stable-quickjs130026
✅ hono-stable-node130026
✅ hono-stable-quickjs130026
✅ nest-stable-node130026
✅ nest-stable-quickjs130026
✅ nextjs-turbopack-canary-node137019
✅ nextjs-turbopack-canary-quickjs137019
✅ nextjs-turbopack-stable-node15600
✅ nextjs-turbopack-stable-quickjs15600
✅ nextjs-webpack-canary-node137019
✅ nextjs-webpack-canary-quickjs137019
✅ nextjs-webpack-stable-node15600
✅ nextjs-webpack-stable-quickjs15600
✅ nitro-stable-node130026
✅ nitro-stable-quickjs130026
✅ nuxt-stable-node130026
✅ nuxt-stable-quickjs130026
✅ sveltekit-stable-node14907
✅ sveltekit-stable-quickjs14907
✅ tanstack-start-node130026
✅ tanstack-start-quickjs130026
✅ vite-stable-node130026
✅ vite-stable-quickjs130026

✅ 🪟 Windows

AppPassedFailedSkipped
✅ nextjs-turbopack-node15600
✅ nextjs-turbopack-quickjs15600

✅ vercel-multi-region

AppPassedFailedSkipped
✅ nextjs-turbopack2700

📋 View full workflow run

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit f6ef804 · Fri, 14 Aug 2026 18:55:29 GMT · run logs

Backend: vercel · app: nextjs-turbopack

MetricScenarioBest (ms)P75 (ms)P90 (ms)P99 (ms)Samples
TTFSstep1370 (+27%) 🔻1558 🔴 (+8.3%)1649 🔴 (+9.3%)1815 🔴 (+12%)30
TTFSstream1365 (+166%) 🔻1488 🔴 (+14%)1507 🔴 (+15%)1527 🔴 (+8.1%)30
TTFShook + stream1553 (+150%) 🔻1815 🔴 (+10%)1929 🔴 (+9.3%)2145 🔴 (+10%)30
Fan-out TTFSPromise.all(100 steps)9240 (+3.4%)10944 (+9.1%)10957 (+7.6%)15535 (+51%) 🔻10
Fan-out TTLSPromise.all(100 steps)18017 (+3.5%)19894 (+5.3%)20030 (+5.6%)25596 (+27%) 🔻10
STSO1020 steps (inline)126 (-10%)190 (-18%) 💚215 (-23%) 💚321 (-57%) 💚1019
WO1020 steps191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚191181 (-16%) 💚1
SLstream latency120 (+2.6%)160 🔴 (-13%)180 🔴 (-25%) 💚234 🔴 (-66%) 💚30
SOstream overhead (text)147 (+7.3%)207 (-13%)247 (-17%) 💚313 (-44%) 💚30
SOstream overhead (structured)151 (+2.0%)204 (-22%) 💚226 (-22%) 💚456 (+10%)30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 226900ms → this run 189546ms (Δ -37354ms, -16%)

 100-150 ms ┃ main 11 this 3 -8
150-200 ms ██████████████░░░░░░░░░┃ main 499 this 847 +348
200-250 ms ███┃██████ main 338 this 129 -209
250-300 ms ┃██ main 90 this 25 -65
300-350 ms ┃ main 27 this 9 -18
350-400 ms ┃ main 20 this 2 -18
400-450 ms ┃ main 5 this 2 -3
450-500 ms ┃ main 4 this 0 -4
500-550 ms ┃ main 3 this 0 -3
550-600 ms ┃ main 0 this 1 +1
600-650 ms ┃ main 1 this 0 -1
650-700 ms ┃ main 5 this 0 -5
700-750 ms ┃ main 8 this 1 -7
800-850 ms ┃ main 2 this 0 -2
850-900 ms ┃ main 2 this 0 -2
900-950 ms ┃ main 2 this 0 -2
1050-1100 ms ┃ main 1 this 0 -1
1150-1200 ms ┃ main 1 this 0 -1
ℹ️ Metric definitions & methodology

The 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: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

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 (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. Fan-out TTFS/TTLS are the first and last step completions of a single Promise.all over trivial steps, from the same anchor, so the gap between the two rows is the spread the runtime adds across the fan-out. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 3 fail of 41 total

log=mint-ordered · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisionfailed91.0mMISMATCH1
in-flight-before-decision-countedfailed91.0mMISMATCH1
in-flight-after-decisionfailed91.0mMISMATCH1
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 41 total

log=append-only · fence=per-spec

scenariooutcomeeventsvirtreplayviolations
smoke-no-stepscompleted30msok0
smoke-one-stepcompleted60msok0
hook-at-step-startedcompleted120msok0
hook-at-step-completedcompleted120msok0
hook-at-hook-createdcompleted120msok0
deadline-hook-winscompleted71.0hok0
deadline-expirescompleted71.0hok0
long-sleepcompleted1130.0dok0
hook-never-arrivesstalled30msskipped0
step-retries-twicecompleted102.0sok0
parallel-stepscompleted90msok0
hook-on-execution-statecompleted120msok0
peek-hook-before-branchcompleted120msok0
peek-hook-after-branchcompleted120msok0
peek-hook-at-registrationcompleted120msok0
race-hook-before-probecompleted120msok0
race-hook-after-probecompleted120msok0
race-duplicate-deliverycompleted130msok0
attr-hook-before-stepcompleted110msok0
attr-hook-after-stepcompleted110msok0
attr-from-step-bodycompleted130msok0
fork-hook-after-timeoutcompleted141.0mok0
fork-hook-before-timeoutcompleted141.0mok0
count-hook-after-timeoutcompleted171.0mok0
count-hook-before-timeoutcompleted201.0mok0
stale-read-step-count-forkcompleted201.0mok0
stale-read-equal-step-countscompleted141.0mok0
step-vs-step-forkcompleted120msok0
step-vs-step-fork-fencedcompleted120msok0
fence-catches-benign-directioncompleted125msok0
in-flight-before-decisioncompleted171.0mok0
in-flight-before-decision-countedcompleted171.0mok0
in-flight-after-decisioncompleted192.0mok0
stale-read-step-count-fork-fencedcompleted201.0mok0
fork-hook-winscompleted131.0mok0
fork-timeout-winscompleted131.0mok0
unclaimed-payload-under-forkcompleted171.0mok0
claimed-payload-under-forkcompleted171.0mok0
writers-independent-step-bodiescompleted120msok0
writers-scripted-tempocompleted120msok0
cancel-mid-stepcancelled70msskipped0

Full trace: world-sim-append-only.txt

@github-actions

github-actionsBot commented Aug 14, 2026

Copy link
Copy Markdown
Contributor

Event Log Race Repro

  • vercel clean, 14 runs
  • local clean, 14 runs
  • postgres clean, 14 runs

Run History

RunLaneTotalCompleteCorruptStuckOther
08-14 18:25vercel1414000
local1414000
postgres1414000
08-14 18:39vercel1414000
local1414000
postgres1414000
Config

14 runs / step-storm 6, hook-storm 6, hook-sleep 2 / c8 / 6x8 / watchdog 2500ms / step 2200±250ms / stagger 400ms / poke 750ms / poke max 64 / timeout 240000ms

@VaguelySeriousVaguelySerious changed the title [e2e] Bound the event-log race repro's self-inflicted load[e2e] Fix event-log-race-repro for local/postgres Aug 14, 2026
The cap binds on the local lanes — every step-storm run there reaches it — so a
config line naming only the cadence advertises a run-long stream of out-of-band
writes the run did not receive. A bound that truncates coverage has to be
visible next to the numbers it truncates.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: Peter Wielander <peter.wielander@vercel.com>
@VaguelySerious
VaguelySerious marked this pull request as ready for review August 14, 2026 18:34
@VaguelySerious
VaguelySerious requested a review from a team as a code ownerAugust 14, 2026 18:34
@VaguelySerious
VaguelySerious merged commit f5591aa into mainAug 14, 2026
161 of 165 checks passed
@VaguelySerious
VaguelySerious deleted the peter/fix-race-repro-lanes branch August 14, 2026 18:34
@github-actions

Copy link
Copy Markdown
Contributor

No backport to stable for f5591aa (AI decision).

This tunes the event-log-race-repro harness (poke-pressure cap, cancelling abandoned runs, progress diagnostics) plus its CI wiring and AGENTS.md notes — no runtime or World code. The behavior it fixes is main-only: git show origin/stable:packages/core/e2e/event-log-race-repro.test.ts still has just the hook-sleep scenario with no storm scenarios, poke pump, or resumesSent pressure, and scripts/event-log-race-repro-local.sh (the local world-local/world-postgres lanes this targets) does not exist on stable at all. There is nothing on the maintenance line for the fix to make correct.

To override, re-run the Backport to stable workflow manually via workflow_dispatch and paste this commit SHA into the ref input:

f5591aa27860a777fba06531daec555ae4e22d34

Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

event-log-race-reproRun the event log race reproduction job

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@VaguelySerious