Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions .changeset/replay-cost-telemetry.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
---
'@workflow/core': patch
---

Report replay cost for every step-to-step transition, not just a run's first step, and flag whether a retained VM served the batch
22 changes: 11 additions & 11 deletions .github/workflows/tests.yml
Original file line number Diff line number Diff line change
Expand Up @@ -321,6 +321,9 @@ jobs:
name: E2E Vercel Prod Tests (${{ matrix.app.name }} - ${{ matrix.vm }})
runs-on: ubuntu-latest
timeout-minutes: 30
# Keep cross-language coverage visible without blocking JavaScript SDK
# changes while the Python runtime catches up with the current protocol.
continue-on-error: ${{ matrix.app.name == 'python' }}
needs: ci-scope
if: ${{ needs.ci-scope.outputs.fast-path != 'true' }}
permissions:
Expand Down Expand Up @@ -1320,10 +1323,10 @@ jobs:
# `e2e-vercel-prod` lane, whose rows only need a URL, does carry `python` as an
# ordinary matrix row.
#
# What this lane protects is the gate, not the fixtures it happens to run: a
# test that stops skipping correctly, or a fixture declared in
# `e2e-conformance.json` that the app stops registering, fails here and nowhere
# else.
# This lane is advisory while the Python runtime catches up with the current
# protocol. A test that stops skipping correctly, or a fixture declared in
# `e2e-conformance.json` that the app stops registering, still fails visibly
# here and nowhere else.
e2e-python:
name: E2E Python Conformance
runs-on: ubuntu-latest
Expand Down Expand Up @@ -1671,12 +1674,12 @@ jobs:
header: e2e-test-results
path: e2e-summary.md

# Final required check: passes only when unit + all E2E jobs succeed.
# Community worlds are intentionally excluded — they are disabled on main.
# Final required check: passes only when unit + required E2E jobs succeed.
# Python conformance is advisory, and community worlds are disabled on main.
e2e-required-check:
name: E2E Required Check
runs-on: ubuntu-latest
needs: [ci-scope, unit, e2e-package-build, e2e-vercel-prod, e2e-vercel-ws-transport, e2e-vercel-http-transport, e2e-local-dev, e2e-local-prod, e2e-local-postgres, e2e-python, e2e-windows]
needs: [ci-scope, unit, e2e-package-build, e2e-vercel-prod, e2e-vercel-ws-transport, e2e-vercel-http-transport, e2e-local-dev, e2e-local-prod, e2e-local-postgres, e2e-windows]
if: always()
timeout-minutes: 5

Expand All @@ -1691,7 +1694,6 @@ jobs:
LOCAL_DEV_STATUS: ${{ needs.e2e-local-dev.result }}
LOCAL_PROD_STATUS: ${{ needs.e2e-local-prod.result }}
POSTGRES_STATUS: ${{ needs.e2e-local-postgres.result }}
PYTHON_STATUS: ${{ needs.e2e-python.result }}
WINDOWS_STATUS: ${{ needs.e2e-windows.result }}
FAST_PATH: ${{ needs.ci-scope.outputs.fast-path }}
VALIDATION_FAST_PATH: ${{ needs.ci-scope.outputs.validation-fast-path }}
Expand Down Expand Up @@ -1726,10 +1728,9 @@ jobs:
[[ "$LOCAL_DEV_STATUS" == "skipped" ]] || echo "Warning: e2e-local-dev was not skipped ($LOCAL_DEV_STATUS)"
[[ "$LOCAL_PROD_STATUS" == "skipped" ]] || echo "Warning: e2e-local-prod was not skipped ($LOCAL_PROD_STATUS)"
[[ "$POSTGRES_STATUS" == "skipped" ]] || echo "Warning: e2e-local-postgres was not skipped ($POSTGRES_STATUS)"
[[ "$PYTHON_STATUS" == "skipped" ]] || echo "Warning: e2e-python was not skipped ($PYTHON_STATUS)"
[[ "$WINDOWS_STATUS" == "skipped" ]] || echo "Warning: e2e-windows was not skipped ($WINDOWS_STATUS)"
else
echo "Standard PR - checking all jobs"
echo "Standard PR - checking all required jobs"
[[ "$UNIT_STATUS" == "success" ]] || FAILED_JOBS+=("unit ($UNIT_STATUS)")
[[ "$BUILD_STATUS" == "success" ]] || FAILED_JOBS+=("e2e-package-build ($BUILD_STATUS)")
[[ "$VERCEL_STATUS" == "success" ]] || FAILED_JOBS+=("e2e-vercel-prod ($VERCEL_STATUS)")
Expand All @@ -1738,7 +1739,6 @@ jobs:
[[ "$LOCAL_DEV_STATUS" == "success" ]] || FAILED_JOBS+=("e2e-local-dev ($LOCAL_DEV_STATUS)")
[[ "$LOCAL_PROD_STATUS" == "success" ]] || FAILED_JOBS+=("e2e-local-prod ($LOCAL_PROD_STATUS)")
[[ "$POSTGRES_STATUS" == "success" ]] || FAILED_JOBS+=("e2e-local-postgres ($POSTGRES_STATUS)")
[[ "$PYTHON_STATUS" == "success" ]] || FAILED_JOBS+=("e2e-python ($PYTHON_STATUS)")
[[ "$WINDOWS_STATUS" == "success" ]] || FAILED_JOBS+=("e2e-windows ($WINDOWS_STATUS)")
fi

