From 44897b7a8c9132a3d3c1b7c925c2ba33abe6c54c Mon Sep 17 00:00:00 2001 From: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> Date: Thu, 13 Aug 2026 20:15:44 -0700 Subject: [PATCH 1/5] Trace fresh workflow replay phases Signed-off-by: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> --- .changeset/trace-replay-phases.md | 5 + packages/core/src/runtime-trace-mode.test.ts | 2 - .../src/telemetry/semantic-conventions.ts | 5 + packages/core/src/vm/script-cache.test.ts | 16 +++ packages/core/src/vm/script-cache.ts | 19 ++- packages/core/src/workflow-tracing.test.ts | 133 ++++++++++++++++++ packages/core/src/workflow.ts | 85 ++++++++--- 7 files changed, 240 insertions(+), 25 deletions(-) create mode 100644 .changeset/trace-replay-phases.md create mode 100644 packages/core/src/workflow-tracing.test.ts diff --git a/.changeset/trace-replay-phases.md b/.changeset/trace-replay-phases.md new file mode 100644 index 0000000000..96334a0ae5 --- /dev/null +++ b/.changeset/trace-replay-phases.md @@ -0,0 +1,5 @@ +--- +"@workflow/core": patch +--- + +Trace workflow VM creation, bundle compilation and evaluation, input hydration, and replay execution. diff --git a/packages/core/src/runtime-trace-mode.test.ts b/packages/core/src/runtime-trace-mode.test.ts index bf119ac4ac..8f71a1d2b6 100644 --- a/packages/core/src/runtime-trace-mode.test.ts +++ b/packages/core/src/runtime-trace-mode.test.ts @@ -201,7 +201,6 @@ async function driveHandler(opts: { const getWorldSpan = exporter .getFinishedSpans() .find((s) => s.name === 'workflow.route.get_world'); - return { workflowSpan, routeSpan, @@ -287,7 +286,6 @@ describe('workflowEntrypoint trace modes', () => { ); expect(getWorldSpan).toBeDefined(); expect(getWorldSpan?.parentSpanId).toBe(routeSpan?.spanContext().spanId); - expect(workflowSpan).toBeDefined(); // Child of the local /flow route span — same trace, so one // invocation is a single bounded trace rather than a new root. diff --git a/packages/core/src/telemetry/semantic-conventions.ts b/packages/core/src/telemetry/semantic-conventions.ts index fb6754017f..063c97db98 100644 --- a/packages/core/src/telemetry/semantic-conventions.ts +++ b/packages/core/src/telemetry/semantic-conventions.ts @@ -82,6 +82,11 @@ export const WorkflowExecutionMode = SemanticConvention<'replay' | 'retained'>( 'workflow.execution.mode' ); +/** Whether every script needed for workflow bundle evaluation was cached. */ +export const WorkflowBundleCompileCacheHit = SemanticConvention( + 'workflow.bundle.compile.cache_hit' +); + /** * Events the replay walked past that no consumer claimed, still held when the * replay stopped. diff --git a/packages/core/src/vm/script-cache.test.ts b/packages/core/src/vm/script-cache.test.ts index 399f6b2c69..6e12da9f1e 100644 --- a/packages/core/src/vm/script-cache.test.ts +++ b/packages/core/src/vm/script-cache.test.ts @@ -4,6 +4,7 @@ import { createContext } from './index.js'; import { clearWorkflowScriptCache, getCachedWorkflowScript, + getCachedWorkflowScriptWithStatus, runCachedWorkflowScript, workflowScriptCacheSize, } from './script-cache.js'; @@ -48,6 +49,21 @@ describe('script-cache', () => { expect(a).toBe(b); }); + it('reports whether compilation was served from cache', () => { + const first = getCachedWorkflowScriptWithStatus( + SAMPLE_BUNDLE, + 'workflows/a.ts' + ); + const second = getCachedWorkflowScriptWithStatus( + SAMPLE_BUNDLE, + 'workflows/a.ts' + ); + + expect(first.cacheHit).toBe(false); + expect(second.cacheHit).toBe(true); + expect(second.script).toBe(first.script); + }); + it('returns distinct Scripts for the same code under different filenames', () => { const a = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts'); const b = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/b.ts'); diff --git a/packages/core/src/vm/script-cache.ts b/packages/core/src/vm/script-cache.ts index fe69884523..c9b94fdbfe 100644 --- a/packages/core/src/vm/script-cache.ts +++ b/packages/core/src/vm/script-cache.ts @@ -104,10 +104,10 @@ function touchBundle(code: string): Map | undefined { * equivalent to `vm.runInContext(code, context, { filename })` but skips the * recompile. */ -export function getCachedWorkflowScript( +export function getCachedWorkflowScriptWithStatus( code: string, filename: string -): Script { +): { script: Script; cacheHit: boolean } { let byFilename = touchBundle(code); if (byFilename === undefined) { byFilename = new Map(); @@ -123,11 +123,24 @@ export function getCachedWorkflowScript( } } let script = byFilename.get(filename); + const cacheHit = script !== undefined; if (script === undefined) { script = new Script(code, { filename }); byFilename.set(filename, script); } - return script; + return { script, cacheHit }; +} + +/** + * Returns a compiled workflow script, hiding cache metadata from callers that + * only need to evaluate it. Replay tracing uses the status-bearing variant to + * distinguish actual V8 compilation from a cache lookup. + */ +export function getCachedWorkflowScript( + code: string, + filename: string +): Script { + return getCachedWorkflowScriptWithStatus(code, filename).script; } /** diff --git a/packages/core/src/workflow-tracing.test.ts b/packages/core/src/workflow-tracing.test.ts new file mode 100644 index 0000000000..d187f64dd7 --- /dev/null +++ b/packages/core/src/workflow-tracing.test.ts @@ -0,0 +1,133 @@ +import { context, trace as otelTrace } from '@opentelemetry/api'; +import { AsyncLocalStorageContextManager } from '@opentelemetry/context-async-hooks'; +import { + BasicTracerProvider, + InMemorySpanExporter, + SimpleSpanProcessor, +} from '@opentelemetry/sdk-trace-base'; +import type { WorkflowRun } from '@workflow/world'; +import { + afterAll, + afterEach, + beforeAll, + beforeEach, + describe, + expect, + it, +} from 'vitest'; +import { dehydrateWorkflowArguments } from './serialization.js'; +import { clearWorkflowScriptCache } from './vm/script-cache.js'; +import { runWorkflow } from './workflow.js'; + +const exporter = new InMemorySpanExporter(); +const provider = new BasicTracerProvider(); +const contextManager = new AsyncLocalStorageContextManager(); + +beforeAll(() => { + provider.addSpanProcessor(new SimpleSpanProcessor(exporter)); + contextManager.enable(); + context.setGlobalContextManager(contextManager); + otelTrace.setGlobalTracerProvider(provider); +}); + +afterAll(async () => { + await provider.shutdown(); + context.disable(); + otelTrace.disable(); +}); + +beforeEach(() => { + clearWorkflowScriptCache(); +}); + +afterEach(() => { + exporter.reset(); +}); + +async function makeRun(): Promise { + const runId = 'wrun_trace_replay'; + return { + runId, + workflowName: 'workflow', + status: 'running', + input: await dehydrateWorkflowArguments(['hello'], runId, undefined, []), + createdAt: new Date('2024-01-01T00:00:00.000Z'), + updatedAt: new Date('2024-01-01T00:00:00.000Z'), + startedAt: new Date('2024-01-01T00:00:00.000Z'), + deploymentId: 'test-deployment', + }; +} + +const workflowCode = ` +async function workflow(value) { return value; } +globalThis.__private_workflows = new Map(); +globalThis.__private_workflows.set('workflow', workflow); +`; + +describe('fresh replay tracing', () => { + it('breaks workflow.run into blocking replay phases', async () => { + const run = await makeRun(); + await runWorkflow(workflowCode, run, [], undefined); + + const spans = exporter.getFinishedSpans(); + const workflowRun = spans.find( + (span) => span.name === 'workflow.run workflow' + ); + expect(workflowRun).toBeDefined(); + + const childNames = spans + .filter((span) => span.parentSpanId === workflowRun?.spanContext().spanId) + .map((span) => span.name); + expect(childNames).toEqual( + expect.arrayContaining([ + 'workflow.vm.create_context', + 'workflow.bundle.compile', + 'workflow.bundle.evaluate', + 'workflow.input.hydrate', + 'workflow.replay.execute', + ]) + ); + }); + + it('marks bundle compilation cache hits on later fresh replays', async () => { + const run = await makeRun(); + await runWorkflow(workflowCode, run, [], undefined); + await runWorkflow(workflowCode, run, [], undefined); + + const compileSpans = exporter + .getFinishedSpans() + .filter((span) => span.name === 'workflow.bundle.compile'); + expect(compileSpans).toHaveLength(2); + expect( + compileSpans.map( + (span) => span.attributes['workflow.bundle.compile.cache_hit'] + ) + ).toEqual([false, true]); + }); + + it('reports a bundle hit when only a different workflow lookup compiles', async () => { + const firstName = 'workflow//./workflows/shared//first'; + const secondName = 'workflow//./workflows/shared//second'; + const sharedBundle = ` +async function first(value) { return value; } +async function second(value) { return value; } +globalThis.__private_workflows = new Map(); +globalThis.__private_workflows.set(${JSON.stringify(firstName)}, first); +globalThis.__private_workflows.set(${JSON.stringify(secondName)}, second); +`; + const firstRun = { ...(await makeRun()), workflowName: firstName }; + const secondRun = { ...(await makeRun()), workflowName: secondName }; + + await runWorkflow(sharedBundle, firstRun, [], undefined); + await runWorkflow(sharedBundle, secondRun, [], undefined); + + const compileSpans = exporter + .getFinishedSpans() + .filter((span) => span.name === 'workflow.bundle.compile'); + expect( + compileSpans.map( + (span) => span.attributes['workflow.bundle.compile.cache_hit'] + ) + ).toEqual([false, true]); + }); +}); diff --git a/packages/core/src/workflow.ts b/packages/core/src/workflow.ts index 0a158b58f9..27ca992cf6 100644 --- a/packages/core/src/workflow.ts +++ b/packages/core/src/workflow.ts @@ -42,10 +42,14 @@ import { WORKFLOW_USE_STEP, } from './symbols.js'; import * as Attribute from './telemetry/semantic-conventions.js'; -import { applyWorkflowSuspensionToSpan, trace } from './telemetry.js'; +import { + applyWorkflowSuspensionToSpan, + recordElapsedSpan, + trace, +} from './telemetry.js'; import { getWorkflowRunStreamId } from './util.js'; import { createContext } from './vm/index.js'; -import { runCachedWorkflowScript } from './vm/script-cache.js'; +import { getCachedWorkflowScriptWithStatus } from './vm/script-cache.js'; import { createAbortSignalStatics, createCreateAbortController, @@ -345,6 +349,11 @@ async function createWorkflowSession({ : `http://localhost:${(await getPortLazy()) ?? 3000}` ); + // Include both node:vm's context creation and the host-side sandbox wiring + // below. Most of the bootstrap lives in this function (EventsConsumer, + // workflow globals, Web API shims), so tracing createContext() alone would + // materially under-report VM startup. + const vmBootstrapStartedAt = Date.now(); const { context, globalThis: vmGlobalThis, @@ -1071,22 +1080,43 @@ async function createWorkflowSession({ vmGlobalThis[SYMBOL_FOR_REQ_CONTEXT] = (globalThis as any)[ SYMBOL_FOR_REQ_CONTEXT ]; + await recordElapsedSpan('workflow.vm.create_context', vmBootstrapStartedAt); // Get a reference to the user-defined workflow function. // The filename parameter ensures stack traces show a meaningful name // (e.g., "example/workflows/99_e2e.ts") instead of "evalmachine.". const parsedName = parseWorkflowName(workflowRun.workflowName); const filename = parsedName?.moduleSpecifier || workflowRun.workflowName; + const workflowLookupCode = `globalThis.__private_workflows?.get(${JSON.stringify(workflowRun.workflowName)})`; // Reuse compiled scripts by `(code, filename)`: compilation is deterministic // and the filename preserves workflow source attribution in stack traces. // The bundle registers workflows on `globalThis.__private_workflows`. - runCachedWorkflowScript(workflowCode, filename, context); - const workflowFn = runCachedWorkflowScript( - `globalThis.__private_workflows?.get(${JSON.stringify(workflowRun.workflowName)})`, - filename, - context + const { bundleScript, workflowLookupScript } = await trace( + 'workflow.bundle.compile', + async (span) => { + const bundle = getCachedWorkflowScriptWithStatus(workflowCode, filename); + const lookup = getCachedWorkflowScriptWithStatus( + workflowLookupCode, + filename + ); + span?.setAttributes({ + // This attribute intentionally describes the workflow bundle. The + // tiny workflow-name lookup script has its own cache entry and may + // miss when another workflow from the same source file runs, but that + // does not mean V8 recompiled the application bundle. + ...Attribute.WorkflowBundleCompileCacheHit(bundle.cacheHit), + }); + return { + bundleScript: bundle.script, + workflowLookupScript: lookup.script, + }; + } ); + const workflowFn = await trace('workflow.bundle.evaluate', async () => { + bundleScript.runInContext(context); + return workflowLookupScript.runInContext(context); + }); if (typeof workflowFn !== 'function') { throw new WorkflowNotRegisteredError(workflowRun.workflowName); @@ -1098,24 +1128,27 @@ async function createWorkflowSession({ // workflow function subscribing its first step callbacks. let args: unknown[] = []; workflowContext.promiseQueue = workflowContext.promiseQueue.then(async () => { - const prepared = await replayPayloadCache.prepareWorkflowInput(workflowRun); - args = await hydrateWorkflowArguments( - workflowRun.input, - workflowRun.runId, - encryptionKey, - vmGlobalThis, - {}, - prepared - ); + // Include any residual preparation that did not finish while the event log + // was streaming, plus VM-local deserialization, in the blocking boundary. + args = await trace('workflow.input.hydrate', async () => { + const prepared = + await replayPayloadCache.prepareWorkflowInput(workflowRun); + return hydrateWorkflowArguments( + workflowRun.input, + workflowRun.runId, + encryptionKey, + vmGlobalThis, + {}, + prepared + ); + }); }); await workflowContext.promiseQueue; // The user function's promise. It may stay pending across many resumes // (each parked step promise holds it up) and is raced against the current // attempt's interruption in waitForExecution. - const workflowBody = (async (): Promise => { - return await workflowFn(...args); - })(); + let workflowBody: Promise; const failWorkflow = async (error: unknown): Promise => { // Control-flow signals are handled by the runtime and do not mean the @@ -1244,8 +1277,20 @@ async function createWorkflowSession({ }, }; + // Start the user function inside the span, rather than wrapping the already + // running promise: an async workflow executes synchronously until its first + // await, and that work is part of replay. The span ends at the first + // suspension/completion; later retained resumes get their own workflow.run + // span and do not leave this replay span open while the VM is parked. + const execution = trace('workflow.replay.execute', async () => { + workflowBody = (async (): Promise => { + return await workflowFn(...args); + })(); + return waitForExecution(initialInterruption); + }); + return { session, - execution: waitForExecution(initialInterruption), + execution, }; } From 2f4d8d4e808f9d22e706e7182ad4af8f61001f6d Mon Sep 17 00:00:00 2001 From: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> Date: Fri, 14 Aug 2026 22:58:44 -0700 Subject: [PATCH 2/5] refactor(core): simplify workflow script cache API Signed-off-by: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> --- packages/core/src/vm/script-cache.test.ts | 76 +++++++++++------------ packages/core/src/vm/script-cache.ts | 28 +-------- packages/core/src/workflow.ts | 9 +-- 3 files changed, 41 insertions(+), 72 deletions(-) diff --git a/packages/core/src/vm/script-cache.test.ts b/packages/core/src/vm/script-cache.test.ts index 6e12da9f1e..1dc2b34db5 100644 --- a/packages/core/src/vm/script-cache.test.ts +++ b/packages/core/src/vm/script-cache.test.ts @@ -1,11 +1,9 @@ -import { runInContext } from 'node:vm'; +import { type Context, runInContext } from 'node:vm'; import { afterEach, describe, expect, it } from 'vitest'; import { createContext } from './index.js'; import { clearWorkflowScriptCache, getCachedWorkflowScript, - getCachedWorkflowScriptWithStatus, - runCachedWorkflowScript, workflowScriptCacheSize, } from './script-cache.js'; @@ -38,26 +36,28 @@ function buildBundle(marker: string, workflowCount = 12): string { return `globalThis.__private_workflows = new Map();\n${defs.join('\n')}\n`; } +function getScript(code: string, filename: string) { + return getCachedWorkflowScript(code, filename).script; +} + +function runScript(code: string, filename: string, context: Context) { + return getScript(code, filename).runInContext(context); +} + describe('script-cache', () => { afterEach(() => { clearWorkflowScriptCache(); }); it('returns the same compiled Script for identical (code, filename)', () => { - const a = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts'); - const b = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts'); + const a = getScript(SAMPLE_BUNDLE, 'workflows/a.ts'); + const b = getScript(SAMPLE_BUNDLE, 'workflows/a.ts'); expect(a).toBe(b); }); it('reports whether compilation was served from cache', () => { - const first = getCachedWorkflowScriptWithStatus( - SAMPLE_BUNDLE, - 'workflows/a.ts' - ); - const second = getCachedWorkflowScriptWithStatus( - SAMPLE_BUNDLE, - 'workflows/a.ts' - ); + const first = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts'); + const second = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts'); expect(first.cacheHit).toBe(false); expect(second.cacheHit).toBe(true); @@ -65,14 +65,14 @@ describe('script-cache', () => { }); it('returns distinct Scripts for the same code under different filenames', () => { - const a = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts'); - const b = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/b.ts'); + const a = getScript(SAMPLE_BUNDLE, 'workflows/a.ts'); + const b = getScript(SAMPLE_BUNDLE, 'workflows/b.ts'); expect(a).not.toBe(b); }); it('returns distinct Scripts for different code under the same filename', () => { - const a = getCachedWorkflowScript('1 + 1', 'workflows/a.ts'); - const b = getCachedWorkflowScript('2 + 2', 'workflows/a.ts'); + const a = getScript('1 + 1', 'workflows/a.ts'); + const b = getScript('2 + 2', 'workflows/a.ts'); expect(a).not.toBe(b); }); @@ -80,8 +80,8 @@ describe('script-cache', () => { // Cached path: run the bundle then look up the workflow, mirroring // runWorkflow's two-step evaluation. const { context: cachedCtx } = createContext({ seed, fixedTimestamp }); - runCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts', cachedCtx); - const cachedFn = runCachedWorkflowScript( + runScript(SAMPLE_BUNDLE, 'workflows/a.ts', cachedCtx); + const cachedFn = runScript( `globalThis.__private_workflows?.get('my/workflow')`, 'workflows/a.ts', cachedCtx @@ -106,16 +106,14 @@ describe('script-cache', () => { }); it('reuses the compiled Script across multiple runs against fresh contexts', async () => { - const script = getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts'); + const script = getScript(SAMPLE_BUNDLE, 'workflows/a.ts'); const results: string[] = []; for (let i = 0; i < 3; i++) { const { context } = createContext({ seed, fixedTimestamp }); - runCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts', context); + runScript(SAMPLE_BUNDLE, 'workflows/a.ts', context); // The same cached Script object is used every iteration. - expect(getCachedWorkflowScript(SAMPLE_BUNDLE, 'workflows/a.ts')).toBe( - script - ); + expect(getScript(SAMPLE_BUNDLE, 'workflows/a.ts')).toBe(script); const fn = runInContext( `globalThis.__private_workflows?.get('my/workflow')`, context @@ -135,7 +133,7 @@ describe('script-cache', () => { const editCount = 100; const filename = 'workflows/a.ts'; for (let i = 0; i < editCount; i++) { - getCachedWorkflowScript(buildBundle(`edit-${i}`), filename); + getScript(buildBundle(`edit-${i}`), filename); } const size = workflowScriptCacheSize(); @@ -146,9 +144,7 @@ describe('script-cache', () => { // The cache still serves correctly after heavy churn: the most-recently // inserted bundle is retained and repeated lookups return the same Script. const latest = buildBundle(`edit-${editCount - 1}`); - expect(getCachedWorkflowScript(latest, filename)).toBe( - getCachedWorkflowScript(latest, filename) - ); + expect(getScript(latest, filename)).toBe(getScript(latest, filename)); }); it('keeps the most-recently-used bundle and evicts the stale one', () => { @@ -157,18 +153,18 @@ describe('script-cache', () => { // unrelated bundles churn through. LRU must NOT evict the bundle we keep // using, even though it was inserted first. const hot = buildBundle('hot'); - const hotScript = getCachedWorkflowScript(hot, filename); + const hotScript = getScript(hot, filename); for (let i = 0; i < 50; i++) { - getCachedWorkflowScript(buildBundle(`cold-${i}`), filename); + getScript(buildBundle(`cold-${i}`), filename); // Re-access the hot bundle so it stays most-recently-used. - expect(getCachedWorkflowScript(hot, filename)).toBe(hotScript); + expect(getScript(hot, filename)).toBe(hotScript); } // After all that churn the hot bundle is still the *same* cached Script — // proving LRU recency (touch-on-access), not mere insertion order, governs // eviction. - expect(getCachedWorkflowScript(hot, filename)).toBe(hotScript); + expect(getScript(hot, filename)).toBe(hotScript); }); it('never returns the wrong Script across realistic multi-workflow bundles', async () => { @@ -181,10 +177,10 @@ describe('script-cache', () => { const fileA = 'workflows/a.ts'; const fileB = 'workflows/b.ts'; - const xa = getCachedWorkflowScript(bundleX, fileA); - const xb = getCachedWorkflowScript(bundleX, fileB); - const ya = getCachedWorkflowScript(bundleY, fileA); - const yb = getCachedWorkflowScript(bundleY, fileB); + const xa = getScript(bundleX, fileA); + const xb = getScript(bundleX, fileB); + const ya = getScript(bundleY, fileA); + const yb = getScript(bundleY, fileB); // All four (code, filename) combinations are distinct Script objects. const scripts = [xa, xb, ya, yb]; @@ -195,12 +191,12 @@ describe('script-cache', () => { } // Same (code, filename) is stable across lookups. - expect(getCachedWorkflowScript(bundleX, fileA)).toBe(xa); - expect(getCachedWorkflowScript(bundleY, fileB)).toBe(yb); + expect(getScript(bundleX, fileA)).toBe(xa); + expect(getScript(bundleY, fileB)).toBe(yb); // Running each bundle yields its OWN marker, confirming no cross-wiring. const { context: ctxX } = createContext({ seed, fixedTimestamp }); - runCachedWorkflowScript(bundleX, fileA, ctxX); + runScript(bundleX, fileA, ctxX); const fnX = runInContext( `globalThis.__private_workflows?.get('app/workflow-3')`, ctxX @@ -208,7 +204,7 @@ describe('script-cache', () => { expect(await fnX('z')).toContain('bundle-X:3:z'); const { context: ctxY } = createContext({ seed, fixedTimestamp }); - runCachedWorkflowScript(bundleY, fileA, ctxY); + runScript(bundleY, fileA, ctxY); const fnY = runInContext( `globalThis.__private_workflows?.get('app/workflow-3')`, ctxY diff --git a/packages/core/src/vm/script-cache.ts b/packages/core/src/vm/script-cache.ts index c9b94fdbfe..09db402497 100644 --- a/packages/core/src/vm/script-cache.ts +++ b/packages/core/src/vm/script-cache.ts @@ -1,4 +1,4 @@ -import { type Context, Script } from 'node:vm'; +import { Script } from 'node:vm'; import { globalSingleton } from '@workflow/utils'; /** @@ -104,7 +104,7 @@ function touchBundle(code: string): Map | undefined { * equivalent to `vm.runInContext(code, context, { filename })` but skips the * recompile. */ -export function getCachedWorkflowScriptWithStatus( +export function getCachedWorkflowScript( code: string, filename: string ): { script: Script; cacheHit: boolean } { @@ -131,30 +131,6 @@ export function getCachedWorkflowScriptWithStatus( return { script, cacheHit }; } -/** - * Returns a compiled workflow script, hiding cache metadata from callers that - * only need to evaluate it. Replay tracing uses the status-bearing variant to - * distinguish actual V8 compilation from a cache lookup. - */ -export function getCachedWorkflowScript( - code: string, - filename: string -): Script { - return getCachedWorkflowScriptWithStatus(code, filename).script; -} - -/** - * Runs the cached workflow-bundle `Script` against `context`. Compiles and - * caches the `Script` on first use for the given `(code, filename)`. - */ -export function runCachedWorkflowScript( - code: string, - filename: string, - context: Context -): unknown { - return getCachedWorkflowScript(code, filename).runInContext(context); -} - /** * Clears the compiled-script cache. Intended for tests that want to assert * compile-vs-cache behaviour in isolation; not used on the hot path. diff --git a/packages/core/src/workflow.ts b/packages/core/src/workflow.ts index 27ca992cf6..309f48bae8 100644 --- a/packages/core/src/workflow.ts +++ b/packages/core/src/workflow.ts @@ -49,7 +49,7 @@ import { } from './telemetry.js'; import { getWorkflowRunStreamId } from './util.js'; import { createContext } from './vm/index.js'; -import { getCachedWorkflowScriptWithStatus } from './vm/script-cache.js'; +import { getCachedWorkflowScript } from './vm/script-cache.js'; import { createAbortSignalStatics, createCreateAbortController, @@ -1095,11 +1095,8 @@ async function createWorkflowSession({ const { bundleScript, workflowLookupScript } = await trace( 'workflow.bundle.compile', async (span) => { - const bundle = getCachedWorkflowScriptWithStatus(workflowCode, filename); - const lookup = getCachedWorkflowScriptWithStatus( - workflowLookupCode, - filename - ); + const bundle = getCachedWorkflowScript(workflowCode, filename); + const lookup = getCachedWorkflowScript(workflowLookupCode, filename); span?.setAttributes({ // This attribute intentionally describes the workflow bundle. The // tiny workflow-name lookup script has its own cache entry and may From 1bd9c047755681eeeb69c29bc93ad4113c7c5dce Mon Sep 17 00:00:00 2001 From: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> Date: Tue, 18 Aug 2026 15:06:18 -0700 Subject: [PATCH 3/5] Fix retained workflow tracing Signed-off-by: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> --- packages/core/src/telemetry.ts | 46 +++++++++ packages/core/src/workflow-tracing.test.ts | 109 ++++++++++++++++++--- packages/core/src/workflow.ts | 67 +++++++------ 3 files changed, 177 insertions(+), 45 deletions(-) diff --git a/packages/core/src/telemetry.ts b/packages/core/src/telemetry.ts index e23ef6fc45..5706ff9927 100644 --- a/packages/core/src/telemetry.ts +++ b/packages/core/src/telemetry.ts @@ -288,6 +288,52 @@ export async function trace( }); } +/** Starts a child span without installing it as the active context. */ +export async function startTraceSpan(spanName: string) { + const [tracer, otel] = await Promise.all([Tracer.value, OtelApi.value]); + if (!tracer || !otel) return { end() {}, fail() {} }; + + const span = tracer.startSpan(spanName); + let ended = false; + const finish = (status: api.SpanStatus) => { + if (ended) return; + ended = true; + span.setStatus(status); + span.end(); + }; + + return { + end: () => finish({ code: otel.SpanStatusCode.OK }), + fail: (error: unknown) => + finish({ + code: otel.SpanStatusCode.ERROR, + message: (error as Error).message, + }), + }; +} + +/** Keeps a parked workflow's ambient trace context aligned with each resume. */ +export async function createRefreshableTraceContext() { + const otel = await OtelApi.value; + if (!otel) { + return { refresh() {}, run: (fn: () => T): T => fn() }; + } + + let current = otel.context.active(); + const context: api.Context = { + getValue: (key) => current.getValue(key), + setValue: (key, value) => current.setValue(key, value), + deleteValue: (key) => current.deleteValue(key), + }; + + return { + refresh: () => { + current = otel.context.active(); + }, + run: (fn: () => T): T => otel.context.with(context, fn), + }; +} + /** * Emit a span whose start is back-dated to `startEpochMs` and whose end is now, * so its duration reflects an interval only measurable at its end (e.g. diff --git a/packages/core/src/workflow-tracing.test.ts b/packages/core/src/workflow-tracing.test.ts index d187f64dd7..3d2a1553a7 100644 --- a/packages/core/src/workflow-tracing.test.ts +++ b/packages/core/src/workflow-tracing.test.ts @@ -1,23 +1,39 @@ -import { context, trace as otelTrace } from '@opentelemetry/api'; +import { + context, + trace as otelTrace, + SpanStatusCode, +} from '@opentelemetry/api'; import { AsyncLocalStorageContextManager } from '@opentelemetry/context-async-hooks'; import { BasicTracerProvider, InMemorySpanExporter, SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; -import type { WorkflowRun } from '@workflow/world'; +import type { Event, WorkflowRun } from '@workflow/world'; import { afterAll, afterEach, + assert, beforeAll, beforeEach, describe, expect, it, + vi, } from 'vitest'; -import { dehydrateWorkflowArguments } from './serialization.js'; +import { ReplayPayloadCache } from './replay-payload-cache.js'; +import { + dehydrateStepReturnValue, + dehydrateWorkflowArguments, +} from './serialization.js'; +import { createContext } from './vm/index.js'; import { clearWorkflowScriptCache } from './vm/script-cache.js'; -import { runWorkflow } from './workflow.js'; +import { replayWorkflow, resumeWorkflow, runWorkflow } from './workflow.js'; + +vi.mock('./vm/index.js', async (importActual) => { + const actual = await importActual(); + return { ...actual, createContext: vi.fn(actual.createContext) }; +}); const exporter = new InMemorySpanExporter(); const provider = new BasicTracerProvider(); @@ -42,6 +58,7 @@ beforeEach(() => { afterEach(() => { exporter.reset(); + vi.restoreAllMocks(); }); async function makeRun(): Promise { @@ -58,6 +75,10 @@ async function makeRun(): Promise { }; } +function spans(name: string) { + return exporter.getFinishedSpans().filter((span) => span.name === name); +} + const workflowCode = ` async function workflow(value) { return value; } globalThis.__private_workflows = new Map(); @@ -69,13 +90,11 @@ describe('fresh replay tracing', () => { const run = await makeRun(); await runWorkflow(workflowCode, run, [], undefined); - const spans = exporter.getFinishedSpans(); - const workflowRun = spans.find( - (span) => span.name === 'workflow.run workflow' - ); + const allSpans = exporter.getFinishedSpans(); + const [workflowRun] = spans('workflow.run workflow'); expect(workflowRun).toBeDefined(); - const childNames = spans + const childNames = allSpans .filter((span) => span.parentSpanId === workflowRun?.spanContext().spanId) .map((span) => span.name); expect(childNames).toEqual( @@ -89,14 +108,76 @@ describe('fresh replay tracing', () => { ); }); + it('records VM bootstrap failures on the create-context span', async () => { + vi.mocked(createContext).mockImplementationOnce(() => { + throw new Error('test bootstrap failure'); + }); + + await expect( + runWorkflow(workflowCode, await makeRun(), [], undefined) + ).rejects.toThrow('test bootstrap failure'); + + expect(spans('workflow.vm.create_context')[0]?.status).toEqual({ + code: SpanStatusCode.ERROR, + message: 'test bootstrap failure', + }); + }); + + it('parents retained workflow continuations to the retained run', async () => { + const run = await makeRun(); + const code = `const step = globalThis[Symbol.for("WORKFLOW_USE_STEP")]("step"); + async function workflow() { await step(); console.log("resumed"); } + globalThis.__private_workflows = new Map([["workflow", workflow]]); + `; + const activeSpanIds: (string | undefined)[] = []; + vi.spyOn(console, 'log').mockImplementation((message) => { + if (message === 'resumed') { + activeSpanIds.push(otelTrace.getActiveSpan()?.spanContext().spanId); + } + }); + + const first = await replayWorkflow({ + workflowCode: code, + workflowRun: run, + events: [], + encryptionKey: undefined, + replayPayloadCache: new ReplayPayloadCache(undefined), + }); + assert(first.type === 'suspended'); + expect(spans('workflow.replay.execute')).toHaveLength(1); + const step = first.suspension.steps[0]; + assert(step?.type === 'step'); + const result = await dehydrateStepReturnValue( + undefined, + run.runId, + undefined + ); + + const completed = await resumeWorkflow(first.session, [ + { + eventId: 'event-step-completed', + runId: run.runId, + eventType: 'step_completed', + correlationId: step.correlationId, + eventData: { stepName: 'step', result }, + createdAt: run.updatedAt, + }, + ] as Event[]); + assert(completed.type === 'completed'); + + expect(spans('workflow.replay.execute')).toHaveLength(1); + const retainedRun = spans('workflow.run workflow').find( + (span) => span.attributes['workflow.execution.mode'] === 'retained' + ); + expect(activeSpanIds).toEqual([retainedRun?.spanContext().spanId]); + }); + it('marks bundle compilation cache hits on later fresh replays', async () => { const run = await makeRun(); await runWorkflow(workflowCode, run, [], undefined); await runWorkflow(workflowCode, run, [], undefined); - const compileSpans = exporter - .getFinishedSpans() - .filter((span) => span.name === 'workflow.bundle.compile'); + const compileSpans = spans('workflow.bundle.compile'); expect(compileSpans).toHaveLength(2); expect( compileSpans.map( @@ -121,9 +202,7 @@ globalThis.__private_workflows.set(${JSON.stringify(secondName)}, second); await runWorkflow(sharedBundle, firstRun, [], undefined); await runWorkflow(sharedBundle, secondRun, [], undefined); - const compileSpans = exporter - .getFinishedSpans() - .filter((span) => span.name === 'workflow.bundle.compile'); + const compileSpans = spans('workflow.bundle.compile'); expect( compileSpans.map( (span) => span.attributes['workflow.bundle.compile.cache_hit'] diff --git a/packages/core/src/workflow.ts b/packages/core/src/workflow.ts index 309f48bae8..743f5d1099 100644 --- a/packages/core/src/workflow.ts +++ b/packages/core/src/workflow.ts @@ -44,7 +44,8 @@ import { import * as Attribute from './telemetry/semantic-conventions.js'; import { applyWorkflowSuspensionToSpan, - recordElapsedSpan, + createRefreshableTraceContext, + startTraceSpan, trace, } from './telemetry.js'; import { getWorkflowRunStreamId } from './util.js'; @@ -309,15 +310,26 @@ export async function runWorkflow( return result.output; } -async function createWorkflowSession({ - workflowCode, - workflowRun, - events, - encryptionKey, - replayPayloadCache, - runReadyBarrier, - worldCapabilities, -}: WorkflowSessionOptions): Promise<{ +async function createWorkflowSession(options: WorkflowSessionOptions) { + const vmTrace = await startTraceSpan('workflow.vm.create_context'); + return createWorkflowSessionInner(options, vmTrace.end).catch((error) => { + vmTrace.fail(error); + throw error; + }); +} + +async function createWorkflowSessionInner( + { + workflowCode, + workflowRun, + events, + encryptionKey, + replayPayloadCache, + runReadyBarrier, + worldCapabilities, + }: WorkflowSessionOptions, + endVmTrace: () => void +): Promise<{ session: WorkflowSession; execution: Promise; }> { @@ -348,12 +360,10 @@ async function createWorkflowSession({ ? `https://${process.env.VERCEL_URL}` : `http://localhost:${(await getPortLazy()) ?? 3000}` ); - // Include both node:vm's context creation and the host-side sandbox wiring // below. Most of the bootstrap lives in this function (EventsConsumer, // workflow globals, Web API shims), so tracing createContext() alone would // materially under-report VM startup. - const vmBootstrapStartedAt = Date.now(); const { context, globalThis: vmGlobalThis, @@ -1080,7 +1090,7 @@ async function createWorkflowSession({ vmGlobalThis[SYMBOL_FOR_REQ_CONTEXT] = (globalThis as any)[ SYMBOL_FOR_REQ_CONTEXT ]; - await recordElapsedSpan('workflow.vm.create_context', vmBootstrapStartedAt); + endVmTrace(); // Get a reference to the user-defined workflow function. // The filename parameter ensures stack traces show a meaningful name @@ -1142,11 +1152,6 @@ async function createWorkflowSession({ }); await workflowContext.promiseQueue; - // The user function's promise. It may stay pending across many resumes - // (each parked step promise holds it up) and is raced against the current - // attempt's interruption in waitForExecution. - let workflowBody: Promise; - const failWorkflow = async (error: unknown): Promise => { // Control-flow signals are handled by the runtime and do not mean the // workflow has terminally failed. `onWorkflowError` usually already moved @@ -1173,6 +1178,7 @@ async function createWorkflowSession({ }; const waitForExecution = async ( + workflowBody: Promise, interruption: PromiseWithResolvers ): Promise => { let result: unknown; @@ -1235,6 +1241,12 @@ async function createWorkflowSession({ } }; + const workflowTraceContext = await createRefreshableTraceContext(); + const replayTrace = await startTraceSpan('workflow.replay.execute'); + const workflowBody = workflowTraceContext.run(async () => + workflowFn(...args) + ); + const session: WorkflowSession = { workflowRun, argumentCount: args.length, @@ -1259,8 +1271,9 @@ async function createWorkflowSession({ const interruption = withResolvers(); state = { type: 'running', interruption }; workflowContext.suspensionGeneration++; + workflowTraceContext.refresh(); eventsConsumer.append(nextEvents.slice(knownEvents.length)); - return waitForExecution(interruption); + return waitForExecution(workflowBody, interruption); } case 'replay': return { type: 'replay' }; @@ -1274,17 +1287,11 @@ async function createWorkflowSession({ }, }; - // Start the user function inside the span, rather than wrapping the already - // running promise: an async workflow executes synchronously until its first - // await, and that work is part of replay. The span ends at the first - // suspension/completion; later retained resumes get their own workflow.run - // span and do not leave this replay span open while the VM is parked. - const execution = trace('workflow.replay.execute', async () => { - workflowBody = (async (): Promise => { - return await workflowFn(...args); - })(); - return waitForExecution(initialInterruption); - }); + // The replay span measures the user function without becoming its ambient + // context. The workflow promise stays pending across retained resumes, so an + // active replay span here would remain captured after that span has ended. + const execution = waitForExecution(workflowBody, initialInterruption); + void execution.then(replayTrace.end, replayTrace.fail); return { session, From 532197ac22e1caa273a75811cc8aa8bdf2f72be9 Mon Sep 17 00:00:00 2001 From: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> Date: Thu, 20 Aug 2026 10:30:37 -0700 Subject: [PATCH 4/5] fix(core): keep tracing failure-safe Signed-off-by: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> --- packages/core/src/telemetry.ts | 21 +++++++++++++++++-- .../src/telemetry/semantic-conventions.ts | 2 +- packages/core/src/workflow-tracing.test.ts | 16 ++++++++++++++ 3 files changed, 36 insertions(+), 3 deletions(-) diff --git a/packages/core/src/telemetry.ts b/packages/core/src/telemetry.ts index 5706ff9927..7b6ebdee2d 100644 --- a/packages/core/src/telemetry.ts +++ b/packages/core/src/telemetry.ts @@ -214,6 +214,23 @@ const StepExecutionDurationHistogram = once(async () => { // OTel registration, which is the whole point of the log. With several copies // in a process, each one's view is what is worth seeing. let otelDiagLogged = false; + +function describeThrownValue(value: unknown): string { + try { + if ( + typeof value === 'object' && + value !== null && + 'message' in value && + typeof value.message === 'string' + ) { + return value.message; + } + return String(value); + } catch { + return 'Unknown error'; + } +} + function logOtelDiagnosticOnce(otel: typeof api, tracer: api.Tracer): void { const debugEnabled = typeof process !== 'undefined' && @@ -278,7 +295,7 @@ export async function trace( } else { span.setStatus({ code: otel.SpanStatusCode.ERROR, - message: (e as Error).message, + message: describeThrownValue(e), }); } throw e; @@ -307,7 +324,7 @@ export async function startTraceSpan(spanName: string) { fail: (error: unknown) => finish({ code: otel.SpanStatusCode.ERROR, - message: (error as Error).message, + message: describeThrownValue(error), }), }; } diff --git a/packages/core/src/telemetry/semantic-conventions.ts b/packages/core/src/telemetry/semantic-conventions.ts index 063c97db98..8d14b6af48 100644 --- a/packages/core/src/telemetry/semantic-conventions.ts +++ b/packages/core/src/telemetry/semantic-conventions.ts @@ -82,7 +82,7 @@ export const WorkflowExecutionMode = SemanticConvention<'replay' | 'retained'>( 'workflow.execution.mode' ); -/** Whether every script needed for workflow bundle evaluation was cached. */ +/** Whether the compiled application workflow bundle was cached. */ export const WorkflowBundleCompileCacheHit = SemanticConvention( 'workflow.bundle.compile.cache_hit' ); diff --git a/packages/core/src/workflow-tracing.test.ts b/packages/core/src/workflow-tracing.test.ts index 3d2a1553a7..730868451d 100644 --- a/packages/core/src/workflow-tracing.test.ts +++ b/packages/core/src/workflow-tracing.test.ts @@ -123,6 +123,22 @@ describe('fresh replay tracing', () => { }); }); + it('ends the replay span when workflow code throws null', async () => { + const nullThrowingWorkflow = ` +async function workflow() { throw null; } +globalThis.__private_workflows = new Map([['workflow', workflow]]); +`; + + await expect( + runWorkflow(nullThrowingWorkflow, await makeRun(), [], undefined) + ).rejects.toBeNull(); + + expect(spans('workflow.replay.execute')[0]?.status).toEqual({ + code: SpanStatusCode.ERROR, + message: 'null', + }); + }); + it('parents retained workflow continuations to the retained run', async () => { const run = await makeRun(); const code = `const step = globalThis[Symbol.for("WORKFLOW_USE_STEP")]("step"); From 2f331e9d2664ea1e81ce29c3d2b7ac142f4b0138 Mon Sep 17 00:00:00 2001 From: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> Date: Tue, 25 Aug 2026 16:13:29 -0700 Subject: [PATCH 5/5] Trace replay event loading Signed-off-by: Nathan Colosimo <110621881+NathanColosimo@users.noreply.github.com> --- .changeset/trace-replay-phases.md | 2 +- packages/core/src/runtime-trace-mode.test.ts | 11 ++ packages/core/src/runtime.ts | 59 ++++-- packages/core/src/runtime/helpers.ts | 184 +++++++++--------- .../src/telemetry/semantic-conventions.ts | 9 + packages/core/src/workflow.ts | 4 +- 6 files changed, 155 insertions(+), 114 deletions(-) diff --git a/.changeset/trace-replay-phases.md b/.changeset/trace-replay-phases.md index 96334a0ae5..6ec248ced6 100644 --- a/.changeset/trace-replay-phases.md +++ b/.changeset/trace-replay-phases.md @@ -2,4 +2,4 @@ "@workflow/core": patch --- -Trace workflow VM creation, bundle compilation and evaluation, input hydration, and replay execution. +Trace event loading, workflow VM creation, bundle compilation and evaluation, input hydration, and replay execution. diff --git a/packages/core/src/runtime-trace-mode.test.ts b/packages/core/src/runtime-trace-mode.test.ts index 8f71a1d2b6..22721b4961 100644 --- a/packages/core/src/runtime-trace-mode.test.ts +++ b/packages/core/src/runtime-trace-mode.test.ts @@ -314,6 +314,17 @@ describe('workflowEntrypoint trace modes', () => { runStartedCreateEvent?.attributes['workflow.run_started.skip_preload'] ).toBe(false); + const replayLoadSpan = exporter + .getFinishedSpans() + .find((finished) => finished.name === 'workflow.replay.load'); + expect(replayLoadSpan?.parentSpanId).toBe( + workflowSpan?.spanContext().spanId + ); + expect(replayLoadSpan?.attributes).toMatchObject({ + 'workflow.replay.load.source': 'run_started', + 'workflow.events.count': 0, + }); + // Queue-delivered invocation spans use the CONSUMER kind, matching // queue-delivered step.execute spans. expect(workflowSpan?.kind).toBe(SpanKind.CONSUMER); diff --git a/packages/core/src/runtime.ts b/packages/core/src/runtime.ts index 426fdcc14e..6cc4ce4415 100644 --- a/packages/core/src/runtime.ts +++ b/packages/core/src/runtime.ts @@ -969,6 +969,24 @@ export function workflowEntrypoint( return result; }; + const traceReplayLoad = ( + source: Attribute.WorkflowReplayLoadSource, + load: () => Promise + ): Promise => + trace('workflow.replay.load', async (loadSpan) => { + loadSpan?.setAttributes({ + ...Attribute.WorkflowRunId(runId), + ...Attribute.WorkflowReplayLoadSource(source), + }); + const result = await load(); + loadSpan?.setAttributes( + Attribute.WorkflowEventsCount( + result.events?.length ?? 0 + ) + ); + return result; + }); + /** * The slot snapshot for a write issued from this loop: how * much of the run's log the decision behind it was made @@ -2034,23 +2052,25 @@ export function workflowEntrypoint( span?.addEvent('workflow.hook_received.create.start', { 'workflow.hook_received.preload_events': true, }); - const result = await createEvent( - { - eventType: 'hook_received', - specVersion: SPEC_VERSION_CURRENT, - correlationId: hookResumeInput.hookId, - eventData: { - token: hookResumeInput.token, - payload: hookResumeInput.payload, + const result = await traceReplayLoad('hook_preload', () => + createEvent( + { + eventType: 'hook_received', + specVersion: SPEC_VERSION_CURRENT, + correlationId: hookResumeInput.hookId, + eventData: { + token: hookResumeInput.token, + payload: hookResumeInput.payload, + }, }, - }, - { - requestId, - occurredAt, - resumeId: hookResumeInput.resumeId, - resumePayloadDigest: hookResumeInput.payloadDigest, - preloadEvents: true, - } + { + requestId, + occurredAt, + resumeId: hookResumeInput.resumeId, + resumePayloadDigest: hookResumeInput.payloadDigest, + preloadEvents: true, + } + ) ); hookEnsured = true; // Note: unlike the re-ensure below, this hoisted write @@ -2324,9 +2344,10 @@ export function workflowEntrypoint( span?.addEvent('workflow.run_started.create.start', { 'workflow.run_started.skip_preload': false, }); - const result = await createEvent(runStartedEvent, { - requestId, - }); + const result = await traceReplayLoad( + 'run_started', + () => createEvent(runStartedEvent, { requestId }) + ); workflowRun = result.run; maxEventsLimit = clampMaxEvents(result.maxEvents); // Anchors RSFS, see the declaration above. diff --git a/packages/core/src/runtime/helpers.ts b/packages/core/src/runtime/helpers.ts index 8c7a4ce530..5f28ca0af3 100644 --- a/packages/core/src/runtime/helpers.ts +++ b/packages/core/src/runtime/helpers.ts @@ -597,108 +597,108 @@ export async function loadWorkflowRunEvents( afterCursor?: string ): Promise { const incremental = afterCursor !== undefined; - return trace( - incremental ? 'workflow.loadNewEvents' : 'workflow.loadEvents', - async (span) => { - span?.setAttributes({ - ...Attribute.WorkflowRunId(runId), - }); - - const loadedEvents: Event[] = []; - const loadedEventIds = new Set(); - const requestedCursors = new Set(); - let cursor: string | null = afterCursor ?? null; - let hasMore = true; - let pagesLoaded = 0; - let retriedWithoutCursor = false; - - const world = await getWorldLazy(); - const loadStart = Date.now(); - while (hasMore) { - // TODO: we're currently loading all the data with resolveRef behavior. We need to update this - // to lazyload the data from the world instead so that we can optimize and make the event log loading - // much faster and memory efficient - const pageStart = Date.now(); - const requestedCursor = cursor; - recordRequestedEventCursor(runId, requestedCursor, requestedCursors); - - let response: Awaited>; - try { - response = await world.events.list({ - runId, - pagination: { - sortOrder: 'asc', - cursor: requestedCursor ?? undefined, - }, - }); - } catch (error) { - if ( - shouldRetryWithoutEventCursor( - error, - requestedCursor, - retriedWithoutCursor - ) - ) { - runtimeLogger.warn( - 'Event cursor was rejected; retrying with a full event reload.', - { workflowRunId: runId } - ); - loadedEvents.length = 0; - loadedEventIds.clear(); - requestedCursors.clear(); - cursor = null; - retriedWithoutCursor = true; - continue; - } - throw error; - } - - appendUniqueEvents(loadedEvents, response.data, loadedEventIds); - hasMore = response.hasMore; - assertEventPaginationProgress( + return trace('workflow.replay.load', async (span) => { + span?.setAttributes({ + ...Attribute.WorkflowRunId(runId), + ...Attribute.WorkflowReplayLoadSource( + incremental ? 'events_list_incremental' : 'events_list' + ), + }); + + const loadedEvents: Event[] = []; + const loadedEventIds = new Set(); + const requestedCursors = new Set(); + let cursor: string | null = afterCursor ?? null; + let hasMore = true; + let pagesLoaded = 0; + let retriedWithoutCursor = false; + + const world = await getWorldLazy(); + const loadStart = Date.now(); + while (hasMore) { + // TODO: we're currently loading all the data with resolveRef behavior. We need to update this + // to lazyload the data from the world instead so that we can optimize and make the event log loading + // much faster and memory efficient + const pageStart = Date.now(); + const requestedCursor = cursor; + recordRequestedEventCursor(runId, requestedCursor, requestedCursors); + + let response: Awaited>; + try { + response = await world.events.list({ runId, - hasMore, - response.cursor, - requestedCursors - ); - // Preserve the last non-null cursor across pages. A World may - // legitimately return `{ data: [], cursor: null, hasMore: false }` - // on a trailing empty page, for example when the previous page's - // underlying DB query hit the limit exactly and returned a - // precautionary `LastEvaluatedKey`. Overwriting with that null - // would lose the position past the last real event we loaded and - // force the runtime into the "no cursor after initial load" full- - // reload fallback on every subsequent replay iteration. - cursor = response.cursor ?? cursor; - pagesLoaded++; - - runtimeLogger.debug('Loaded event page', { - workflowRunId: runId, - incremental, - page: pagesLoaded, - pageEvents: response.data.length, - totalEvents: loadedEvents.length, - hasMore, - pageMs: Date.now() - pageStart, + pagination: { + sortOrder: 'asc', + cursor: requestedCursor ?? undefined, + }, }); + } catch (error) { + if ( + shouldRetryWithoutEventCursor( + error, + requestedCursor, + retriedWithoutCursor + ) + ) { + runtimeLogger.warn( + 'Event cursor was rejected; retrying with a full event reload.', + { workflowRunId: runId } + ); + loadedEvents.length = 0; + loadedEventIds.clear(); + requestedCursors.clear(); + cursor = null; + retriedWithoutCursor = true; + continue; + } + throw error; } - runtimeLogger.debug('Event load complete', { + appendUniqueEvents(loadedEvents, response.data, loadedEventIds); + hasMore = response.hasMore; + assertEventPaginationProgress( + runId, + hasMore, + response.cursor, + requestedCursors + ); + // Preserve the last non-null cursor across pages. A World may + // legitimately return `{ data: [], cursor: null, hasMore: false }` + // on a trailing empty page, for example when the previous page's + // underlying DB query hit the limit exactly and returned a + // precautionary `LastEvaluatedKey`. Overwriting with that null + // would lose the position past the last real event we loaded and + // force the runtime into the "no cursor after initial load" full- + // reload fallback on every subsequent replay iteration. + cursor = response.cursor ?? cursor; + pagesLoaded++; + + runtimeLogger.debug('Loaded event page', { workflowRunId: runId, incremental, + page: pagesLoaded, + pageEvents: response.data.length, totalEvents: loadedEvents.length, - pagesLoaded, - totalMs: Date.now() - loadStart, + hasMore, + pageMs: Date.now() - pageStart, }); + } - span?.setAttributes({ - ...Attribute.WorkflowEventsCount(loadedEvents.length), - ...Attribute.WorkflowEventsPagesLoaded(pagesLoaded), - }); + runtimeLogger.debug('Event load complete', { + workflowRunId: runId, + incremental, + totalEvents: loadedEvents.length, + pagesLoaded, + totalMs: Date.now() - loadStart, + }); - return { events: loadedEvents, cursor }; - } - ); + span?.setAttributes({ + ...Attribute.WorkflowEventsCount(loadedEvents.length), + ...Attribute.WorkflowEventsPagesLoaded(pagesLoaded), + }); + + return { events: loadedEvents, cursor }; + }); } /** diff --git a/packages/core/src/telemetry/semantic-conventions.ts b/packages/core/src/telemetry/semantic-conventions.ts index 8d14b6af48..cb445c7976 100644 --- a/packages/core/src/telemetry/semantic-conventions.ts +++ b/packages/core/src/telemetry/semantic-conventions.ts @@ -87,6 +87,15 @@ export const WorkflowBundleCompileCacheHit = SemanticConvention( 'workflow.bundle.compile.cache_hit' ); +/** Operation that supplied events to the current replay. */ +export type WorkflowReplayLoadSource = + | 'run_started' + | 'hook_preload' + | 'events_list' + | 'events_list_incremental'; +export const WorkflowReplayLoadSource = + SemanticConvention('workflow.replay.load.source'); + /** * Events the replay walked past that no consumer claimed, still held when the * replay stopped. diff --git a/packages/core/src/workflow.ts b/packages/core/src/workflow.ts index 743f5d1099..f138806fd9 100644 --- a/packages/core/src/workflow.ts +++ b/packages/core/src/workflow.ts @@ -1135,8 +1135,8 @@ async function createWorkflowSessionInner( // workflow function subscribing its first step callbacks. let args: unknown[] = []; workflowContext.promiseQueue = workflowContext.promiseQueue.then(async () => { - // Include any residual preparation that did not finish while the event log - // was streaming, plus VM-local deserialization, in the blocking boundary. + // Include any residual payload preparation plus VM-local deserialization + // in the blocking boundary. args = await trace('workflow.input.hydrate', async () => { const prepared = await replayPayloadCache.prepareWorkflowInput(workflowRun);