[core] Fold events.create deltas into the replay log - #3382
Conversation
Outside of turbo mode, every write the orchestrator loop makes now carries `sinceCursor` (the cursor of the log it was computed against) and folds whatever the World hands back into that log. This removes the extra `events.list` the loop made after committing an elapsed `wait_completed`: a supporting World has already returned the delta with the write, so the follow-up fetch only runs for completions still missing locally (a World that ignores `sinceCursor`, a truncated page, a lost cursor race, or an `EntityConflictError`, whose rejection carries no delta). world-local, world-postgres, and world-vercel now serve the delta for any event type, not just terminal step events. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
🦋 Changeset detectedLatest commit: 8e345a4 The changes in this PR will be included in the next version bump. This PR includes changesets to release 20 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 |
🧪 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
|
📊 Workflow Benchmarkscommit Backend:
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 204348ms → this run 146786ms (Δ -57562ms, -28%) ℹ️ Metric definitions & methodologyThe collapsed STSO distribution section above buckets every step gap of the sequential-steps run (not a sampled window), split by whether the step ending the gap ran inline — in the same warm process as the step before it, so the gap is pure framework overhead — or after a queue-hop — the first step of a fresh process, which pays queue dispatch, client reinit and event-log replay. Bars overlay the two runs: Best/P75/P90/P99 deltas compare against the most recent benchmark run on Metrics — TTFS: time to first step body (in-deployment start() → first step body, deployment clocks) · 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 All metrics are measured from deployment-side timestamps only. Runs are triggered by an in-deployment route that stamps the anchor ( Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the |
VaguelySerious
added
the
event-log-race-repro
Event Log Race Repro7 of 14 latest repro runs hit event-log regressions. Run History
Latest Scenario Breakdown
Latest Non-Completed Runs
|
shalabhc
left a comment
shalabhc
left a comment
There was a problem hiding this comment.
Design wise, this feels like the right direction.
Should we stamp sinceCursor on the event derived from that prefix? Might be super useful when debugging cases where another event slips in between the prefix we read and the event we produced.
| .where( | ||
| and( | ||
| eq(Schema.events.runId, effectiveRunId), | ||
| gt(Schema.events.eventId, params.sinceCursor) |
There was a problem hiding this comment.
Note only, possibly preexisting:
If mint order is different than commit order (eg in current ULID scheme) could this skip events on delta read? IOW some events that land on the db in the past could be missed by a delta read.
I think this possibility exists everywhere we use the current scheme of minting ULIDs before commit, not just postgres.
There was a problem hiding this comment.
yes, this can be an issue, but I'm closing that gap separately in #3389
|
No backport to This is a performance optimization: it extends the existing To override, re-run the Backport to stable workflow manually via |
2 participants
Outside of turbo mode, every write the orchestrator loop makes now carries
sinceCursor(the cursor of the log it was computed against) and folds whatever the World hands back into that log.The follow-up
events.listthe loop made after committing an elapsedwait_completedis gone. A supporting World has already returned the delta with the write, so the fetch now only runs for completions still missing locally.What changed
packages/core/src/runtime.tsEventCreatorcomputes asinceCursorper write (deltaRequestCursor) and absorbs the response delta (absorbCreateDelta).deltaRequestCursordeclines for: turbo (it exists to make the first invocation's writes cheap, and there is no loaded log to extend), run-terminal writes (nothing reads the log afterwards), a caller that set its ownsinceCursor, and a caller that asked for therun_started/hook_receivedpreload, which owns the same response fields.absorbCreateDeltadeclines on a truncated page (hasMore), on a cursor that moved since the request went out, and while apendingInlineDeltais unconsumed. Declining is always safe: an unabsorbed delta is a delta the nextevents.listreturns. The cursor-equality gate is what serializes concurrent absorbs, sinceappendUniqueEventsdeliberately does not re-sort.waitsToCompletedown to the completions not already in the local log and skips the fetch when that filter is empty. The remaining cases are a World that ignoressinceCursor, a truncated delta, a lost cursor race, and anEntityConflictError, whose rejection carries no delta.Worlds —
world-local,world-postgres, andworld-vercelnow serve the delta for any event type, not just terminal step events.world-postgresgains a delta branch mirroring its ownlistcursor semantics (same limit,gton eventId,limit + 1forhasMore).world-vercelalready forwardedsinceCursorgenerically.Scope
Only the orchestrator loop's
EventCreatorwas wired up. The step-executor and suspension-handler creators were left alone deliberately: absorbing there saves no round trip and multiplies the concurrent-absorb ordering hazard. The step-executor already has its own inline-delta path feedingpendingInlineDelta.Tests
wait-completion-replay.test.ts: a fake World that honorssinceCursor(the follow-up fetch is skipped entirely), and one that truncates the delta (the fetch still runs). The fake implements fullevents.listcursor semantics, so the five pre-existing tests in that file pass unchanged.runtime.test.ts: no inline delta is requested on a run-terminal write, or anywhere under turbo.world-local/storage.test.ts: the create-response delta for non-terminal event types and forwait_completedmatches a realevents.listfrom the same cursor.Both new runtime behaviors were checked to be load-bearing by neutering the implementation and confirming exactly the expected tests fail.
🤖 Generated with Claude Code