Expand Down
11 changes: 9 additions & 2 deletions packages/core/src/runtime.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -3015,14 +3015,21 @@ describe('workflowEntrypoint latency telemetry (ttfs / stso)', () => {
expect(second.eventData.stso).toBeLessThanOrEqual(elapsed);
expect(second.eventData.stepCount).toBe(1);
expect(second.eventData.eventCount).toBeGreaterThan(0);
// `retained` is per-pass, not per-invocation: the first step's pass built
// the VM (a full replay, so no flag above), the second step's pass
// resumed the session this same invocation retained.
expect(second.eventData.optimizations).toEqual([
'turbo',
'lazyStepStart',
'optimisticStart',
'retained',
]);
// STSO-only steps never qualify for RSFS (it shares TTFS eligibility).
// STSO-only steps never qualify for RSFS (it shares TTFS eligibility),
// but finalSchedulingReplay is ungated — reported for any batch STSO is,
// not just the run's first step.
expect(second.eventData.rsfs).toBeUndefined();
expect(second.eventData.finalSchedulingReplay).toBeUndefined();
expect(second.eventData.finalSchedulingReplay).toBeGreaterThanOrEqual(0);
expect(second.eventData.finalSchedulingReplay).toBeLessThanOrEqual(elapsed);
});

it('anchors ttfs correctly for a region-tagged run ID (tag bit cleared, not a future timestamp)', async () => {
Expand Down
14 changes: 14 additions & 0 deletions packages/core/src/runtime.ts
Original file line number Diff line number Diff line change
Expand Up @@ -2624,6 +2624,10 @@ export function workflowEntrypoint(
}

let replayStart = 0;
// Whether this pass was served by a retained VM session.
// Set at the resume/replay decision below, before
// `retainedSession` is reassigned for the next iteration.
let servedByRetainedSession = false;
try {
// --- QuickJS VM engine dispatch ---
// The QuickJS engine (opt-in via WORKFLOW_VM=quickjs
Expand Down Expand Up @@ -2980,6 +2984,15 @@ export function workflowEntrypoint(
let workflowResult: WorkflowResumeResult = retainedSession
? await resumeWorkflow(retainedSession, eventLog.events)
: { type: 'replay' };
// A retained resume can still report back `{ type:
// 'replay' }` (internal cache miss), in which case this
// pass falls through to a full replay below and is not
// a retained pass. The `workflow.run` span cannot say
// this: it is tagged `retained` when it opens, before
// the resume result is known.
servedByRetainedSession =
retainedSession !== null &&
workflowResult.type !== 'replay';

if (workflowResult.type === 'replay') {
retainedSession = null;
Expand Down Expand Up @@ -3981,6 +3994,7 @@ export function workflowEntrypoint(
suspensionCreatedHooks:
err.hookCount > 0 || suspensionResult.hasHookEvents,
turbo,
retained: servedByRetainedSession,
});

// Slot snapshot for the inline step_started claims: the
Expand Down
93 changes: 93 additions & 0 deletions packages/core/src/runtime/step-latency.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@ const BASE = {
suspensionHasWaits: false,
suspensionCreatedHooks: false,
turbo: false,
retained: false,
};

describe('computeStepLatencyTracking', () => {
Expand All @@ -47,6 +48,8 @@ describe('computeStepLatencyTracking', () => {
expect(tracking).toEqual({
ttfsAnchorMs: 1_000,
preStepBlockingMs: 0,
replayMs: 0,
retained: false,
turbo: false,
});
});
Expand All @@ -60,6 +63,8 @@ describe('computeStepLatencyTracking', () => {
expect(tracking).toEqual({
ttfsAnchorMs: 1_000,
preStepBlockingMs: 0,
replayMs: 0,
retained: false,
turbo: true,
});
});
Expand Down Expand Up @@ -88,6 +93,8 @@ describe('computeStepLatencyTracking', () => {
expect(tracking).toEqual({
ttfsAnchorMs: 1_000,
preStepBlockingMs: 42,
replayMs: 0,
retained: false,
turbo: false,
});
});
Expand All @@ -112,6 +119,8 @@ describe('computeStepLatencyTracking', () => {
preStepBlockingMs: 0,
// Earliest attr write wins; occurredAt preferred over createdAt.
preStepAttrStartMs: 3_000,
replayMs: 0,
retained: false,
turbo: false,
});
});
Expand All @@ -133,6 +142,8 @@ describe('computeStepLatencyTracking', () => {
ttfsAnchorMs: 1_000,
preStepBlockingMs: 40,
preStepAttrStartMs: 3_000,
replayMs: 0,
retained: false,
turbo: false,
});
});
Expand All @@ -151,6 +162,8 @@ describe('computeStepLatencyTracking', () => {
ttfsAnchorMs: 1_000,
preStepBlockingMs: 0,
preStepAttrStartMs: 3_000,
replayMs: 0,
retained: false,
turbo: false,
});
});
Expand Down Expand Up @@ -194,6 +207,7 @@ describe('computeStepLatencyTracking', () => {
preStepBlockingMs: 0,
rsfsAnchorMs: 1_100,
replayMs: 25,
retained: false,
turbo: false,
});
});
Expand All @@ -205,13 +219,35 @@ describe('computeStepLatencyTracking', () => {
runStartedReceivedAtMs: undefined,
replayMs: 25,
});
// replayMs is ungated: it is reported for any batch this function tracks,
// even one with no RSFS window of its own.
expect(tracking).toEqual({
ttfsAnchorMs: 1_000,
preStepBlockingMs: 0,
replayMs: 25,
retained: false,
turbo: false,
});
});

