[measurement] Storm repro with call-site ids + sequential replays - #3180
[measurement] Storm repro with call-site ids + sequential replays#3180VaguelySerious wants to merge 15 commits into
Conversation
…by event-log position Two production runs on `@workflow/core@5.0.0-beta.36` burned all three divergence-recovery replays at the same event and terminated with CORRUPTED_EVENT_LOG: wrun_41KYJENABV0GSF5YTE9EETV5DD (step vs wait) wrun_41KYJEE01S0GPC9RWT5MEKVCX8 (step vs hook) Replay divergence: step event step_created for step_X belongs to "A", but the current step consumer is "B" `useStep` proxies draw deterministic ULIDs in invocation order, so the ULID -> stepName allocation is a function of the order in which promise resolutions are delivered to workflow code. The delivery-barrier registry pinned that order to event-log position for hook payloads and wait completions, but step results were delivered straight off the serial `promiseQueue` — and their latency varies between replays of the SAME invocation, because the first replay pays full hydration while later replays memo-hit primitive results in the shared `ReplayPayloadCache`. A step completion adjacent in the log to a `wait_completed` was therefore delivered wait-first on a cold replay and step-first on a warm one; whichever order the invocation that wrote the follow-up `step_created` events happened to see became law, and every replay computing the other order diverged permanently. Step results and step failures now register a 'step' delivery barrier at their event-log index and resolve from a detached continuation after every relevant earlier-in-log delivery, mirroring the hook payload path: hydration stays inside the serial queue slot (which also releases `pendingDeliveries`), while the barrier wait and the resolve run off the queue so a queue slot never blocks on a resolution the queue itself drives. Waits and hook payloads likewise defer behind earlier step results. Two details are what actually make the ordering hold, and both were found by testing rather than by reading the code: The deferral set is captured while CONSUMING the event, not at the start of the hydration slot. Captured at slot start it is not merely less deterministic, it is usually empty: an earlier delivery whose own slot runs first on the serial queue has typically already resolved and deregistered its barrier before the later slot begins, so the later delivery does not defer at all. Every event in one drain window is consumed before any slot runs, so consumption time sees all of them. A delivery that had to wait then yields a macrotask before resolving. An earlier delivery being "delivered" only means its `resolve()` ran; the branch it woke may need arbitrarily many further microtask hops before it reaches its next `useStep` call (a `for await` over a hook resumes the generator, settles the promise from `next()`, and only then runs the loop body). Ordering the `resolve()` calls alone therefore buys a fixed hop or two of margin and leaves a hop-count race that holds only for the shortest consumers; yielding a macrotask lets the earlier branch drain completely, whatever its shape. One asymmetry is load-bearing: a step result skips any earlier delivery that will not resolve on its own, i.e. one blocked directly or transitively on a buffered hook payload no consumer has claimed. Such a payload is delivered only when the workflow next reads the hook, and reaching that read commonly requires the step result itself, so gating the step on it stalls the run until the barrier's idle safety net fires — which then releases every delivery queued behind that payload at once and loses the very race the ordering exists to protect. Waits and hooks keep gating on unclaimed payloads, where waiting for the claim IS the guarantee. Tests come in two files. `step-delivery-ordering.test.ts` is byte-identical to the file in the repro-only companion PR #3137 apart from two `it.fails` markers there (which let a repro-only branch have green CI); `sed 's/it\.fails(/it(/g' | cmp` verifies it. Each of its five cases replays one committed log twice through a shared `ReplayPayloadCache`, and the two warm-replay cases fail on main with the production error text. `step-delivery-hop-count.test.ts` exists because those five cases cannot tell "delivered in log order" apart from "resolves a hop or two later than before". It replays logs a live run legitimately produced — the live invocation received the two events in separate deliveries, so the first branch finished long before the second event existed — while the replay receives both in one drain window, and pads the consumer with a varying number of extra awaits so hop count is the only variable. It covers step results against both wait completions and hook payloads, plus step FAILURES against wait completions, since a rejection decides whether a `catch` continuation runs and so which ULID the `useStep` there draws. All 18 cases fail on main; of the 12 that predate the macrotask, 9 still fail with the resolve-ordering-only version of this fix; all 18 pass here. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Signed-off-by: Pranay Prakash <pranay.gp@gmail.com>
Follow-up on the step-delivery barrier work, addressing three cases the registry did not yet cover. Each has a regression test in the new `delivery-barrier-coverage.test.ts` that reproduces the production `ReplayDivergenceError` when its fix is reverted. - Step results now defer behind earlier STEP results. The old exclusion assumed the serial `promiseQueue` fixes step-vs-step order, which stopped holding once a step began resolving from a detached continuation instead of its queue slot: two steps consumed in different drain windows can disagree on their deferral set, and the earlier one — parked on the macrotask yield — gets overtaken. - `sleep.ts` and `hook.ts` (waiting-consumer path) now capture their deferral at event-consumption time, as `step.ts` already does. Reading the registry after their queue work misses an earlier step or hook that delivered and retired its barrier in the meantime, skipping both the gate and the macrotask yield. The buffered hook payload path deliberately keeps evaluating at claim time; a consumption-time snapshot there stalls the e2e `hookWithSleepWorkflow`. - Abort deliveries participate in the registry. `_setAborted` fires the signal's listeners, which may invoke a step and draw a ULID, so an abort is as branch-deciding as any other delivery. Also memoizes `resolvesOnItsOwn`. The walk is exponential in the number of live hook/wait barriers, and the registry is not bounded — a fan-out of `Promise.race([hook, sleep])` branches accumulates one barrier per branch per kind (49 measured for 24 branches). At 40 barriers a single scan took 92s before, and is instant after.
…process A replay-context event creation previously described its snapshot with a single watermark, which only proves no event landed above it. It cannot detect a *missing* event below it, so a replay working from a log with a hole still committed events derived from that hole — and because correlation IDs are positional ordinals of one seeded sequence, a one-event difference renames every downstream entity and corrupts the log. Creations now also send the snapshot's event count and its cursor, and a rejection restarts the replay inside the same invocation instead of re-posting the rejected payload (whose IDs the corrected log invalidates) or paying a queue round trip. A world may attach the missing events to its 412, in which case the first restart needs no event-log request. Also guards the suspension `attr_set` write, and re-sorts a merged event log by event ID when an append arrives out of order. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Also makes the v4 event tests derive their mock origin from the override like the rest of the file already does, so a non-empty override does not fail unit tests. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The matching world-vercel guard shipped and is live in production, so the e2e lanes exercise both halves against the default endpoint. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Resolves the overlap with #3110, which introduced the same event-log merge consolidation this branch had added as `mergeEvents`: `appendUniqueEvents` now carries the optional id set from main plus the out-of-order re-sort and warning, and `mergeEvents` is gone. Main's `withPreconditionRetry` edit drops out with the function itself. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Correlation ids are the Nth draw of one per-run ULID sequence, which makes every id an ordinal: two concurrent replays that disagree about a single event assign different ids to every entity after it, so one replay appends events the other can neither match nor consume and the run fails with CORRUPTED_EVENT_LOG out of a one-event difference. With WORKFLOW_CALLSITE_CORRELATION_IDS=1 an id is derived from the call site that creates the entity — a step's name plus an argument fingerprint, a hook's pinned token — plus a per-scope invocation counter, so the same entity gets the same id in both replays and a late write collides idempotently instead of renaming everything downstream. Ids stay syntactically valid ULIDs; hook tokens for unpinned hooks are derived from the correlation id rather than drawn from the run's PRNG stream. The flag defaults off, and with it off the generator is the positional sequence itself, so nothing about the default path changes. Also sets the flag on the nextjs-turbopack workbench for the race repro.
…ation-ids # Conflicts: # packages/core/src/delivery-barrier-coverage.test.ts # packages/core/src/step-delivery-hop-count.test.ts # packages/core/src/step-delivery-ordering.test.ts
🦋 Changeset detectedLatest commit: acc5739 The changes in this PR will be included in the next version bump. This PR includes changesets to release 21 packages
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 |
VaguelySerious
added
the
event-log-race-repro
📊 Workflow Benchmarkscommit Backend:
📜 Previous results (1)732c5b6Wed, 29 Jul 2026 04:32:34 GMT · run logs
ℹ️ Metric definitions & methodologyBest/P75/P90/P99 deltas compare against the most recent benchmark run on Metrics — TTFS: time to first step body (in-deployment start() → first step body, deployment clocks) · 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 · 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 · STSO (1-20) 20/30/60 · STSO (101-120) 30/45/90 · STSO (1001-1020) 40/60/120 All metrics are measured from deployment-side timestamps only. Runs are triggered by an in-deployment route that stamps the anchor ( Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the |
🧪 E2E Test Results✅ All tests passed E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ 📋 Other
✅ vercel-multi-region
|
Event Log Race Repro84 of 1400 latest repro runs hit event-log regressions. Run History
Latest Scenario Breakdown
Latest Non-Completed Runs
Showing 20 of 84 non-completed runs. |
TEMPORARY measurement branch. The runtime env var alone only creates per-run queue topics; the maxConcurrency: 1 half of the feature is baked into the flow function trigger at build time, so build.env is required for replays to actually serialize.
VaguelySerious
added
event-log-race-repro
|
(AI) First repro run (30421550791) is invalid — discard it. It reported 98/1400 (step-storm 93, hook-storm 5), statistically identical to the call-site-IDs-only baseline of 95/1400, because
|
|
(AI) Re-run with
Sequential replays do not close the residual. No arm reaches significance, and this is the only measurement in the series that produced stuck runs — consistent with the wake-delay trade-off of per-run That refutes the hypothesis this branch was opened to test. The corrected mechanism needs only one replay, not two concurrent ones:
Serializing flow invocations cannot help, because the two disagreeing replays were never required to overlap. This is a currency problem (a replay decided on a prefix that later grew), not a concurrency one, which is the same conclusion the count-based precondition guard ran into. The remaining candidate end states are unchanged: currency-based write admission, or epoch-tagged writes so events from a superseded replay attempt are ignorable rather than fatal. Caveat on verification: I could not confirm serialization at the request-log level because the Vercel API token expired mid-check ( This branch stays measurement-only; do not merge. |
3 participants
Measurement only — do not merge.
Same code as #3179 (call-site correlation IDs), with
WORKFLOW_SEQUENTIAL_REPLAYS=1added to the workbench app on top ofWORKFLOW_CALLSITE_CORRELATION_IDS=1.Why: #3179 cut the storm repro by 84% / 95%, and every one of the residual corrupted runs classified so far fails on a step that only exists on one branch of
Promise.race([settle, sleep(watchdogMs)])— two concurrent replays taking different branches, which no correlation-ID scheme can fix. Sequential replays remove the concurrency that makes the branches disagree. Measured alone (#3175) it was step-storm-neutral; the question is whether it is additive once the rename amplifier is gone.