From d3e268757b4fd942626593b753c967c85a202aae Mon Sep 17 00:00:00 2001 From: Peter Wielander Date: Tue, 14 Jul 2026 15:51:16 -0700 Subject: [PATCH 1/4] [core/world/world-vercel] Report RSFS/replay latency telemetry on step 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 --- .changeset/rsfs-replay-telemetry.md | 7 ++ packages/core/src/runtime.test.ts | 17 +++ packages/core/src/runtime.ts | 25 +++- packages/core/src/runtime/step-executor.ts | 25 +++- .../core/src/runtime/step-latency.test.ts | 117 ++++++++++++++++++ packages/core/src/runtime/step-latency.ts | 84 ++++++++++++- .../src/telemetry/semantic-conventions.ts | 17 +++ packages/world-vercel/src/events-v4.ts | 10 ++ packages/world-vercel/src/events.test.ts | 8 ++ packages/world-vercel/src/events.ts | 12 ++ packages/world/src/events.ts | 8 ++ 11 files changed, 321 insertions(+), 9 deletions(-) create mode 100644 .changeset/rsfs-replay-telemetry.md diff --git a/.changeset/rsfs-replay-telemetry.md b/.changeset/rsfs-replay-telemetry.md new file mode 100644 index 0000000000..1ef838ffc8 --- /dev/null +++ b/.changeset/rsfs-replay-telemetry.md @@ -0,0 +1,7 @@ +--- +'@workflow/core': minor +'@workflow/world': minor +'@workflow/world-vercel': minor +--- + +Report run-started-to-first-step (rsfs) and replay-compute (replay) latency telemetry on step completion events. diff --git a/packages/core/src/runtime.test.ts b/packages/core/src/runtime.test.ts index 6f46637ec4..5dc2f2dcb6 100644 --- a/packages/core/src/runtime.test.ts +++ b/packages/core/src/runtime.test.ts @@ -1908,6 +1908,14 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { 'optimisticStart', ]); + // RSFS/replay: under turbo, rsfsAnchorMs is stamped at local run + // synthesis (well after the backdated run-id timestamp), so unlike ttfs + // it stays within the test's own wall-clock budget. + expect(first.eventData.rsfs).toBeGreaterThanOrEqual(0); + expect(first.eventData.rsfs).toBeLessThanOrEqual(elapsed); + expect(first.eventData.replay).toBeGreaterThanOrEqual(0); + expect(first.eventData.replay).toBeLessThanOrEqual(elapsed); + // Second step ran back-to-back with the first: STSO only, and far // smaller than the TTFS anchor distance (it measures the scheduling // gap, not run age). @@ -1921,6 +1929,9 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { 'lazyStepStart', 'optimisticStart', ]); + // STSO-only steps never qualify for RSFS (it shares TTFS eligibility). + expect(second.eventData.rsfs).toBeUndefined(); + expect(second.eventData.replay).toBeUndefined(); }); it('still reports ttfs without turbo (redelivery), minus turbo-only optimization flags', async () => { @@ -1934,6 +1945,10 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { const [first] = stepCompleted; expect(first.eventData.ttfs).toBeGreaterThanOrEqual(backdateMs); expect(first.eventData.optimizations).toEqual(['lazyStepStart']); + // Non-turbo: rsfsAnchorMs is stamped right after the real (awaited) + // run_started response, so rsfs is a small non-negative duration too. + expect(first.eventData.rsfs).toBeGreaterThanOrEqual(0); + expect(first.eventData.replay).toBeGreaterThanOrEqual(0); }); it('reports nothing when the first step is scheduled alongside a wait', async () => { @@ -1944,6 +1959,8 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { expect(stepCompleted).toHaveLength(1); expect(stepCompleted[0].eventData.ttfs).toBeUndefined(); expect(stepCompleted[0].eventData.stso).toBeUndefined(); + expect(stepCompleted[0].eventData.rsfs).toBeUndefined(); + expect(stepCompleted[0].eventData.replay).toBeUndefined(); expect(stepCompleted[0].eventData.optimizations).toBeUndefined(); }); diff --git a/packages/core/src/runtime.ts b/packages/core/src/runtime.ts index ba04821f87..4ec220e3c6 100644 --- a/packages/core/src/runtime.ts +++ b/packages/core/src/runtime.ts @@ -554,6 +554,14 @@ export function workflowEntrypoint( // cannot be measured wall-clock, so TTFS is not reported. // Set once, on the first iteration's loaded snapshot. let invocationStartedClean: boolean | undefined; + // Epoch ms the `run_started` response was received/parsed + // by the SDK — anchors RSFS (run_started → first step's + // start POST). Set once, in the run_started setup below. + // Under turbo, run_started is backgrounded rather than + // awaited, so this is stamped at the point the run is + // synthesized locally instead of the real response — see + // StepLatencyTracking.rsfsAnchorMs. + let runStartedReceivedAtMs: number | undefined; // Wall-clock ms spent committing hook_created events before // the first step ran, accumulated across suspension passes // and subtracted from TTFS. @@ -964,6 +972,11 @@ export function workflowEntrypoint( updatedAt: now, }; workflowStartedAt = +now; + // See the `runStartedReceivedAtMs` declaration above: + // turbo synthesizes the run before the real + // `run_started` response lands, so anchor RSFS here + // rather than at an actual response instant. + runStartedReceivedAtMs = +now; span?.setAttributes({ ...Attribute.WorkflowRunStatus('running'), ...Attribute.WorkflowStartedAt(workflowStartedAt), @@ -982,6 +995,8 @@ export function workflowEntrypoint( ); } workflowRun = result.run; + // Anchors RSFS — see the declaration above. + runStartedReceivedAtMs = Date.now(); // If the response includes events, use them to skip // the initial events.list call and reduce TTFB. @@ -1434,10 +1449,16 @@ export function workflowEntrypoint( return; } catch (err) { if (WorkflowSuspension.is(err)) { + // Synchronous `runWorkflow` duration for THIS + // suspension — anchors the `replay` telemetry field + // below (see StepLatencyTracking.replayMs). Captured + // here, before `handleSuspension`'s awaited I/O, so + // it excludes that I/O. + const replayDurationMs = Date.now() - replayStart; runtimeLogger.debug('Workflow suspended', { workflowRunId: runId, loopIteration, - replayMs: Date.now() - replayStart, + replayMs: replayDurationMs, steps: err.stepCount, hooks: err.hookCount, waits: err.waitCount, @@ -1957,6 +1978,8 @@ export function workflowEntrypoint( runCreatedAtMs: runIdCreatedAt(runId) ?? (turbo ? undefined : +workflowRun.createdAt), + runStartedReceivedAtMs, + replayMs: replayDurationMs, preStepBlockingMs, preStepBlockingBeforeAttrMs, // This suspension's own hook/wait writes are not in diff --git a/packages/core/src/runtime/step-executor.ts b/packages/core/src/runtime/step-executor.ts index fe2404011d..16bcd004f1 100644 --- a/packages/core/src/runtime/step-executor.ts +++ b/packages/core/src/runtime/step-executor.ts @@ -393,6 +393,10 @@ export async function executeStep( !isOptimisticInlineStartExplicitlyDisabled())); let step: Step; + // `Date.now()` taken immediately before the `step_started` create is + // issued (either path below) — anchors RSFS's end point. See + // StepLatencyEventData.rsfs and the call sites below. + let stepStartPostSentAtMs: number | undefined; // Settled outcome of the in-flight optimistic `step_started`. Handlers are // attached synchronously (`.then(ok, err)`) so a fast rejection never // surfaces as an unhandledRejection while the body runs. @@ -423,8 +427,12 @@ export async function executeStep( // round-trip overlaps the body rather than blocking it. Outside turbo the // barrier is undefined and this is a plain create. const startedPromise = (params.runReadyBarrier ?? Promise.resolve()).then( - () => - world.events.create(workflowRunId, { + () => { + // Taken right before the create fires, not before the barrier — + // RSFS measures the run_started-to-POST stretch, and the barrier + // wait IS part of that stretch under turbo. + stepStartPostSentAtMs = Date.now(); + return world.events.create(workflowRunId, { eventType: 'step_started', specVersion: SPEC_VERSION_CURRENT, correlationId: stepId, @@ -437,7 +445,8 @@ export async function executeStep( ? { ownerMessageId: params.ownerMessageId } : {}), }, - }) + }); + } ); optimisticStartSettled = startedPromise.then( () => ({ ok: true as const }), @@ -474,6 +483,7 @@ export async function executeStep( params.ownerMessageId !== undefined ? { ownerMessageId: params.ownerMessageId } : {}; + stepStartPostSentAtMs = Date.now(); const startResult = await world.events.create(workflowRunId, { eventType: 'step_started', specVersion: SPEC_VERSION_CURRENT, @@ -656,10 +666,11 @@ export async function executeStep( attempt, lazyStepStart: params.lazyStepInput !== undefined, optimisticStart, + stepStartPostSentAtMs, }); if (latencyEventData) { // Mirror the latency telemetry onto the step span so traces show - // TTFS/STSO alongside the flame graph, not just Datadog metrics. + // TTFS/STSO/RSFS alongside the flame graph, not just Datadog metrics. span?.setAttributes({ ...(latencyEventData.ttfs !== undefined ? Attribute.StepTtfsMs(latencyEventData.ttfs) @@ -667,6 +678,12 @@ export async function executeStep( ...(latencyEventData.stso !== undefined ? Attribute.StepStsoMs(latencyEventData.stso) : {}), + ...(latencyEventData.rsfs !== undefined + ? Attribute.StepRsfsMs(latencyEventData.rsfs) + : {}), + ...(latencyEventData.replay !== undefined + ? Attribute.StepReplayMs(latencyEventData.replay) + : {}), ...Attribute.StepLatencyOptimizations( latencyEventData.optimizations ?? [] ), diff --git a/packages/core/src/runtime/step-latency.test.ts b/packages/core/src/runtime/step-latency.test.ts index ea5f30f3a6..d0ad85a075 100644 --- a/packages/core/src/runtime/step-latency.test.ts +++ b/packages/core/src/runtime/step-latency.test.ts @@ -29,6 +29,8 @@ function makeEvent( const BASE = { invocationStartedClean: true, runCreatedAtMs: 1_000, + runStartedReceivedAtMs: undefined as number | undefined, + replayMs: 0, preStepBlockingMs: 0, preStepBlockingBeforeAttrMs: undefined, suspensionHasWaits: false, @@ -180,6 +182,47 @@ describe('computeStepLatencyTracking', () => { expect(tracking).toBeUndefined(); }); + it('marks RSFS-eligible alongside TTFS when runStartedReceivedAtMs is recoverable', () => { + const tracking = computeStepLatencyTracking({ + ...BASE, + events: [makeEvent('run_created'), makeEvent('run_started')], + runStartedReceivedAtMs: 1_100, + replayMs: 25, + }); + expect(tracking).toEqual({ + ttfsAnchorMs: 1_000, + preStepBlockingMs: 0, + rsfsAnchorMs: 1_100, + replayMs: 25, + turbo: false, + }); + }); + + it('does not mark RSFS when runStartedReceivedAtMs is unrecoverable, even though TTFS qualifies', () => { + const tracking = computeStepLatencyTracking({ + ...BASE, + events: [makeEvent('run_created'), makeEvent('run_started')], + runStartedReceivedAtMs: undefined, + replayMs: 25, + }); + expect(tracking).toEqual({ + ttfsAnchorMs: 1_000, + preStepBlockingMs: 0, + turbo: false, + }); + }); + + it('does not mark RSFS when TTFS is disqualified, even though runStartedReceivedAtMs is recoverable', () => { + const tracking = computeStepLatencyTracking({ + ...BASE, + events: [makeEvent('run_started'), makeEvent('hook_received')], + runStartedReceivedAtMs: 1_100, + replayMs: 25, + }); + expect(tracking?.rsfsAnchorMs).toBeUndefined(); + expect(tracking?.replayMs).toBeUndefined(); + }); + it('marks STSO-eligible when the last event is a step terminal, preferring occurredAt', () => { const tracking = computeStepLatencyTracking({ ...BASE, @@ -260,6 +303,7 @@ describe('computeStepLatencyEventData', () => { const data = computeStepLatencyEventData({ tracking: { ttfsAnchorMs: 1_000, preStepBlockingMs: 200, turbo: true }, stepCodeStartedAtMs: 2_000, + stepStartPostSentAtMs: undefined, attempt: 1, lazyStepStart: true, optimisticStart: true, @@ -283,6 +327,7 @@ describe('computeStepLatencyEventData', () => { }, // Includes the setAttributes detour — must be excluded. stepCodeStartedAtMs: 60_000, + stepStartPostSentAtMs: undefined, attempt: 1, lazyStepStart: true, optimisticStart: false, @@ -299,6 +344,7 @@ describe('computeStepLatencyEventData', () => { turbo: false, }, stepCodeStartedAtMs: 2_000, + stepStartPostSentAtMs: undefined, attempt: 1, lazyStepStart: true, optimisticStart: false, @@ -322,6 +368,7 @@ describe('computeStepLatencyEventData', () => { turbo: false, }, stepCodeStartedAtMs: 4_000, + stepStartPostSentAtMs: undefined, attempt: 1, lazyStepStart: false, optimisticStart: false, @@ -339,6 +386,7 @@ describe('computeStepLatencyEventData', () => { const data = computeStepLatencyEventData({ tracking: { ttfsAnchorMs: 1_000, preStepBlockingMs: 0, turbo: false }, stepCodeStartedAtMs: 2_000, + stepStartPostSentAtMs: undefined, attempt: 2, lazyStepStart: false, optimisticStart: false, @@ -350,10 +398,79 @@ describe('computeStepLatencyEventData', () => { const data = computeStepLatencyEventData({ tracking: undefined, stepCodeStartedAtMs: 2_000, + stepStartPostSentAtMs: undefined, attempt: 1, lazyStepStart: true, optimisticStart: true, }); expect(data).toBeUndefined(); }); + + it('computes rsfs and replay alongside ttfs when the tracking and post-sent anchor are both present', () => { + const data = computeStepLatencyEventData({ + tracking: { + ttfsAnchorMs: 1_000, + preStepBlockingMs: 0, + rsfsAnchorMs: 1_200, + replayMs: 15, + turbo: false, + }, + stepCodeStartedAtMs: 2_000, + stepStartPostSentAtMs: 1_950, + attempt: 1, + lazyStepStart: true, + optimisticStart: false, + }); + expect(data).toEqual({ + ttfs: 1_000, + rsfs: 750, + replay: 15, + optimizations: ['lazyStepStart'], + }); + }); + + it('omits rsfs but still reports replay when the post-sent anchor is missing', () => { + const data = computeStepLatencyEventData({ + tracking: { + ttfsAnchorMs: 1_000, + preStepBlockingMs: 0, + rsfsAnchorMs: 1_200, + replayMs: 15, + turbo: false, + }, + stepCodeStartedAtMs: 2_000, + stepStartPostSentAtMs: undefined, + attempt: 1, + lazyStepStart: true, + optimisticStart: false, + }); + expect(data).toEqual({ + ttfs: 1_000, + replay: 15, + optimizations: ['lazyStepStart'], + }); + }); + + it('clamps a negative rsfs (cross-machine clock skew) to zero', () => { + const data = computeStepLatencyEventData({ + tracking: { + ttfsAnchorMs: 1_000, + preStepBlockingMs: 0, + rsfsAnchorMs: 5_000, + replayMs: 10, + turbo: false, + }, + stepCodeStartedAtMs: 2_000, + stepStartPostSentAtMs: 4_000, + attempt: 1, + lazyStepStart: true, + optimisticStart: false, + }); + expect(data).toEqual({ + ttfs: 1_000, + rsfs: 0, + replay: 10, + optimizations: ['lazyStepStart'], + }); + }); }); diff --git a/packages/core/src/runtime/step-latency.ts b/packages/core/src/runtime/step-latency.ts index c697a4f47b..5a9dca6c03 100644 --- a/packages/core/src/runtime/step-latency.ts +++ b/packages/core/src/runtime/step-latency.ts @@ -1,14 +1,19 @@ import type { Event } from '@workflow/world'; /** - * Client-side latency measurement (TTFS / STSO) threaded from the + * Client-side latency measurement (TTFS / STSO / RSFS) threaded from the * orchestrator's inline execution path into `executeStep`. * * TTFS (time-to-first-step) measures run creation → the first step's body * beginning to execute. STSO (step-to-step overhead) measures the previous - * step's terminal event → the next step's body beginning to execute. Both are - * attached to the step's terminal event so a backend can emit latency metrics - * from the event write alone, without extra event-log queries. + * step's terminal event → the next step's body beginning to execute. RSFS + * (run-started-to-first-step) measures the `run_started` response landing → + * the first step's start POST being issued — a sub-window of TTFS that + * isolates replay overhead from the run-creation queue hop; `replay` further + * splits out the synchronous workflow-function-execution portion of that + * window from awaited network I/O. All are attached to the step's terminal + * event so a backend can emit latency metrics from the event write alone, + * without extra event-log queries. * * Eligibility is decided by the orchestrator (which owns the event log) via * {@link computeStepLatencyTracking}; the final values are computed by @@ -50,6 +55,27 @@ export interface StepLatencyTracking { stepCount?: number; /** Number of events already in the event log. */ eventCount?: number; + /** + * Epoch ms the `run_started` response was received/parsed by the SDK. + * Present only when the step qualifies for RSFS — the same eligibility as + * TTFS (see {@link computeStepLatencyTracking}), plus a recoverable + * anchor. In turbo mode, `run_started` is backgrounded rather than + * awaited, so this is stamped at the point the runtime synthesizes the + * run locally and begins replay instead of at the real response; the + * first step's start POST is still chained on the real `run_started` + * promise (see step-executor.ts), so RSFS still ends up measuring the + * genuine run_started-to-first-step-POST stretch even though the two + * halves overlap under turbo. + */ + rsfsAnchorMs?: number; + /** + * Wall-clock ms this invocation's synchronous workflow-function replay + * took: from calling `runWorkflow` to it throwing the suspension that + * scheduled this batch. Excludes awaited network I/O (the suspension's + * event commits, the step's own start POST). Present only alongside + * `rsfsAnchorMs`. + */ + replayMs?: number; /** Whether turbo mode is active for this invocation. */ turbo: boolean; } @@ -60,6 +86,10 @@ export interface StepLatencyEventData { stso?: number; stepCount?: number; eventCount?: number; + /** Client-measured run_started → first step's start POST, ms. */ + rsfs?: number; + /** Client-measured synchronous replay-compute portion of `rsfs`, ms. */ + replay?: number; optimizations?: string[]; } @@ -117,6 +147,18 @@ export function computeStepLatencyTracking(params: { invocationStartedClean: boolean; /** Epoch ms of run creation, if recoverable. Absent disqualifies TTFS. */ runCreatedAtMs: number | undefined; + /** + * Epoch ms the `run_started` response was received/parsed by the SDK (or, + * under turbo, the instant the run was synthesized locally — see + * {@link StepLatencyTracking.rsfsAnchorMs}). Absent disqualifies RSFS. + */ + runStartedReceivedAtMs: number | undefined; + /** + * Wall-clock ms this suspension's `runWorkflow` call spent executing + * synchronously before throwing. See + * {@link StepLatencyTracking.replayMs}. + */ + replayMs: number; /** See {@link StepLatencyTracking.preStepBlockingMs}. */ preStepBlockingMs: number; /** @@ -199,6 +241,11 @@ export function computeStepLatencyTracking(params: { eventCount = events.length; } + // RSFS shares TTFS's eligibility exactly (same event-log/wait checks), + // plus its own anchor being recoverable. + const rsfsEligible = + ttfsEligible && params.runStartedReceivedAtMs !== undefined; + if (!ttfsEligible && prevStepEndMs === undefined) { return undefined; } @@ -216,6 +263,12 @@ export function computeStepLatencyTracking(params: { ...(preStepAttrStartMs !== undefined ? { preStepAttrStartMs } : {}), } : {}), + ...(rsfsEligible + ? { + rsfsAnchorMs: params.runStartedReceivedAtMs, + replayMs: params.replayMs, + } + : {}), ...(prevStepEndMs !== undefined ? { prevStepEndMs, stepCount, eventCount } : {}), @@ -234,6 +287,12 @@ export function computeStepLatencyEventData(params: { tracking: StepLatencyTracking | undefined; /** `Date.now()` taken immediately before user step code began executing. */ stepCodeStartedAtMs: number; + /** + * `Date.now()` taken immediately before the first step's start POST + * (`step_started`) was issued. Present only for the lazy inline steps RSFS + * cares about; see the call sites in step-executor.ts. + */ + stepStartPostSentAtMs: number | undefined; attempt: number; /** Whether this step was started lazily (no separate step_created write). */ lazyStepStart: boolean; @@ -267,6 +326,21 @@ export function computeStepLatencyEventData(params: { tracking.prevStepEndMs !== undefined ? Math.max(0, params.stepCodeStartedAtMs - tracking.prevStepEndMs) : undefined; + // RSFS ends at the actual start-POST instant, not at ttfsEndMs — unlike + // TTFS it is not subject to the pre-step attr-write shortcut, so a + // pre-step setAttributes detour (rare) makes RSFS include the detour + // while TTFS excludes it. `replay` is a direct passthrough: it is already + // the synchronous duration of the suspension that scheduled this step, so + // no further subtraction applies. + const rsfs = + tracking.rsfsAnchorMs !== undefined && + params.stepStartPostSentAtMs !== undefined + ? Math.max(0, params.stepStartPostSentAtMs - tracking.rsfsAnchorMs) + : undefined; + const replay = + tracking.replayMs !== undefined + ? Math.max(0, tracking.replayMs) + : undefined; if (ttfs === undefined && stso === undefined) { return undefined; @@ -286,6 +360,8 @@ export function computeStepLatencyEventData(params: { ...(stso !== undefined && tracking.eventCount !== undefined ? { eventCount: tracking.eventCount } : {}), + ...(rsfs !== undefined ? { rsfs } : {}), + ...(replay !== undefined ? { replay } : {}), optimizations, }; } diff --git a/packages/core/src/telemetry/semantic-conventions.ts b/packages/core/src/telemetry/semantic-conventions.ts index e8c53f9dbe..de01dcb1b1 100644 --- a/packages/core/src/telemetry/semantic-conventions.ts +++ b/packages/core/src/telemetry/semantic-conventions.ts @@ -212,6 +212,23 @@ export const StepTtfsMs = SemanticConvention('step.ttfs_ms'); */ export const StepStsoMs = SemanticConvention('step.stso_ms'); +/** + * Client-measured run_started-to-first-step latency in milliseconds: the + * `run_started` response landing (or, under turbo, the local run synthesis + * instant) → this step's start POST being issued. A sub-window of ttfs that + * isolates replay overhead from the run-creation queue hop. Only present on + * the run's first step execution when it qualified for measurement (see + * runtime/step-latency.ts). + */ +export const StepRsfsMs = SemanticConvention('step.rsfs_ms'); + +/** + * Client-measured synchronous workflow-function replay duration in + * milliseconds within the rsfs window, excluding awaited network I/O. Only + * present alongside step.rsfs_ms. + */ +export const StepReplayMs = SemanticConvention('step.replay_ms'); + /** * Runtime startup-latency optimizations active for the ttfs/stso measurement * (e.g. 'turbo', 'lazyStepStart', 'optimisticStart'). diff --git a/packages/world-vercel/src/events-v4.ts b/packages/world-vercel/src/events-v4.ts index e6df1d1152..68cc0c5412 100644 --- a/packages/world-vercel/src/events-v4.ts +++ b/packages/world-vercel/src/events-v4.ts @@ -162,6 +162,14 @@ export interface CreateEventV4Input { /** Progress counters taken when the STSO gap began. */ stepCount?: number; eventCount?: number; + /** Client-measured run_started-to-first-step ms (the `run_started` + * response landing → this step's start POST being issued), riding on the + * run's first step_completed / step_failed. Consumed server-side for + * latency metrics. */ + rsfs?: number; + /** Client-measured synchronous replay-compute ms within the rsfs window, + * excluding awaited network I/O. Only present alongside rsfs. */ + replay?: number; /** Runtime optimizations active for the ttfs/stso measurement * (e.g. 'turbo', 'lazyStepStart', 'optimisticStart'). */ optimizations?: string[]; @@ -253,6 +261,8 @@ function buildPostFrameMeta( if (input.stso !== undefined) meta.stso = input.stso; if (input.stepCount !== undefined) meta.stepCount = input.stepCount; if (input.eventCount !== undefined) meta.eventCount = input.eventCount; + if (input.rsfs !== undefined) meta.rsfs = input.rsfs; + if (input.replay !== undefined) meta.replay = input.replay; if (input.optimizations !== undefined) { meta.optimizations = input.optimizations; } diff --git a/packages/world-vercel/src/events.test.ts b/packages/world-vercel/src/events.test.ts index 73a0513939..6793b9a7f8 100644 --- a/packages/world-vercel/src/events.test.ts +++ b/packages/world-vercel/src/events.test.ts @@ -299,11 +299,15 @@ describe('splitEventDataForV4 attribute fields', () => { workflowName: 'wf', result: new TextEncoder().encode('"ok"'), ttfs: 123, + rsfs: 88, + replay: 12, optimizations: ['turbo', 'lazyStepStart'], }, } as AnyEventRequest); expect(completed.meta.ttfs).toBe(123); expect(completed.meta.stso).toBeUndefined(); + expect(completed.meta.rsfs).toBe(88); + expect(completed.meta.replay).toBe(12); expect(completed.meta.optimizations).toEqual(['turbo', 'lazyStepStart']); const failed = splitEventDataForV4({ @@ -334,12 +338,16 @@ describe('splitEventDataForV4 attribute fields', () => { stepName: 's', result: new TextEncoder().encode('"ok"'), ttfs: 'fast', + rsfs: 'fast', + replay: 'fast', stepCount: 0, eventCount: 2.5, optimizations: [1, 2], }, } as unknown as AnyEventRequest); expect(malformed.meta.ttfs).toBeUndefined(); + expect(malformed.meta.rsfs).toBeUndefined(); + expect(malformed.meta.replay).toBeUndefined(); expect(malformed.meta.stepCount).toBeUndefined(); expect(malformed.meta.eventCount).toBeUndefined(); expect(malformed.meta.optimizations).toBeUndefined(); diff --git a/packages/world-vercel/src/events.ts b/packages/world-vercel/src/events.ts index c17e7686d9..b9bd5864ae 100644 --- a/packages/world-vercel/src/events.ts +++ b/packages/world-vercel/src/events.ts @@ -147,6 +147,10 @@ interface SplitEventData { /** Progress counters taken when the STSO gap began. */ stepCount?: number; eventCount?: number; + /** Client-measured run_started-to-first-step ms (step_completed / step_failed). */ + rsfs?: number; + /** Client-measured synchronous replay-compute ms within the rsfs window. */ + replay?: number; /** Runtime optimizations active for the ttfs/stso measurement. */ optimizations?: string[]; }; @@ -183,6 +187,8 @@ type MetaSourceField = | 'stso' | 'stepCount' | 'eventCount' + | 'rsfs' + | 'replay' | 'optimizations'; /** @@ -349,6 +355,12 @@ export function splitEventDataForV4(data: AnyEventRequest): SplitEventData { ) { meta.eventCount = eventData.eventCount; } + if (typeof eventData.rsfs === 'number') { + meta.rsfs = eventData.rsfs; + } + if (typeof eventData.replay === 'number') { + meta.replay = eventData.replay; + } if ( Array.isArray(eventData.optimizations) && eventData.optimizations.every((o) => typeof o === 'string') diff --git a/packages/world/src/events.ts b/packages/world/src/events.ts index 676032dfae..423e604593 100644 --- a/packages/world/src/events.ts +++ b/packages/world/src/events.ts @@ -268,6 +268,14 @@ const stepLatencyTelemetryFields = { // stso. stepCount: z.number().int().positive().optional(), eventCount: z.number().int().positive().optional(), + // Run-started-to-first-step: milliseconds from the `run_started` response + // landing (or, under turbo, the local run synthesis instant) until this + // step's start POST was issued. A sub-window of ttfs. Only reported + // alongside the same eligibility as ttfs. + rsfs: z.number().optional(), + // Synchronous workflow-function replay duration within the rsfs window, + // excluding awaited network I/O. Only present alongside rsfs. + replay: z.number().optional(), // Names of the runtime's optional startup-latency optimizations that were // active for this measurement (e.g. 'turbo', 'lazyStepStart', // 'optimisticStart'), so latency metrics can be segmented by them. From 2d5af951efe3fb41e924d9966376bb2e31467693 Mon Sep 17 00:00:00 2001 From: Peter Wielander Date: Wed, 15 Jul 2026 12:21:43 -0700 Subject: [PATCH 2/4] refactor(core,world,world-vercel): rename replay latency field to firstReplay 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 --- .changeset/rsfs-replay-telemetry.md | 2 +- packages/core/src/runtime.test.ts | 12 +++++----- packages/core/src/runtime.ts | 16 +++++++++---- packages/core/src/runtime/step-executor.ts | 4 ++-- .../core/src/runtime/step-latency.test.ts | 10 ++++---- packages/core/src/runtime/step-latency.ts | 24 ++++++++++++------- .../src/telemetry/semantic-conventions.ts | 7 ++++-- packages/world-vercel/src/events-v4.ts | 7 +++--- packages/world-vercel/src/events.test.ts | 8 +++---- packages/world-vercel/src/events.ts | 8 +++---- packages/world/src/events.ts | 5 ++-- 11 files changed, 61 insertions(+), 42 deletions(-) diff --git a/.changeset/rsfs-replay-telemetry.md b/.changeset/rsfs-replay-telemetry.md index 1ef838ffc8..9162a2bfda 100644 --- a/.changeset/rsfs-replay-telemetry.md +++ b/.changeset/rsfs-replay-telemetry.md @@ -4,4 +4,4 @@ '@workflow/world-vercel': minor --- -Report run-started-to-first-step (rsfs) and replay-compute (replay) latency telemetry on step completion events. +Report run-started-to-first-step (rsfs) and first-step replay-compute (firstReplay) latency telemetry on step completion events. diff --git a/packages/core/src/runtime.test.ts b/packages/core/src/runtime.test.ts index 5dc2f2dcb6..bb5fcc65f4 100644 --- a/packages/core/src/runtime.test.ts +++ b/packages/core/src/runtime.test.ts @@ -1908,13 +1908,13 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { 'optimisticStart', ]); - // RSFS/replay: under turbo, rsfsAnchorMs is stamped at local run + // RSFS/firstReplay: under turbo, rsfsAnchorMs is stamped at local run // synthesis (well after the backdated run-id timestamp), so unlike ttfs // it stays within the test's own wall-clock budget. expect(first.eventData.rsfs).toBeGreaterThanOrEqual(0); expect(first.eventData.rsfs).toBeLessThanOrEqual(elapsed); - expect(first.eventData.replay).toBeGreaterThanOrEqual(0); - expect(first.eventData.replay).toBeLessThanOrEqual(elapsed); + expect(first.eventData.firstReplay).toBeGreaterThanOrEqual(0); + expect(first.eventData.firstReplay).toBeLessThanOrEqual(elapsed); // Second step ran back-to-back with the first: STSO only, and far // smaller than the TTFS anchor distance (it measures the scheduling @@ -1931,7 +1931,7 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { ]); // STSO-only steps never qualify for RSFS (it shares TTFS eligibility). expect(second.eventData.rsfs).toBeUndefined(); - expect(second.eventData.replay).toBeUndefined(); + expect(second.eventData.firstReplay).toBeUndefined(); }); it('still reports ttfs without turbo (redelivery), minus turbo-only optimization flags', async () => { @@ -1948,7 +1948,7 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { // Non-turbo: rsfsAnchorMs is stamped right after the real (awaited) // run_started response, so rsfs is a small non-negative duration too. expect(first.eventData.rsfs).toBeGreaterThanOrEqual(0); - expect(first.eventData.replay).toBeGreaterThanOrEqual(0); + expect(first.eventData.firstReplay).toBeGreaterThanOrEqual(0); }); it('reports nothing when the first step is scheduled alongside a wait', async () => { @@ -1960,7 +1960,7 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { expect(stepCompleted[0].eventData.ttfs).toBeUndefined(); expect(stepCompleted[0].eventData.stso).toBeUndefined(); expect(stepCompleted[0].eventData.rsfs).toBeUndefined(); - expect(stepCompleted[0].eventData.replay).toBeUndefined(); + expect(stepCompleted[0].eventData.firstReplay).toBeUndefined(); expect(stepCompleted[0].eventData.optimizations).toBeUndefined(); }); diff --git a/packages/core/src/runtime.ts b/packages/core/src/runtime.ts index 4ec220e3c6..e25a099691 100644 --- a/packages/core/src/runtime.ts +++ b/packages/core/src/runtime.ts @@ -1450,10 +1450,18 @@ export function workflowEntrypoint( } catch (err) { if (WorkflowSuspension.is(err)) { // Synchronous `runWorkflow` duration for THIS - // suspension — anchors the `replay` telemetry field - // below (see StepLatencyTracking.replayMs). Captured - // here, before `handleSuspension`'s awaited I/O, so - // it excludes that I/O. + // suspension — anchors the `firstReplay` telemetry + // field below (see StepLatencyTracking.replayMs). + // Captured here, before `handleSuspension`'s awaited + // I/O, so it excludes that I/O. + // + // This duplicates what OTEL already captures on the + // run/invocation span, but is collected as client + // telemetry so the server can emit it as an + // UNSAMPLED metric: workflow-server's server spans + // are heavily sampled in production (~7%), so + // span-derived percentiles are biased and can't + // serve as the dashboard's exact TTFS decomposition. const replayDurationMs = Date.now() - replayStart; runtimeLogger.debug('Workflow suspended', { workflowRunId: runId, diff --git a/packages/core/src/runtime/step-executor.ts b/packages/core/src/runtime/step-executor.ts index 16bcd004f1..4876201f54 100644 --- a/packages/core/src/runtime/step-executor.ts +++ b/packages/core/src/runtime/step-executor.ts @@ -681,8 +681,8 @@ export async function executeStep( ...(latencyEventData.rsfs !== undefined ? Attribute.StepRsfsMs(latencyEventData.rsfs) : {}), - ...(latencyEventData.replay !== undefined - ? Attribute.StepReplayMs(latencyEventData.replay) + ...(latencyEventData.firstReplay !== undefined + ? Attribute.StepFirstReplayMs(latencyEventData.firstReplay) : {}), ...Attribute.StepLatencyOptimizations( latencyEventData.optimizations ?? [] diff --git a/packages/core/src/runtime/step-latency.test.ts b/packages/core/src/runtime/step-latency.test.ts index d0ad85a075..37635021d9 100644 --- a/packages/core/src/runtime/step-latency.test.ts +++ b/packages/core/src/runtime/step-latency.test.ts @@ -406,7 +406,7 @@ describe('computeStepLatencyEventData', () => { expect(data).toBeUndefined(); }); - it('computes rsfs and replay alongside ttfs when the tracking and post-sent anchor are both present', () => { + it('computes rsfs and firstReplay alongside ttfs when the tracking and post-sent anchor are both present', () => { const data = computeStepLatencyEventData({ tracking: { ttfsAnchorMs: 1_000, @@ -424,12 +424,12 @@ describe('computeStepLatencyEventData', () => { expect(data).toEqual({ ttfs: 1_000, rsfs: 750, - replay: 15, + firstReplay: 15, optimizations: ['lazyStepStart'], }); }); - it('omits rsfs but still reports replay when the post-sent anchor is missing', () => { + it('omits rsfs but still reports firstReplay when the post-sent anchor is missing', () => { const data = computeStepLatencyEventData({ tracking: { ttfsAnchorMs: 1_000, @@ -446,7 +446,7 @@ describe('computeStepLatencyEventData', () => { }); expect(data).toEqual({ ttfs: 1_000, - replay: 15, + firstReplay: 15, optimizations: ['lazyStepStart'], }); }); @@ -469,7 +469,7 @@ describe('computeStepLatencyEventData', () => { expect(data).toEqual({ ttfs: 1_000, rsfs: 0, - replay: 10, + firstReplay: 10, optimizations: ['lazyStepStart'], }); }); diff --git a/packages/core/src/runtime/step-latency.ts b/packages/core/src/runtime/step-latency.ts index 5a9dca6c03..745694dc19 100644 --- a/packages/core/src/runtime/step-latency.ts +++ b/packages/core/src/runtime/step-latency.ts @@ -9,9 +9,9 @@ import type { Event } from '@workflow/world'; * step's terminal event → the next step's body beginning to execute. RSFS * (run-started-to-first-step) measures the `run_started` response landing → * the first step's start POST being issued — a sub-window of TTFS that - * isolates replay overhead from the run-creation queue hop; `replay` further - * splits out the synchronous workflow-function-execution portion of that - * window from awaited network I/O. All are attached to the step's terminal + * isolates replay overhead from the run-creation queue hop; `firstReplay` + * further splits out the synchronous workflow-function-execution portion of + * that window from awaited network I/O. All are attached to the step's terminal * event so a backend can emit latency metrics from the event write alone, * without extra event-log queries. * @@ -89,7 +89,7 @@ export interface StepLatencyEventData { /** Client-measured run_started → first step's start POST, ms. */ rsfs?: number; /** Client-measured synchronous replay-compute portion of `rsfs`, ms. */ - replay?: number; + firstReplay?: number; optimizations?: string[]; } @@ -329,15 +329,21 @@ export function computeStepLatencyEventData(params: { // RSFS ends at the actual start-POST instant, not at ttfsEndMs — unlike // TTFS it is not subject to the pre-step attr-write shortcut, so a // pre-step setAttributes detour (rare) makes RSFS include the detour - // while TTFS excludes it. `replay` is a direct passthrough: it is already - // the synchronous duration of the suspension that scheduled this step, so - // no further subtraction applies. + // while TTFS excludes it. `firstReplay` is a direct passthrough: it is + // already the synchronous duration of the suspension that scheduled this + // step, so no further subtraction applies. + // + // 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: workflow-server's server spans are + // heavily sampled in production (~7%), so span-derived percentiles are + // biased and can't serve as the dashboard's exact TTFS decomposition. const rsfs = tracking.rsfsAnchorMs !== undefined && params.stepStartPostSentAtMs !== undefined ? Math.max(0, params.stepStartPostSentAtMs - tracking.rsfsAnchorMs) : undefined; - const replay = + const firstReplay = tracking.replayMs !== undefined ? Math.max(0, tracking.replayMs) : undefined; @@ -361,7 +367,7 @@ export function computeStepLatencyEventData(params: { ? { eventCount: tracking.eventCount } : {}), ...(rsfs !== undefined ? { rsfs } : {}), - ...(replay !== undefined ? { replay } : {}), + ...(firstReplay !== undefined ? { firstReplay } : {}), optimizations, }; } diff --git a/packages/core/src/telemetry/semantic-conventions.ts b/packages/core/src/telemetry/semantic-conventions.ts index de01dcb1b1..5947ecdb27 100644 --- a/packages/core/src/telemetry/semantic-conventions.ts +++ b/packages/core/src/telemetry/semantic-conventions.ts @@ -225,9 +225,12 @@ export const StepRsfsMs = SemanticConvention('step.rsfs_ms'); /** * Client-measured synchronous workflow-function replay duration in * milliseconds within the rsfs window, excluding awaited network I/O. Only - * present alongside step.rsfs_ms. + * present alongside step.rsfs_ms and only for the run's first step + * (see runtime/step-latency.ts) — hence "first" in the name. */ -export const StepReplayMs = SemanticConvention('step.replay_ms'); +export const StepFirstReplayMs = SemanticConvention( + 'step.first_replay_ms' +); /** * Runtime startup-latency optimizations active for the ttfs/stso measurement diff --git a/packages/world-vercel/src/events-v4.ts b/packages/world-vercel/src/events-v4.ts index 68cc0c5412..7f87351ef9 100644 --- a/packages/world-vercel/src/events-v4.ts +++ b/packages/world-vercel/src/events-v4.ts @@ -168,8 +168,9 @@ export interface CreateEventV4Input { * latency metrics. */ rsfs?: number; /** Client-measured synchronous replay-compute ms within the rsfs window, - * excluding awaited network I/O. Only present alongside rsfs. */ - replay?: number; + * excluding awaited network I/O. Only present alongside rsfs, and only + * for the run's first step. */ + firstReplay?: number; /** Runtime optimizations active for the ttfs/stso measurement * (e.g. 'turbo', 'lazyStepStart', 'optimisticStart'). */ optimizations?: string[]; @@ -262,7 +263,7 @@ function buildPostFrameMeta( if (input.stepCount !== undefined) meta.stepCount = input.stepCount; if (input.eventCount !== undefined) meta.eventCount = input.eventCount; if (input.rsfs !== undefined) meta.rsfs = input.rsfs; - if (input.replay !== undefined) meta.replay = input.replay; + if (input.firstReplay !== undefined) meta.firstReplay = input.firstReplay; if (input.optimizations !== undefined) { meta.optimizations = input.optimizations; } diff --git a/packages/world-vercel/src/events.test.ts b/packages/world-vercel/src/events.test.ts index 6793b9a7f8..ff5fc2e79e 100644 --- a/packages/world-vercel/src/events.test.ts +++ b/packages/world-vercel/src/events.test.ts @@ -300,14 +300,14 @@ describe('splitEventDataForV4 attribute fields', () => { result: new TextEncoder().encode('"ok"'), ttfs: 123, rsfs: 88, - replay: 12, + firstReplay: 12, optimizations: ['turbo', 'lazyStepStart'], }, } as AnyEventRequest); expect(completed.meta.ttfs).toBe(123); expect(completed.meta.stso).toBeUndefined(); expect(completed.meta.rsfs).toBe(88); - expect(completed.meta.replay).toBe(12); + expect(completed.meta.firstReplay).toBe(12); expect(completed.meta.optimizations).toEqual(['turbo', 'lazyStepStart']); const failed = splitEventDataForV4({ @@ -339,7 +339,7 @@ describe('splitEventDataForV4 attribute fields', () => { result: new TextEncoder().encode('"ok"'), ttfs: 'fast', rsfs: 'fast', - replay: 'fast', + firstReplay: 'fast', stepCount: 0, eventCount: 2.5, optimizations: [1, 2], @@ -347,7 +347,7 @@ describe('splitEventDataForV4 attribute fields', () => { } as unknown as AnyEventRequest); expect(malformed.meta.ttfs).toBeUndefined(); expect(malformed.meta.rsfs).toBeUndefined(); - expect(malformed.meta.replay).toBeUndefined(); + expect(malformed.meta.firstReplay).toBeUndefined(); expect(malformed.meta.stepCount).toBeUndefined(); expect(malformed.meta.eventCount).toBeUndefined(); expect(malformed.meta.optimizations).toBeUndefined(); diff --git a/packages/world-vercel/src/events.ts b/packages/world-vercel/src/events.ts index b9bd5864ae..d62551d722 100644 --- a/packages/world-vercel/src/events.ts +++ b/packages/world-vercel/src/events.ts @@ -150,7 +150,7 @@ interface SplitEventData { /** Client-measured run_started-to-first-step ms (step_completed / step_failed). */ rsfs?: number; /** Client-measured synchronous replay-compute ms within the rsfs window. */ - replay?: number; + firstReplay?: number; /** Runtime optimizations active for the ttfs/stso measurement. */ optimizations?: string[]; }; @@ -188,7 +188,7 @@ type MetaSourceField = | 'stepCount' | 'eventCount' | 'rsfs' - | 'replay' + | 'firstReplay' | 'optimizations'; /** @@ -358,8 +358,8 @@ export function splitEventDataForV4(data: AnyEventRequest): SplitEventData { if (typeof eventData.rsfs === 'number') { meta.rsfs = eventData.rsfs; } - if (typeof eventData.replay === 'number') { - meta.replay = eventData.replay; + if (typeof eventData.firstReplay === 'number') { + meta.firstReplay = eventData.firstReplay; } if ( Array.isArray(eventData.optimizations) && diff --git a/packages/world/src/events.ts b/packages/world/src/events.ts index 423e604593..8190999164 100644 --- a/packages/world/src/events.ts +++ b/packages/world/src/events.ts @@ -274,8 +274,9 @@ const stepLatencyTelemetryFields = { // alongside the same eligibility as ttfs. rsfs: z.number().optional(), // Synchronous workflow-function replay duration within the rsfs window, - // excluding awaited network I/O. Only present alongside rsfs. - replay: z.number().optional(), + // excluding awaited network I/O. Only present alongside rsfs, and only for + // the run's first step — hence "first" in the name. + firstReplay: z.number().optional(), // Names of the runtime's optional startup-latency optimizations that were // active for this measurement (e.g. 'turbo', 'lazyStepStart', // 'optimisticStart'), so latency metrics can be segmented by them. From 187510b6a5ce97223a2a09dabaef754864a29d9c Mon Sep 17 00:00:00 2001 From: Peter Wielander Date: Wed, 15 Jul 2026 13:12:49 -0700 Subject: [PATCH 3/4] Narrow firstReplay to finalSchedulingReplay per review feedback The field only reports the final runWorkflow() replay pass that scheduled the first step, not an accumulation across earlier pre-first-step passes (e.g. setAttributes() detours, or work omitted by a redelivery), so it cannot be read as "the replay portion of rsfs". Rename to make that scope explicit and sharpen the doc comments at each measurement site. Co-Authored-By: Claude Fable 5 --- .changeset/rsfs-replay-telemetry.md | 2 +- packages/core/src/runtime.test.ts | 12 ++--- packages/core/src/runtime.ts | 24 ++++++--- packages/core/src/runtime/step-executor.ts | 6 ++- .../core/src/runtime/step-latency.test.ts | 10 ++-- packages/core/src/runtime/step-latency.ts | 52 +++++++++++++------ .../src/telemetry/semantic-conventions.ts | 15 ++++-- packages/world-vercel/src/events-v4.ts | 14 +++-- packages/world-vercel/src/events.test.ts | 8 +-- packages/world-vercel/src/events.ts | 12 +++-- packages/world/src/events.ts | 10 ++-- 11 files changed, 107 insertions(+), 58 deletions(-) diff --git a/.changeset/rsfs-replay-telemetry.md b/.changeset/rsfs-replay-telemetry.md index 9162a2bfda..c69ce28351 100644 --- a/.changeset/rsfs-replay-telemetry.md +++ b/.changeset/rsfs-replay-telemetry.md @@ -4,4 +4,4 @@ '@workflow/world-vercel': minor --- -Report run-started-to-first-step (rsfs) and first-step replay-compute (firstReplay) latency telemetry on step completion events. +Report run-started-to-first-step (rsfs) and final-scheduling-replay (finalSchedulingReplay) latency telemetry on step completion events. diff --git a/packages/core/src/runtime.test.ts b/packages/core/src/runtime.test.ts index bb5fcc65f4..6837b076f5 100644 --- a/packages/core/src/runtime.test.ts +++ b/packages/core/src/runtime.test.ts @@ -1908,13 +1908,13 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { 'optimisticStart', ]); - // RSFS/firstReplay: under turbo, rsfsAnchorMs is stamped at local run + // RSFS/finalSchedulingReplay: under turbo, rsfsAnchorMs is stamped at local run // synthesis (well after the backdated run-id timestamp), so unlike ttfs // it stays within the test's own wall-clock budget. expect(first.eventData.rsfs).toBeGreaterThanOrEqual(0); expect(first.eventData.rsfs).toBeLessThanOrEqual(elapsed); - expect(first.eventData.firstReplay).toBeGreaterThanOrEqual(0); - expect(first.eventData.firstReplay).toBeLessThanOrEqual(elapsed); + expect(first.eventData.finalSchedulingReplay).toBeGreaterThanOrEqual(0); + expect(first.eventData.finalSchedulingReplay).toBeLessThanOrEqual(elapsed); // Second step ran back-to-back with the first: STSO only, and far // smaller than the TTFS anchor distance (it measures the scheduling @@ -1931,7 +1931,7 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { ]); // STSO-only steps never qualify for RSFS (it shares TTFS eligibility). expect(second.eventData.rsfs).toBeUndefined(); - expect(second.eventData.firstReplay).toBeUndefined(); + expect(second.eventData.finalSchedulingReplay).toBeUndefined(); }); it('still reports ttfs without turbo (redelivery), minus turbo-only optimization flags', async () => { @@ -1948,7 +1948,7 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { // Non-turbo: rsfsAnchorMs is stamped right after the real (awaited) // run_started response, so rsfs is a small non-negative duration too. expect(first.eventData.rsfs).toBeGreaterThanOrEqual(0); - expect(first.eventData.firstReplay).toBeGreaterThanOrEqual(0); + expect(first.eventData.finalSchedulingReplay).toBeGreaterThanOrEqual(0); }); it('reports nothing when the first step is scheduled alongside a wait', async () => { @@ -1960,7 +1960,7 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => { expect(stepCompleted[0].eventData.ttfs).toBeUndefined(); expect(stepCompleted[0].eventData.stso).toBeUndefined(); expect(stepCompleted[0].eventData.rsfs).toBeUndefined(); - expect(stepCompleted[0].eventData.firstReplay).toBeUndefined(); + expect(stepCompleted[0].eventData.finalSchedulingReplay).toBeUndefined(); expect(stepCompleted[0].eventData.optimizations).toBeUndefined(); }); diff --git a/packages/core/src/runtime.ts b/packages/core/src/runtime.ts index e25a099691..d11ee4a8b2 100644 --- a/packages/core/src/runtime.ts +++ b/packages/core/src/runtime.ts @@ -1450,18 +1450,30 @@ export function workflowEntrypoint( } catch (err) { if (WorkflowSuspension.is(err)) { // Synchronous `runWorkflow` duration for THIS - // suspension — anchors the `firstReplay` telemetry - // field below (see StepLatencyTracking.replayMs). + // suspension only — anchors the `finalSchedulingReplay` + // telemetry field below (see + // StepLatencyTracking.replayMs). This is the FINAL + // replay pass, the one that reached and scheduled the + // first step: valid rsfs paths can replay more than + // once before the first step (e.g. a workflow-body + // `setAttributes()` detour replays twice), and a + // redelivery omits earlier invocations' replay work + // entirely. This value is NOT accumulated across + // those earlier passes, so it must not be read as + // "the replay portion of rsfs" — rsfs covers the + // whole run_started-to-first-step window; + // finalSchedulingReplay covers only this last pass. // Captured here, before `handleSuspension`'s awaited // I/O, so it excludes that I/O. // // This duplicates what OTEL already captures on the // run/invocation span, but is collected as client // telemetry so the server can emit it as an - // UNSAMPLED metric: workflow-server's server spans - // are heavily sampled in production (~7%), so - // span-derived percentiles are biased and can't - // serve as the dashboard's exact TTFS decomposition. + // UNSAMPLED, full-population metric: workflow-server's + // server spans are heavily sampled in production + // (~7%), and client spans can't be filtered by SDK + // version, so neither can serve as the dashboard's + // exact TTFS decomposition. const replayDurationMs = Date.now() - replayStart; runtimeLogger.debug('Workflow suspended', { workflowRunId: runId, diff --git a/packages/core/src/runtime/step-executor.ts b/packages/core/src/runtime/step-executor.ts index 4876201f54..48bc409195 100644 --- a/packages/core/src/runtime/step-executor.ts +++ b/packages/core/src/runtime/step-executor.ts @@ -681,8 +681,10 @@ export async function executeStep( ...(latencyEventData.rsfs !== undefined ? Attribute.StepRsfsMs(latencyEventData.rsfs) : {}), - ...(latencyEventData.firstReplay !== undefined - ? Attribute.StepFirstReplayMs(latencyEventData.firstReplay) + ...(latencyEventData.finalSchedulingReplay !== undefined + ? Attribute.StepFinalSchedulingReplayMs( + latencyEventData.finalSchedulingReplay + ) : {}), ...Attribute.StepLatencyOptimizations( latencyEventData.optimizations ?? [] diff --git a/packages/core/src/runtime/step-latency.test.ts b/packages/core/src/runtime/step-latency.test.ts index 37635021d9..b21c103883 100644 --- a/packages/core/src/runtime/step-latency.test.ts +++ b/packages/core/src/runtime/step-latency.test.ts @@ -406,7 +406,7 @@ describe('computeStepLatencyEventData', () => { expect(data).toBeUndefined(); }); - it('computes rsfs and firstReplay alongside ttfs when the tracking and post-sent anchor are both present', () => { + it('computes rsfs and finalSchedulingReplay alongside ttfs when the tracking and post-sent anchor are both present', () => { const data = computeStepLatencyEventData({ tracking: { ttfsAnchorMs: 1_000, @@ -424,12 +424,12 @@ describe('computeStepLatencyEventData', () => { expect(data).toEqual({ ttfs: 1_000, rsfs: 750, - firstReplay: 15, + finalSchedulingReplay: 15, optimizations: ['lazyStepStart'], }); }); - it('omits rsfs but still reports firstReplay when the post-sent anchor is missing', () => { + it('omits rsfs but still reports finalSchedulingReplay when the post-sent anchor is missing', () => { const data = computeStepLatencyEventData({ tracking: { ttfsAnchorMs: 1_000, @@ -446,7 +446,7 @@ describe('computeStepLatencyEventData', () => { }); expect(data).toEqual({ ttfs: 1_000, - firstReplay: 15, + finalSchedulingReplay: 15, optimizations: ['lazyStepStart'], }); }); @@ -469,7 +469,7 @@ describe('computeStepLatencyEventData', () => { expect(data).toEqual({ ttfs: 1_000, rsfs: 0, - firstReplay: 10, + finalSchedulingReplay: 10, optimizations: ['lazyStepStart'], }); }); diff --git a/packages/core/src/runtime/step-latency.ts b/packages/core/src/runtime/step-latency.ts index 745694dc19..b0cb3af5c9 100644 --- a/packages/core/src/runtime/step-latency.ts +++ b/packages/core/src/runtime/step-latency.ts @@ -9,9 +9,12 @@ import type { Event } from '@workflow/world'; * step's terminal event → the next step's body beginning to execute. RSFS * (run-started-to-first-step) measures the `run_started` response landing → * the first step's start POST being issued — a sub-window of TTFS that - * isolates replay overhead from the run-creation queue hop; `firstReplay` - * further splits out the synchronous workflow-function-execution portion of - * that window from awaited network I/O. All are attached to the step's terminal + * isolates replay overhead from the run-creation queue hop; `finalSchedulingReplay` + * is the synchronous workflow-function-execution duration of only the FINAL + * replay pass within that window (the pass that reached and scheduled the + * first step) — it is NOT accumulated across earlier pre-first-step passes + * (see {@link StepLatencyTracking.replayMs}), so it must not be read as "the + * replay portion of RSFS". All are attached to the step's terminal * event so a backend can emit latency metrics from the event write alone, * without extra event-log queries. * @@ -74,6 +77,15 @@ export interface StepLatencyTracking { * scheduled this batch. Excludes awaited network I/O (the suspension's * event commits, the step's own start POST). Present only alongside * `rsfsAnchorMs`. + * + * This is the FINAL replay pass only — the invocation that reached and + * scheduled the first step. Valid RSFS paths can replay more than once + * before the first step (e.g. a workflow-body `setAttributes()` detour + * replays twice), and a redelivery omits earlier invocations' replay work + * entirely; this value is not accumulated across those earlier passes. + * Do not read it as "the replay portion of RSFS" — RSFS + * ({@link rsfsAnchorMs}) covers the whole run_started-to-first-step + * window, this covers only the last pass. */ replayMs?: number; /** Whether turbo mode is active for this invocation. */ @@ -88,8 +100,13 @@ export interface StepLatencyEventData { eventCount?: number; /** Client-measured run_started → first step's start POST, ms. */ rsfs?: number; - /** Client-measured synchronous replay-compute portion of `rsfs`, ms. */ - firstReplay?: number; + /** + * Client-measured wall-clock ms of the FINAL replay pass that scheduled + * the first step (see {@link StepLatencyTracking.replayMs}) — not + * accumulated across earlier pre-first-step passes, so it must not be + * read as "the replay portion of `rsfs`". + */ + finalSchedulingReplay?: number; optimizations?: string[]; } @@ -155,7 +172,8 @@ export function computeStepLatencyTracking(params: { runStartedReceivedAtMs: number | undefined; /** * Wall-clock ms this suspension's `runWorkflow` call spent executing - * synchronously before throwing. See + * synchronously before throwing — the FINAL replay pass only, not + * accumulated across earlier passes. See * {@link StepLatencyTracking.replayMs}. */ replayMs: number; @@ -329,21 +347,25 @@ export function computeStepLatencyEventData(params: { // RSFS ends at the actual start-POST instant, not at ttfsEndMs — unlike // TTFS it is not subject to the pre-step attr-write shortcut, so a // pre-step setAttributes detour (rare) makes RSFS include the detour - // while TTFS excludes it. `firstReplay` is a direct passthrough: it is - // already the synchronous duration of the suspension that scheduled this - // step, so no further subtraction applies. + // while TTFS excludes it. `finalSchedulingReplay` is a direct passthrough + // of `tracking.replayMs` — the FINAL replay pass only (see + // StepLatencyTracking.replayMs) — so no further subtraction applies, but + // it also means it is NOT accumulated across any earlier pre-first-step + // passes (e.g. a setAttributes detour) and must not be read as "the + // replay portion of rsfs"; rsfs covers the whole window. // - // firstReplay duplicates what OTEL already captures on the run/invocation + // finalSchedulingReplay 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: workflow-server's server spans are - // heavily sampled in production (~7%), so span-derived percentiles are - // biased and can't serve as the dashboard's exact TTFS decomposition. + // can emit it as an UNSAMPLED, full-population metric: workflow-server's + // server spans are heavily sampled in production (~7%), and client spans + // can't be filtered by SDK version, so neither can serve as the + // dashboard's exact TTFS decomposition. const rsfs = tracking.rsfsAnchorMs !== undefined && params.stepStartPostSentAtMs !== undefined ? Math.max(0, params.stepStartPostSentAtMs - tracking.rsfsAnchorMs) : undefined; - const firstReplay = + const finalSchedulingReplay = tracking.replayMs !== undefined ? Math.max(0, tracking.replayMs) : undefined; @@ -367,7 +389,7 @@ export function computeStepLatencyEventData(params: { ? { eventCount: tracking.eventCount } : {}), ...(rsfs !== undefined ? { rsfs } : {}), - ...(firstReplay !== undefined ? { firstReplay } : {}), + ...(finalSchedulingReplay !== undefined ? { finalSchedulingReplay } : {}), optimizations, }; } diff --git a/packages/core/src/telemetry/semantic-conventions.ts b/packages/core/src/telemetry/semantic-conventions.ts index 5947ecdb27..bcc6d1dabf 100644 --- a/packages/core/src/telemetry/semantic-conventions.ts +++ b/packages/core/src/telemetry/semantic-conventions.ts @@ -224,12 +224,17 @@ export const StepRsfsMs = SemanticConvention('step.rsfs_ms'); /** * Client-measured synchronous workflow-function replay duration in - * milliseconds within the rsfs window, excluding awaited network I/O. Only - * present alongside step.rsfs_ms and only for the run's first step - * (see runtime/step-latency.ts) — hence "first" in the name. + * milliseconds, excluding awaited network I/O, of only the FINAL replay pass + * within the rsfs window — the pass that reached and scheduled the first + * step. Not accumulated across earlier pre-first-step passes (e.g. a + * workflow-body `setAttributes()` detour replays more than once, and a + * redelivery omits earlier invocations' work entirely), so this must not be + * read as "the replay portion of rsfs" — step.rsfs_ms covers the whole + * window. Only present alongside step.rsfs_ms and only for the run's first + * step (see runtime/step-latency.ts). */ -export const StepFirstReplayMs = SemanticConvention( - 'step.first_replay_ms' +export const StepFinalSchedulingReplayMs = SemanticConvention( + 'step.final_scheduling_replay_ms' ); /** diff --git a/packages/world-vercel/src/events-v4.ts b/packages/world-vercel/src/events-v4.ts index 7f87351ef9..aa5e8a8e20 100644 --- a/packages/world-vercel/src/events-v4.ts +++ b/packages/world-vercel/src/events-v4.ts @@ -167,10 +167,12 @@ export interface CreateEventV4Input { * run's first step_completed / step_failed. Consumed server-side for * latency metrics. */ rsfs?: number; - /** Client-measured synchronous replay-compute ms within the rsfs window, - * excluding awaited network I/O. Only present alongside rsfs, and only - * for the run's first step. */ - firstReplay?: number; + /** Client-measured synchronous replay-compute ms of only the FINAL replay + * pass within the rsfs window (the pass that scheduled the first step), + * excluding awaited network I/O — not accumulated across earlier + * pre-first-step passes, so it is not "the replay portion of rsfs". + * Only present alongside rsfs, and only for the run's first step. */ + finalSchedulingReplay?: number; /** Runtime optimizations active for the ttfs/stso measurement * (e.g. 'turbo', 'lazyStepStart', 'optimisticStart'). */ optimizations?: string[]; @@ -263,7 +265,9 @@ function buildPostFrameMeta( if (input.stepCount !== undefined) meta.stepCount = input.stepCount; if (input.eventCount !== undefined) meta.eventCount = input.eventCount; if (input.rsfs !== undefined) meta.rsfs = input.rsfs; - if (input.firstReplay !== undefined) meta.firstReplay = input.firstReplay; + if (input.finalSchedulingReplay !== undefined) { + meta.finalSchedulingReplay = input.finalSchedulingReplay; + } if (input.optimizations !== undefined) { meta.optimizations = input.optimizations; } diff --git a/packages/world-vercel/src/events.test.ts b/packages/world-vercel/src/events.test.ts index ff5fc2e79e..2c3460ee4c 100644 --- a/packages/world-vercel/src/events.test.ts +++ b/packages/world-vercel/src/events.test.ts @@ -300,14 +300,14 @@ describe('splitEventDataForV4 attribute fields', () => { result: new TextEncoder().encode('"ok"'), ttfs: 123, rsfs: 88, - firstReplay: 12, + finalSchedulingReplay: 12, optimizations: ['turbo', 'lazyStepStart'], }, } as AnyEventRequest); expect(completed.meta.ttfs).toBe(123); expect(completed.meta.stso).toBeUndefined(); expect(completed.meta.rsfs).toBe(88); - expect(completed.meta.firstReplay).toBe(12); + expect(completed.meta.finalSchedulingReplay).toBe(12); expect(completed.meta.optimizations).toEqual(['turbo', 'lazyStepStart']); const failed = splitEventDataForV4({ @@ -339,7 +339,7 @@ describe('splitEventDataForV4 attribute fields', () => { result: new TextEncoder().encode('"ok"'), ttfs: 'fast', rsfs: 'fast', - firstReplay: 'fast', + finalSchedulingReplay: 'fast', stepCount: 0, eventCount: 2.5, optimizations: [1, 2], @@ -347,7 +347,7 @@ describe('splitEventDataForV4 attribute fields', () => { } as unknown as AnyEventRequest); expect(malformed.meta.ttfs).toBeUndefined(); expect(malformed.meta.rsfs).toBeUndefined(); - expect(malformed.meta.firstReplay).toBeUndefined(); + expect(malformed.meta.finalSchedulingReplay).toBeUndefined(); expect(malformed.meta.stepCount).toBeUndefined(); expect(malformed.meta.eventCount).toBeUndefined(); expect(malformed.meta.optimizations).toBeUndefined(); diff --git a/packages/world-vercel/src/events.ts b/packages/world-vercel/src/events.ts index d62551d722..a769cc91de 100644 --- a/packages/world-vercel/src/events.ts +++ b/packages/world-vercel/src/events.ts @@ -149,8 +149,10 @@ interface SplitEventData { eventCount?: number; /** Client-measured run_started-to-first-step ms (step_completed / step_failed). */ rsfs?: number; - /** Client-measured synchronous replay-compute ms within the rsfs window. */ - firstReplay?: number; + /** Client-measured synchronous replay-compute ms of only the FINAL replay + * pass within the rsfs window — not accumulated across earlier + * pre-first-step passes, so it is not "the replay portion of rsfs". */ + finalSchedulingReplay?: number; /** Runtime optimizations active for the ttfs/stso measurement. */ optimizations?: string[]; }; @@ -188,7 +190,7 @@ type MetaSourceField = | 'stepCount' | 'eventCount' | 'rsfs' - | 'firstReplay' + | 'finalSchedulingReplay' | 'optimizations'; /** @@ -358,8 +360,8 @@ export function splitEventDataForV4(data: AnyEventRequest): SplitEventData { if (typeof eventData.rsfs === 'number') { meta.rsfs = eventData.rsfs; } - if (typeof eventData.firstReplay === 'number') { - meta.firstReplay = eventData.firstReplay; + if (typeof eventData.finalSchedulingReplay === 'number') { + meta.finalSchedulingReplay = eventData.finalSchedulingReplay; } if ( Array.isArray(eventData.optimizations) && diff --git a/packages/world/src/events.ts b/packages/world/src/events.ts index 8190999164..cd7a4e8dbf 100644 --- a/packages/world/src/events.ts +++ b/packages/world/src/events.ts @@ -273,10 +273,12 @@ const stepLatencyTelemetryFields = { // step's start POST was issued. A sub-window of ttfs. Only reported // alongside the same eligibility as ttfs. rsfs: z.number().optional(), - // Synchronous workflow-function replay duration within the rsfs window, - // excluding awaited network I/O. Only present alongside rsfs, and only for - // the run's first step — hence "first" in the name. - firstReplay: z.number().optional(), + // Synchronous workflow-function replay duration of only the FINAL replay + // pass within the rsfs window (the pass that scheduled the first step), + // excluding awaited network I/O — not accumulated across earlier + // pre-first-step passes, so it is not "the replay portion of rsfs". Only + // present alongside rsfs, and only for the run's first step. + finalSchedulingReplay: z.number().optional(), // Names of the runtime's optional startup-latency optimizations that were // active for this measurement (e.g. 'turbo', 'lazyStepStart', // 'optimisticStart'), so latency metrics can be segmented by them. From 90ffbdc5b1aa41eaf01c02772d88684679875512 Mon Sep 17 00:00:00 2001 From: "vercel[bot]" <35613825+vercel[bot]@users.noreply.github.com> Date: Wed, 15 Jul 2026 20:30:49 +0000 Subject: [PATCH 4/4] Fix: RSFS telemetry is systematically dropped on the turbo optimistic-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. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Co-authored-by: VaguelySerious --- packages/core/src/runtime/step-executor.ts | 29 +++++++++ .../core/src/runtime/step-handler.test.ts | 59 +++++++++++++++++++ 2 files changed, 88 insertions(+) diff --git a/packages/core/src/runtime/step-executor.ts b/packages/core/src/runtime/step-executor.ts index 48bc409195..2b720cf6c3 100644 --- a/packages/core/src/runtime/step-executor.ts +++ b/packages/core/src/runtime/step-executor.ts @@ -606,6 +606,30 @@ export async function executeStep( // catch below) can attach it to step_failed too. let latencyEventData: StepLatencyEventData | undefined; + // Backfill RSFS onto the already-computed telemetry once the optimistic + // turbo start has settled. On that path the step-start POST fires inside + // the run-ready barrier's `.then`, so `stepStartPostSentAtMs` — and + // therefore RSFS — is usually still unset when `latencyEventData` is + // first computed just before user code (the barrier is still in flight + // for any non-trivial `run_started` round-trip, which is exactly the + // slow-run_started case RSFS exists to measure). By the time + // `reconcileOptimisticStart()` has awaited the barrier the POST timestamp + // is known, so we patch RSFS in before the terminal event is written. + // Without this, slow-run_started samples are dropped, biasing RSFS + // percentiles low (missing-not-at-random). Recomputes only RSFS — + // TTFS/STSO stay anchored to `executionStartTime` as computed above. + 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), + }); + } + }; + try { const attempt = step.attempt; @@ -821,6 +845,9 @@ export async function executeStep( if (optimisticStart) { const reconcile = await reconcileOptimisticStart(); if (reconcile) return reconcile; + // Barrier resolved — the step-start POST timestamp is now known, so + // RSFS can be attached to the step_completed event below. + backfillOptimisticRsfs(); } // Commit must-be-durable ops (e.g. a step-initiated abort's @@ -849,6 +876,8 @@ export async function executeStep( if (optimisticStart) { const reconcile = await reconcileOptimisticStart(); if (reconcile) return reconcile; + // Barrier resolved — attach RSFS to the step_failed event(s) below. + backfillOptimisticRsfs(); } // Order any must-be-durable ops (e.g. a step-initiated abort's diff --git a/packages/core/src/runtime/step-handler.test.ts b/packages/core/src/runtime/step-handler.test.ts index 8e5f95d61c..cf5b821652 100644 --- a/packages/core/src/runtime/step-handler.test.ts +++ b/packages/core/src/runtime/step-handler.test.ts @@ -1468,4 +1468,63 @@ describe('executeStep optimistic inline start', () => { expect(calls).toContain('step_started'); expect(calls.indexOf('body')).toBeLessThan(calls.indexOf('step_started')); }); + + it('still records rsfs on the terminal event when runReadyBarrier resolves AFTER the latency computation', async () => { + // Regression: on the optimistic turbo path the step-start POST fires + // inside the run-ready barrier's `.then`, so `stepStartPostSentAtMs` (the + // RSFS end anchor) is unset when `latencyEventData` is first computed just + // before user code. If the barrier is still in flight at that point — the + // common slow-`run_started` case RSFS exists to measure — RSFS would be + // dropped, biasing percentiles low. The terminal event must carry rsfs + // regardless of barrier timing. + delete process.env.WORKFLOW_OPTIMISTIC_INLINE_START; + let release!: () => void; + const barrier = new Promise((r) => { + release = r; + }); + mockEventsCreate + .mockReset() + .mockImplementation((_runId: string, _event: { eventType: string }) => + Promise.resolve({ event: {} }) + ); + mockStepFn.mockReset().mockResolvedValue('step-result'); + + // Anchor RSFS/TTFS in the past so both are computable and non-negative. + const anchorMs = Date.now() - 10; + + const world = await getWorld(); + const resultPromise = executeStep({ + world: world as never, + ...baseParams, + forceOptimisticStart: true, + runReadyBarrier: barrier, + latencyTracking: { + ttfsAnchorMs: anchorMs, + rsfsAnchorMs: anchorMs, + replayMs: 1, + turbo: true, + }, + }); + + // Let the body run and reach the latency computation while the barrier — + // and therefore the step-start POST — is still pending. + await vi.waitFor(() => expect(mockStepFn).toHaveBeenCalledTimes(1), { + timeout: 15_000, + }); + + release(); + const result = await resultPromise; + expect(result.type).toBe('completed'); + + const completedWrite = mockEventsCreate.mock.calls.find( + ([, event]) => + (event as { eventType: string }).eventType === 'step_completed' + ); + expect(completedWrite).toBeDefined(); + const eventData = ( + completedWrite![1] as { eventData: { rsfs?: number } } + ).eventData; + expect(eventData.rsfs).toBeDefined(); + expect(eventData.rsfs).toBeGreaterThanOrEqual(0); + }); });