it('reports replayMs and retained for an STSO-only (non-first-step) batch', () => {
const tracking = computeStepLatencyTracking({
...BASE,
events: [
makeEvent('run_created'),
makeEvent('run_started'),
makeEvent('step_completed', { createdAt: new Date(4_500) }),
],
invocationStartedClean: false,
replayMs: 33,
retained: true,
});
expect(tracking?.ttfsAnchorMs).toBeUndefined();
expect(tracking?.rsfsAnchorMs).toBeUndefined();
expect(tracking?.replayMs).toBe(33);
expect(tracking?.retained).toBe(true);
});

it('does not mark RSFS when TTFS is disqualified, even though runStartedReceivedAtMs is recoverable', () => {
const tracking = computeStepLatencyTracking({
...BASE,
Expand Down Expand Up @@ -240,6 +276,8 @@ describe('computeStepLatencyTracking', () => {
prevStepEndMs: 4_500,
stepCount: 1,
eventCount: 3,
replayMs: 0,
retained: false,
turbo: false,
});
});
Expand All @@ -253,6 +291,8 @@ describe('computeStepLatencyTracking', () => {
prevStepEndMs: 5_000,
stepCount: 1,
eventCount: 1,
replayMs: 0,
retained: false,
turbo: false,
});
});
Expand All @@ -271,6 +311,8 @@ describe('computeStepLatencyTracking', () => {
prevStepEndMs: new Date('2024-01-01T00:00:00.000Z').getTime(),
stepCount: 2,
eventCount: 3,
replayMs: 0,
retained: false,
turbo: false,
});
});
Expand Down Expand Up @@ -324,6 +366,7 @@ describe('computeStepLatencyEventData', () => {
preStepBlockingMs: 40,
preStepAttrStartMs: 3_000,
turbo: false,
retained: false,
},
// Includes the setAttributes detour — must be excluded.
stepCodeStartedAtMs: 60_000,
Expand All @@ -345,6 +388,7 @@ describe('computeStepLatencyEventData', () => {
stepCount: 7,
eventCount: 42,
turbo: false,
retained: false,
},
stepCodeStartedAtMs: 2_000,
stepStartPostSentAtMs: undefined,
Expand All @@ -360,6 +404,49 @@ describe('computeStepLatencyEventData', () => {
});
});

