Report RSFS/replay latency telemetry on step terminal events#2929
Conversation
…p terminal events The runtime now measures run-started-to-first-step (the run_started response landing, or the local run synthesis instant under turbo, to the first step's start POST being issued) and synchronous replay compute duration within that window, attaching them to the run's first step_completed/step_failed eventData alongside ttfs/stso. rsfs shares ttfs's exact eligibility gating; replay is a direct passthrough of the replay duration captured at the top of the WorkflowSuspension catch block and can be reported even when rsfs itself is not (e.g. under redelivery before the post-sent anchor is captured). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
🦋 Changeset detectedLatest commit: 90ffbdc 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 |
📊 Workflow Benchmarkscommit Backend:
📜 Previous results (2)2d5af95Wed, 15 Jul 2026 19:42:57 GMT · run logs
d3e2687Tue, 14 Jul 2026 23:15:08 GMT · run logs
Avg deltas compare against the most recent benchmark run on Metrics — TTFS: time to first step body execution · STSO: step-to-step overhead (gap between consecutive step bodies) · WO: workflow overhead (time outside step bodies, client start → last step body exit) · SL: stream latency (first chunk write → visible to the reader) Scenarios — stream: one step that streams chunks back to the client; no hooks, so the run stays in turbo mode · hook + stream: registers a hook before the same streaming step, which exits turbo mode · 1020 steps: 1020 trivial sequential steps; STSO is measured between consecutive steps in the given step ranges 🟢/🔴 mark percentiles within/above target. Targets (p75/p90/p99, ms) — TTFS 200/300/600 · SL 50/60/125 · STSO (1-20) 20/30/60 · STSO (101-120) 30/45/90 · STSO (1001-1020) 40/60/120 TTFS/WO compare client vs deployment clocks and SL compares the step runner’s clock vs the client’s (NTP-synced in CI). WO ends at the last step body exit, the closest observable proxy for the final step-completion request. |
🧪 E2E Test Results✅ All tests passed Summary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ 📋 Other
✅ vercel-multi-region
|
| // below (see StepLatencyTracking.replayMs). Captured | ||
| // here, before `handleSuspension`'s awaited I/O, so | ||
| // it excludes that I/O. | ||
| const replayDurationMs = Date.now() - replayStart; |
There was a problem hiding this comment.
Could we either aggregate replay time across every pre-first-step replay pass, or narrow this metric definition/name? This captures only the current suspension runWorkflow() duration. Valid RSFS/TTFS paths such as workflow-body setAttributes() can replay more than once before the first step, so RSFS covers the whole detour while replay reports only the final pass; a redelivery can omit earlier work too. That makes it misleading to interpret replay as the portion of RSFS spent in replay compute. Accumulating until the first step (or renaming this to something like final_scheduling_replay_ms) would make the semantics explicit. Also, the individual-pass duration is already represented by the existing workflow.run … span; if this metric is intentionally duplicated to provide unsampled/full-population distributions, can we document that rationale?
There was a problem hiding this comment.
or narrow this metric definition/name
Doing
the individual-pass duration is already represented by the existing workflow.run … span
Documenting better
There was a problem hiding this comment.
Addressed in 187510b: renamed to finalSchedulingReplay (lifecycle.step.final_scheduling_replay_ms) and sharpened the comments at both measurement sites — they now state explicitly that this is the final runWorkflow() pass only (not accumulated across pre-first-step passes, so not "the replay portion of RSFS"), and that the duplication with the workflow.run span is deliberate: the server emits it as an unsampled full-population distribution, which the ~7%-sampled span population can't provide.
Server-side counterpart: #626 merged mid-rename with the old name, so the matching server rename is in vercel/workflow-server#628 (deploys before this ships, or the field would be dropped by the allowlist).
…stReplay Clarifies that this sub-window of rsfs is only measured for a run's first step. Renames the eventData field, the StepReplayMs semantic convention (-> StepFirstReplayMs, step.replay_ms -> step.first_replay_ms), and the v4 split-frame meta allowlist entry, keeping the internal "workflow replay" duration variables untouched. Also documents that firstReplay duplicates what OTEL already captures on the run/invocation span, but is deliberately collected as client telemetry so the server can emit it as an unsampled metric. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
![vercel[bot]](https://avatars.githubusercontent.com/in/8329?s=60&v=4){kind=small}
…-start path whenever the `run_started` round-trip is still in flight at the latency-computation point, biasing RSFS percentiles low by discarding exactly the slow-`run_started` samples.
This commit fixes the issue reported at packages/core/src/runtime/step-executor.ts:424
## Bug
In `executeStep` (`packages/core/src/runtime/step-executor.ts`), on the **turbo optimistic-start** path the step-start POST timestamp that anchors RSFS's end point is captured only *inside* the `runReadyBarrier.then(...)` callback:
```ts
const startedPromise = (params.runReadyBarrier ?? Promise.resolve()).then(
() => {
stepStartPostSentAtMs = Date.now(); // runs only after run_started resolves
return world.events.create(workflowRunId, { eventType: 'step_started', ... });
}
);
```
The latency telemetry is then computed **once**, just before user code, at line ~663:
```ts
latencyEventData = computeStepLatencyEventData({
...
stepStartPostSentAtMs, // still undefined if the barrier hasn't resolved
});
```
Between the optimistic-start setup and that computation the only awaits are local/fast operations (`getEncryptionKey()`, `hydrateStepArguments()`, `getPortLazy()`) — **none** await `runReadyBarrier`. So whenever `run_started` has non-trivial latency (the common production case), the barrier is still pending, `stepStartPostSentAtMs` is `undefined`, and in `computeStepLatencyEventData` (`step-latency.ts`) `rsfs` is omitted:
```ts
const rsfs =
tracking.rsfsAnchorMs !== undefined &&
params.stepStartPostSentAtMs !== undefined
? Math.max(0, params.stepStartPostSentAtMs - tracking.rsfsAnchorMs)
: undefined;
```
`reconcileOptimisticStart()` (awaited later, before every terminal write) *does* wait on the barrier, so `stepStartPostSentAtMs` **is** in fact set by the time the terminal event is written — but `latencyEventData` was frozen earlier and never recomputed. Net effect: `rsfs` is recorded only when `run_started` happened to resolve *before* the latency computation (fast runs). Slow-`run_started` invocations — precisely the samples RSFS exists to measure — are dropped. This is a missing-not-at-random bias skewing RSFS percentiles low.
### Concrete trigger
Turbo optimistic start with a `runReadyBarrier` that resolves *after* the body reaches the latency computation. The existing test *"holds the optimistic step_started until runReadyBarrier resolves, but runs the body immediately"* already demonstrates this exact ordering (body runs before `step_started`). I added a regression test with `latencyTracking` anchors and a delayed barrier; with the fix removed it fails (`rsfs` is `undefined` on the terminal `step_completed` event).
## Fix
Added a `backfillOptimisticRsfs()` helper that patches `rsfs` onto the already-computed `latencyEventData` **after** `reconcileOptimisticStart()` has awaited the barrier (so `stepStartPostSentAtMs` is known), called on both the success path and the catch path before the terminal event is written:
```ts
const backfillOptimisticRsfs = (): void => {
if (!latencyEventData || latencyEventData.rsfs !== undefined) return;
const anchorMs = params.latencyTracking?.rsfsAnchorMs;
if (anchorMs === undefined || stepStartPostSentAtMs === undefined) return;
latencyEventData.rsfs = Math.max(0, stepStartPostSentAtMs - anchorMs);
if (span) span.setAttributes({ ...Attribute.StepRsfsMs(latencyEventData.rsfs) });
};
```
It recomputes **only** RSFS — TTFS/STSO stay anchored to `executionStartTime` exactly as before. Because a terminal event is only written when the optimistic start settled `ok` (a lost race / throttle / gone short-circuits via `reconcile` before any write), `stepStartPostSentAtMs` is guaranteed set at each backfill point, so RSFS is now present whenever `rsfsAnchorMs` is eligible. The step span is also updated so traces reflect the backfilled value.
### Validation
- New regression test asserts `rsfs` is present/≥0 on the terminal event with a delayed barrier; it **fails without the fix** and passes with it.
- Full `step-handler.test.ts` (36) and `step-latency.test.ts` (33) suites pass.
- `tsc --noEmit` clean.
### Doc side note
The claims in `packages/world/src/events.ts` and `packages/world-vercel/src/events-v4.ts` that `finalSchedulingReplay` is "Only present alongside rsfs" are now **correct** as a code-enforced invariant, so no doc edit was necessary.
Co-authored-by: Vercel <vercel[bot]@users.noreply.github.com>
Co-authored-by: VaguelySerious <mittgfu@gmail.com>
karthikscale3
left a comment
karthikscale3
left a comment
There was a problem hiding this comment.
Re-reviewed the current head after the requested changes. The turbo optimistic-start RSFS sampling bias is fixed by backfilling after reconciliation on both terminal paths, with delayed-barrier regression coverage. finalSchedulingReplay now precisely documents the non-aggregated final-pass semantics and the unsampled-metric rationale. Approving. Deployment remains gated on workflow-server#628 landing first.
|
No backport to This commit extends the client-side TTFS/STSO latency telemetry infrastructure (from #603) that exists only on To override, re-run the Backport to stable workflow manually via |
3 participants
What
Adds two new client-latency telemetry fields, riding the exact same path as the existing
ttfs/stsofields added in #603:rsfs(run-started-to-first-step): ms from therun_startedresponse being received/parsed by the SDK (or, under turbo, the local run-synthesis instant) to the first step's start POST being issued. Sharesttfs's eligibility gating exactly (invocationStartedClean), plus arunStartedReceivedAtMsanchor.finalSchedulingReplay: ms of only the FINAL replay pass within that window — therunWorkflow()invocation that reached and scheduled the first step — spent in synchronous replay compute (executing the workflow function / event-log replay), excluding awaited network I/O. This is a direct passthrough of the duration captured at the top of theWorkflowSuspensioncatch block, so it can be reported even whenrsfsitself isn't (e.g. under redelivery, before the post-sent anchor is captured). Since RSFS-eligibility implies TTFS-eligibility,finalSchedulingReplaynever appears withoutttfsalso being present.Motivation: the Workflow Code Yellow dashboard decomposes TTFS into measurable parts, and the run_started→first-step stretch is currently the only unmeasured gap in that breakdown — the
workflow.runspan can't stand in for it since it mixes in full v4 replays.rsfscloses the sum;finalSchedulingReplayseparates "replay compute is slow" from "the step POST hop is slow."Naming note (per review): this field was originally named
firstReplay, which read as "the replay portion of RSFS." That's not quite right — valid RSFS paths can replay more than once before the first step (e.g. a workflow-bodysetAttributes()detour replays twice), and a redelivery omits earlier invocations' replay work entirely, so the measured value is only the last pass, never accumulated across passes. Renamed tofinalSchedulingReplayto make that scope explicit, and sharpened the doc comments at each measurement site accordingly rather than switching to accumulation.Changes
packages/core/src/runtime/step-latency.ts:computeStepLatencyTracking/computeStepLatencyEventDataextended to compute and attachrsfs/finalSchedulingReplay.packages/core/src/runtime.ts:runStartedReceivedAtMsanchor (turbo and non-turbo paths),replayDurationMscapture in theWorkflowSuspension.is(err)catch block.packages/core/src/runtime/step-executor.ts:stepStartPostSentAtMscapture immediately before thestep_startedcreate fires (both optimistic and non-optimistic paths); span attributes for the new fields.packages/core/src/telemetry/semantic-conventions.ts:StepRsfsMs/StepFinalSchedulingReplayMsconstants.packages/world/src/events.ts:rsfs/finalSchedulingReplayadded to the sharedstepLatencyTelemetryFieldsZod schema (spread into bothStepCompletedEventSchema/StepFailedEventSchema).packages/world-vercel/src/events.ts:rsfs/finalSchedulingReplayadded to the v4splitEventDataForV4()allowlist — new eventData fields are silently dropped on the v4 wire otherwise.packages/world-vercel/src/events-v4.ts:rsfs/finalSchedulingReplayadded toCreateEventV4Input/buildPostFrameMeta()..changeset/rsfs-replay-telemetry.md: minor bump for@workflow/core,@workflow/world,@workflow/world-vercel(feature addition, matching theminorprecedent set by the ttfs/stso changeset).Server-side PR (parses and emits
lifecycle.step.rsfs_ms/lifecycle.step.final_scheduling_replay_ms): vercel/workflow-server#626 — should land first; it ignores unknown fields, but the v4 allowlist needs to be live before v4 clients can send these.Tests
pnpm vitest run src/runtime/step-latency.test.ts src/runtime.test.ts(packages/core) — 58 passed.pnpm vitest run src/events.test.ts(packages/world-vercel) — 23 passed.pnpm typecheck(core/world/world-vercel, plus a full package build since the rename requires world/world-vercel'sdistto be current) — clean.pnpm biome checkscoped to the changed files — only pre-existingnoExcessiveCognitiveComplexitywarnings on functions touched (not introduced by this change; confirmed present on the pre-rename revision too), no fixes applied beyond formatting.🤖 Generated with Claude Code