feat(runtime): report replay cost per step batch, flagged by retained-VM mode - #3490
Conversation
🦋 Changeset detectedLatest commit: d098a38 The changes in this PR will be included in the next version bump. This PR includes changesets to release 16 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❌ Some tests failed ❌ Failed E2E Tests▲ Vercel Production (8 failed)python-node (8 failed):
🌐 Cross-language Conformance (9 failed)python (9 failed):
|
| Passed | Failed | Skipped | Total | |
|---|---|---|---|---|
| ❌ ▲ Vercel Production | 3570 | 8 | 742 | 4320 |
| ✅ 💻 Local Development | 3922 | 0 | 558 | 4480 |
| ✅ 📦 Local Production | 3922 | 0 | 558 | 4480 |
| ✅ 🐘 Local Postgres | 3922 | 0 | 558 | 4480 |
| ✅ 🪟 Windows | 320 | 0 | 0 | 320 |
| ❌ 🌐 Cross-language Conformance | 0 | 9 | 132 | 141 |
| ✅ vercel-http-transport | 817 | 0 | 143 | 960 |
| ✅ vercel-multi-region | 27 | 0 | 0 | 27 |
| ✅ vercel-ws-transport | 553 | 0 | 87 | 640 |
| Total | 17053 | 17 | 2778 | 19848 |
Details by Category
❌ ▲ Vercel Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-node | 132 | 0 | 28 |
| ✅ astro-quickjs | 132 | 0 | 28 |
| ✅ example-node | 132 | 0 | 28 |
| ✅ example-quickjs | 132 | 0 | 28 |
| ✅ express-node | 132 | 0 | 28 |
| ✅ express-quickjs | 132 | 0 | 28 |
| ✅ fastify-node | 132 | 0 | 28 |
| ✅ fastify-quickjs | 132 | 0 | 28 |
| ✅ hono-node | 132 | 0 | 28 |
| ✅ hono-quickjs | 132 | 0 | 28 |
| ✅ nest-node | 132 | 0 | 28 |
| ✅ nest-quickjs | 132 | 0 | 28 |
| ✅ nextjs-turbopack-node | 157 | 0 | 3 |
| ✅ nextjs-turbopack-quickjs | 157 | 0 | 3 |
| ✅ nextjs-webpack-node | 157 | 0 | 3 |
| ✅ nextjs-webpack-quickjs | 157 | 0 | 3 |
| ✅ nitro-node | 132 | 0 | 28 |
| ✅ nitro-quickjs | 132 | 0 | 28 |
| ✅ nuxt-node | 132 | 0 | 28 |
| ✅ nuxt-quickjs | 132 | 0 | 28 |
| ❌ python-node | 0 | 8 | 152 |
| ✅ sveltekit-node | 151 | 0 | 9 |
| ✅ sveltekit-quickjs | 151 | 0 | 9 |
| ✅ tanstack-start-node | 132 | 0 | 28 |
| ✅ tanstack-start-quickjs | 132 | 0 | 28 |
| ✅ vite-node | 132 | 0 | 28 |
| ✅ vite-quickjs | 132 | 0 | 28 |
✅ 💻 Local Development
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 📦 Local Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 🐘 Local Postgres
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 134 | 0 | 26 |
| ✅ astro-stable-quickjs | 134 | 0 | 26 |
| ✅ express-stable-node | 134 | 0 | 26 |
| ✅ express-stable-quickjs | 134 | 0 | 26 |
| ✅ fastify-stable-node | 134 | 0 | 26 |
| ✅ fastify-stable-quickjs | 134 | 0 | 26 |
| ✅ hono-stable-node | 134 | 0 | 26 |
| ✅ hono-stable-quickjs | 134 | 0 | 26 |
| ✅ nest-stable-node | 134 | 0 | 26 |
| ✅ nest-stable-quickjs | 134 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 160 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 141 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 141 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 160 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 160 | 0 | 0 |
| ✅ nitro-stable-node | 134 | 0 | 26 |
| ✅ nitro-stable-quickjs | 134 | 0 | 26 |
| ✅ nuxt-stable-node | 134 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 134 | 0 | 26 |
| ✅ sveltekit-stable-node | 153 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 153 | 0 | 7 |
| ✅ tanstack-start-node | 134 | 0 | 26 |
| ✅ tanstack-start-quickjs | 134 | 0 | 26 |
| ✅ vite-stable-node | 134 | 0 | 26 |
| ✅ vite-stable-quickjs | 134 | 0 | 26 |
✅ 🪟 Windows
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack-node | 160 | 0 | 0 |
| ✅ nextjs-turbopack-quickjs | 160 | 0 | 0 |
❌ 🌐 Cross-language Conformance
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ❌ python | 0 | 9 | 132 |
✅ vercel-http-transport
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ example | 132 | 0 | 28 |
| ✅ express | 132 | 0 | 28 |
| ✅ hono | 132 | 0 | 28 |
| ✅ nextjs-turbopack | 157 | 0 | 3 |
| ✅ nitro | 132 | 0 | 28 |
| ✅ vite | 132 | 0 | 28 |
✅ vercel-multi-region
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack | 27 | 0 | 0 |
✅ vercel-ws-transport
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ example | 132 | 0 | 28 |
| ✅ express | 132 | 0 | 28 |
| ✅ nextjs-turbopack | 157 | 0 | 3 |
| ✅ vite | 132 | 0 | 28 |
📊 Workflow Benchmarkscommit Backend:
Streams
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 145414ms → this run 140245ms (Δ -5169ms, -4%) 📈 CRTT drill-down vs main (RTT distributions & profiles)RTT over stream progress (avg per tenth of stream, bars scaled min→max): RTT by chunk size (avg per log size bin, ~160B → ~12KB serialized, bars scaled min→max): Delivery jitter over stream progress (avg positive CDV per tenth of stream, bars scaled min→max): ℹ️ Metric definitions & methodologyStreams: first-chunk RTT (the stream-open path, before any buffering/backpressure), CRTT percentiles, and worst delivery stall (CDV max). Cells are medians across iterations; per-run values in the artifacts. No 🔴/🟢 marks until targets attach. The collapsed STSO distribution section above buckets every step gap, split inline (same warm process — pure framework overhead) vs queue-hop (fresh process — dispatch, reinit, replay). The collapsed CRTT drill-down: per-variant RTT histograms (fixed log bins, 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) · 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) · CRTT: chunk round-trip time (per-chunk write → read latency, one clock domain: deployment → stream backend → same deployment) · CDV: chunk delay variation / delivery jitter (inter-arrival gap minus inter-write gap per seq-adjacent pair; skew-free; the row is each run's MAX positive value, so one stall moves it) 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 · paced control (100/s, 60B): the control: 300 tiny (~60B) deltas metronome-paced at 100/s — zero workload structure, so it reads the transport floor and flush cadence, and disambiguates transport-wide vs workload-specific when a replay row moves · size sweep (100/s, 160B-12KB): same pacing as the control with deltas padded in rotation across seven log-spaced sizes (~160B–12KB) — rotation decouples size from stream position, so it isolates whether chunk size causes latency · replay gateway-gpt-5.4-nano-2000t (1x): raw provider SSE cadence captured at the AI gateway boundary (gpt-5.4-nano, the most popular gateway model; per-token deltas p50 208B = the modal production chunk size), replayed exactly as measured — the typical customer's workload; its CDV is the typical customer's real delivery jitter · replay eve-gpt-5.6-sol-2000t (1x): a captured eve turn (gpt-5.6-sol, the most-used demanding eve model; ~2000 output tokens = production p50 turn length) replayed exactly as measured — eve's envelope protocol re-ships the cumulative message so sizes ramp 142B→13KB; the demanding outlier tenant's reality · replay eve-gpt-5.6-sol-2000t (2x): the same eve capture at 2x — the headroom/stress row; real fast-tier models emit the same chunk sizes at proportionally higher rate, so time compression is a faithful speed model · first chunk (pooled): every run's seq-0 RTT pooled across all stream scenarios — the first chunk precedes any workload differentiation, so pooling samples one shared stream-open path with exact percentiles Replay cadences (semantic sha256) — eve-gpt-5.6-sol-2000t 🔴 marks a percentile over its target (within target is left unmarked). Targets (p75/p90/p99, ms) — TTFS 200/300/600 All timestamps are deployment-side; runs are triggered in-deployment, so the CI runner and api.vercel.com sit outside every measured window. TTFS = Cold starts stay in the numbers (real bursty-workload latency, inflates P75+); Best is the warm floor. |
Sim WorldSimulated world deterministic testing for races. Traces 🟠 world-sim scenario book — 1 fail of 41 total
Full trace: |
64da8d0 to
efc2b5f
Compare
…tained-VM mode Co-Authored-By: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com> Co-Authored-By: shalabhc <shalabh.chaturvedi@vercel.com>
|
No backport to This commit adds new telemetry surface — it broadens To override, re-run the Backport to stable workflow manually via |
This changes metrics and spans only:
replayCostretainedas an optimization tag so it is reported by the backend spans.Details
## SummaryTwo changes, both in
@workflow/core:Replay cost is now reported for every batch that qualifies for TTFS or STSO, not just the run's first step.
replayMswas gated on RSFS eligibility, so every ordinary step-to-step transition — the STSO population, which is the bulk of step scheduling — had no replay-cost telemetry at all. The value was already measured at every suspension (replayDurationMsinruntime.ts) and then discarded.Whether a retained VM served the batch is reported as a
retainedentry in the existingoptimizationslist, alongsideturbo/lazyStepStart/optimisticStart.finalSchedulingReplaymeasures a resume on the retained path and a full replay otherwise, so without this dimension the metric is knowingly bimodal — the existing doc comment says so.Why
optimizationsinstead of a dedicated fieldAn earlier version of this PR added a
replayMode: 'replay' | 'retained'wire field, which cost two extra packages here (world-vercel,world) plus a parse/sanitize path and a metric tag in workflow-server.Riding the existing
optimizationsarray instead means the SDK change is one line and the server needs no new parsing at all:reportClientStepLatencyalready turns each known entry into a bounded boolean tag applied to every latency metric. So the companion backend change — vercel/workflow-server#767 — collapses to adding one entry toOPTIMIZATION_TAGS, andretaineddimensionsttfs_ms,stso_ms,rsfs_msandfinal_scheduling_replay_msrather than only the last of those. Unknown entries are already ignored server-side, so old and new SDKs interoperate;client_versionis already a tag on these metrics, so "no flag because full replay" stays distinguishable from "no flag because old SDK".Why the retained flag is computed here rather than read off a span
traceExecutiontags theworkflow.runspanretainedwhen the span opens, beforesession.resume()can come back with{ type: 'replay' }on an internal cache miss and fall through to a real replay. The flag in this PR is computed after the resume result is known, so it does not inherit that mislabeling.Motivation
Production analysis of the
v0chatSTSO tail: retained batches were 88.5% of sampled steps with a 2.0 s STSO p75, full replays 11.4% with a 58.7 s p75, and full replay accounted for 66% of everything above p90. Mode is the strongest tail discriminator found, and it was only reachable via a cross-span temporal join over ~7% sampled spans.Test plan
pnpm exec vitest run packages/core/src/runtime/step-latency.test.ts— 38 passed, including the STSO broadening and bothretainedstatespnpm exec vitest run packages/core/src/runtime.test.ts— 44 passed; the turbo latency test now pins that the first step's pass (a full replay that built the VM) has noretainedflag while the second step's pass, resumed from the session the same invocation retained, doespnpm exec vitest run packages/core/src/workflow.test.ts— 89 passed, 1 expected failpnpm --filter @workflow/core typecheckstep_completed/step_failedevents for ordinary (non-first-step) suspensions carryfinalSchedulingReplay, and thatretainedappears inoptimizations