it('reports finalSchedulingReplay for an STSO (non-first-step) batch, not just RSFS', () => {
const data = computeStepLatencyEventData({
tracking: {
prevStepEndMs: 1_500,
stepCount: 7,
eventCount: 42,
replayMs: 33,
turbo: false,
retained: true,
},
stepCodeStartedAtMs: 2_000,
stepStartPostSentAtMs: undefined,
attempt: 1,
lazyStepStart: true,
optimisticStart: false,
});
expect(data).toEqual({
stso: 500,
stepCount: 7,
eventCount: 42,
finalSchedulingReplay: 33,
optimizations: ['lazyStepStart', 'retained'],
});
});

it('omits the retained optimization when a full replay served the batch', () => {
const data = computeStepLatencyEventData({
tracking: {
prevStepEndMs: 1_500,
replayMs: 900,
turbo: true,
retained: false,
},
stepCodeStartedAtMs: 2_000,
stepStartPostSentAtMs: undefined,
attempt: 1,
lazyStepStart: false,
optimisticStart: false,
});
expect(data?.finalSchedulingReplay).toBe(900);
expect(data?.optimizations).toEqual(['turbo']);
});

it('clamps negative durations (cross-machine clock skew) to zero', () => {
const data = computeStepLatencyEventData({
tracking: {
Expand All @@ -369,6 +456,7 @@ describe('computeStepLatencyEventData', () => {
stepCount: 3,
eventCount: 9,
turbo: false,
retained: false,
},
stepCodeStartedAtMs: 4_000,
stepStartPostSentAtMs: undefined,
Expand All @@ -394,6 +482,7 @@ describe('computeStepLatencyEventData', () => {
ttfsAnchorMs: 2_000 + 2 ** 47,
preStepBlockingMs: 0,
turbo: true,
retained: false,
},
stepCodeStartedAtMs: 2_000,
attempt: 1,
Expand All @@ -414,6 +503,7 @@ describe('computeStepLatencyEventData', () => {
stepCount: 2,
eventCount: 5,
turbo: false,
retained: false,
},
stepCodeStartedAtMs: 2_000,
attempt: 1,
Expand Down Expand Up @@ -460,6 +550,7 @@ describe('computeStepLatencyEventData', () => {
rsfsAnchorMs: 1_200,
replayMs: 15,
turbo: false,
retained: false,
},
stepCodeStartedAtMs: 2_000,
stepStartPostSentAtMs: 1_950,
Expand All @@ -483,6 +574,7 @@ describe('computeStepLatencyEventData', () => {
rsfsAnchorMs: 1_200,
replayMs: 15,
turbo: false,
retained: false,
},
stepCodeStartedAtMs: 2_000,
stepStartPostSentAtMs: undefined,
Expand All @@ -505,6 +597,7 @@ describe('computeStepLatencyEventData', () => {
rsfsAnchorMs: 5_000,
replayMs: 10,
turbo: false,
retained: false,
},
stepCodeStartedAtMs: 2_000,
stepStartPostSentAtMs: 4_000,
Expand Down
Loading
Loading