Uh oh!
There was an error while loading. Please reload this page.
Trace /flow route initialization - #2592
Conversation
🦋 Changeset detectedLatest commit: c9b83f3 The changes in this PR will be included in the next version bump. This PR includes changesets to release 16 packages
Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
🧪 E2E Test Results❌ Some tests failed Summary
❌ Failed Tests▲ Vercel Production (1 failed)nuxt (1 failed):
Details by Category❌ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
✅ 🐘 Local Postgres
✅ 🪟 Windows
✅ 📋 Other
❌ Some E2E test jobs failed:
Check the workflow run for details. |
📊 Benchmark Results
workflow with no steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) workflow with 1 step💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) workflow with 10 sequential steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) workflow with 25 sequential steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express workflow with 50 sequential steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) Promise.all with 10 concurrent steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express Promise.all with 25 concurrent steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express Promise.all with 50 concurrent steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express Promise.race with 10 concurrent steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express Promise.race with 25 concurrent steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express Promise.race with 50 concurrent steps💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) workflow with 10 sequential data payload steps (10KB)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express workflow with 25 sequential data payload steps (10KB)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) workflow with 50 sequential data payload steps (10KB)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) workflow with 10 concurrent data payload steps (10KB)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express workflow with 25 concurrent data payload steps (10KB)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) workflow with 50 concurrent data payload steps (10KB)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) Stream Benchmarks(includes TTFB metrics)workflow with stream💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) stream pipeline with 5 transform steps (1MB)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Next.js (Turbopack) | Express 10 parallel streams (1MB each)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) fan-out fan-in 10 streams (1MB each)💻 Local Development
▲ Production (Vercel)
🔍 Observability: Express | Next.js (Turbopack) SummaryFastest Framework by WorldWinner determined by most benchmark wins
Fastest World by FrameworkWinner determined by most benchmark wins
Column Definitions
Worlds:
|
pranaygp
left a comment
There was a problem hiding this comment.
Reviewed the diff in depth — runtime span wiring, the builders codegen across all three generated route templates (workflow-only bundleFinal, combined, and watch-mode combined) plus the sveltekit/astro regex post-processing, the new semantic conventions, and the tests.
The instrumentation is clean, well-scoped, and well-tested. The span-hierarchy change (workflow.execute now nests under workflow.route.flow) is correctly reflected in the linked-mode tests and doesn't regress continuous mode (it still parents to the run-origin via withTraceContext). All three codegen templates declare workflowRouteModuleBodyStartedAt and reference it via the new options, and the sveltekit/astro regex ([^)]* capture) still matches the variable-reference options. CI E2E is fully green.
Main suggestion (re: the turbo-mode question): there is no dedicated turbo span attribute — turbo is only inferable from the workflow.run_started.skip_preloadevent. Recommend adding a workflow.turbo tag on workflow.execute so runs/invocations are trivially filterable by turbo mode (details inline). Everything else is minor/optional; nothing blocking.
| skipPreload: boolean | ||
| ) => { | ||
| span?.addEvent('workflow.run_started.create.start', { | ||
| 'workflow.run_started.skip_preload': skipPreload, |
There was a problem hiding this comment.
Turbo mode is only observable indirectly here. This workflow.run_started.skip_preload event attribute is currently the only turbo signal on the trace, and it's an awkward proxy for "is this run in turbo mode?":
- It's a span event attribute, not a span tag, so it's harder to facet/filter on in most backends (Datadog, etc.).
- The name
skip_preloaddoesn't say "turbo" — someone asking the turbo question wouldn't know to look here. - The event is only emitted when
run_started.createruns (first delivery). On redeliveries/replays (attempt > 1) there's no event at all, so those invocations carry no turbo signal.
turbo is already computed once per invocation at line 535 (and since turbo requires runInput, this skipPreload=true branch is exactly turbo). Consider also setting a dedicated tag on the workflow.execute span — e.g. right after the turbo constant is computed, where span is in scope:
span?.setAttributes(Attribute.WorkflowTurbo(turbo));backed by a new export const WorkflowTurbo = SemanticConvention<boolean>('workflow.turbo'). That puts a boolean turbo tag on every workflow.execute span (true on the turbo first delivery, false on replays — which is the precise per-invocation distinction we want), and keeps the existing skip_preload event as the finer-grained marker.
There was a problem hiding this comment.
Addressed in c9b83f3: added a dedicated workflow.turbo semantic convention and set it on every workflow.execute span after the per-invocation turbo decision is computed. I kept the existing workflow.run_started.skip_preload event attribute as the lower-level marker for the run_started create call.
| ), | ||
| ...(routeModuleBodyInitMs === undefined | ||
| ? {} | ||
| : Attribute.WorkflowRouteModuleBodyInitMs(routeModuleBodyInitMs)), |
There was a problem hiding this comment.
routeModuleBodyInitMs is a process-level constant (computed once at entrypoint construction) but emitted on everyworkflow.route.flow span, so it's identical across all requests from a given instance. Fine for queryability — just noting it isn't per-request.
Also worth setting expectations on what it measures: the marker is captured at the top of the generated module body, i.e. afterimport { workflowEntrypoint } from 'workflow/runtime' has fully evaluated. So it won't capture the @workflow/core import/eval cost (the likely dominant cold-start contributor) and will typically read ~0 in the workflow-only template, where the only body work between the marker and the workflowEntrypoint() call is a string-literal assignment. The PR description already acknowledges this; flagging only so the attribute's usefulness isn't over-read.
There was a problem hiding this comment.
Updated the PR description to make this explicit: workflow.route.module_body_init_ms is computed once per route entrypoint, emitted on each request from that in-memory entrypoint, and starts after static ESM imports have already evaluated. No code change here since the behavior is intentional.
| return cachedHandler(req); | ||
| invocationCount += 1; | ||
| const handlerCached = cachedHandler !== undefined; | ||
| const spanKind = await getSpanKind('SERVER'); |
There was a problem hiding this comment.
Micro-nit (optional, fine to leave): getSpanKind('SERVER') plus the attributes object are now built on every flow request — including the warm path and when no OTEL SDK is registered — whereas previously the warm path was just return cachedHandler(req). The cost is negligible (awaiting an already-memoized once() promise; trace() awaits the same lazy values anyway), so no action needed; just calling it out since this route is perf-sensitive.
There was a problem hiding this comment.
Acknowledged. I left this as-is: the added warm-path work remains a memoized span-kind lookup plus attribute construction, and trace() already hits the same memoized OTel handles. Keeping the route-level span always available seems worth that small overhead for this incident path.
| }, | ||
| async (span) => { | ||
| if (!cachedHandler) { | ||
| cachedHandler = await trace('workflow.route.init', async () => { |
There was a problem hiding this comment.
Pre-existing behavior (not introduced by this PR), but now more visible in the spans: two concurrent requests on a cold instance can both observe cachedHandler === undefined and each run getWorldHandlers() + handler(), producing two workflow.route.init spans for a single instance (and handler_cached=false on both). Harmless — handlers are stateless and it's effectively last-write-wins — and the new test covers the sequential case. Not a blocker; just noting that under concurrency the span counts can briefly exceed the "once per warm instance" framing in the PR description.
There was a problem hiding this comment.
Good call. I updated the PR description to stop implying a strict once-per-instance invariant: it now says workflow.route.init is emitted when the cached handler is created, and that concurrent cold requests can briefly produce more than one init span because the pre-existing cache assignment is last-write-wins.
| if (options?.routeModuleBodyStartedAt) { | ||
| fields.push( | ||
| `routeModuleBodyStartedAt: ${options.routeModuleBodyStartedAt}` |
There was a problem hiding this comment.
routeModuleBodyStartedAt is interpolated raw here (unlike namespace, which is JSON.stringify'd) because it must emit a code identifier reference, not a string literal — correct by design, and the sole caller passes a hardcoded 'workflowRouteModuleBodyStartedAt'. Since this makes the param a code-injection surface if it's ever called with untrusted input, consider a one-line doc comment on the option noting the value must be a code identifier, not data.
There was a problem hiding this comment.
Addressed in c9b83f3: added a doc comment on routeModuleBodyStartedAt noting that it is emitted as a raw code identifier/expression in generated route files, not serialized data.
| ); | ||
| /** Route pattern for the request */ | ||
| export const HttpRoute = SemanticConvention<string>('http.route'); |
There was a problem hiding this comment.
Tiny organizational nit: http.route is defined here in the "Route attributes" block, while the other standard OTEL Http* conventions (HttpRequestMethod, HttpResponseStatusCode, UrlFull, …) are grouped together around lines 286–309. Consider moving it next to them for discoverability.
There was a problem hiding this comment.
Addressed in c9b83f3: moved HttpRoute down next to the other standard HTTP semantic convention helpers and left the workflow-specific route attributes grouped separately.
pranaygp
left a comment
There was a problem hiding this comment.
Approving. The workflow.turbo attribute (the main ask from the review) plus the smaller nits are all addressed in c9b83f3 — I'd independently prepared the same set of changes, so rather than push a duplicate commit (which would have collided on the identical WorkflowTurbo/HttpRoute additions) I verified your version instead.
What's now in:
workflow.turboboolean tag on theworkflow.executespan (Attribute.WorkflowTurbo(turbo)), so turbo invocations are trivially filterable —trueonly on the turbo first delivery,falseon replays/redeliveries. Complements the finer-grainedworkflow.run_started.skip_preloadevent.http.routeconvention regrouped with the other standard OTELHttp*conventions.- Doc comment on
createWorkflowEntrypointOptionsCode'srouteModuleBodyStartedAtnoting it's emitted raw as a code identifier (not data). workflow.turboassertion added to the linked-mode test.
Verified locally on c9b83f3 (built deps from source): @workflow/core + @workflow/builders typecheck clean, runtime-trace-mode.test.ts (11) and constants.test.ts (7) green. CI E2E was already fully green.
The earlier observations I left (module_body_init_ms being a per-process constant emitted on every span; tiny warm-path overhead; pre-existing concurrent cold-start init) are all non-blocking — fine as-is.
No backport to The core instrumentation in this PR builds directly on To override, re-run the Backport to stable workflow manually via |
…testing * origin/main: Trace /flow route initialization (#2592) Version Packages (beta) (#2591) feat(web): add trace step shortcut helper (#2582) [web-shared] reskin json viewer (no duplicates, better colours and navigation) (#2434) Send occurredAt with workflow events (#2580) docs: use actual eve logo and tidy OSS nav dropdown (#2586) Display occurredAt in trace details (#2581) fix(next): discover root entrypoints (#2564) [core] Turbo: skip the unused run_started event-log preload (#2569) fix(next): prewarm SWC plugin cache (#2538) [world-vercel] Use v3 stream endpoint (supports transparent reconnect on timeout) (#2424) [core] Retry stream reopen against the reconnect budget (#2334) Add Platformatic World to worlds-manifest.json (#1450) docs: derive section landing-page cards from the page tree + lint drift (#2567)
* origin/main: (46 commits) [web] Fix HTTP/2 in bundled server build so observability reads work (#2632) [core] Fix turbo-mode step-body writes racing run_started (#2629) fix(world-postgres): rename setup command (#2644) chore: ignore workflow swc caches (#2640) fix(ai): ignore intentional stream aborts (#2635) fix(nitro): reload steps during Vite HMR (#2572) [world] Make @workflow/world own its Zod dependency (#2622) feat(web-shared): extend cn with custom tailwind-merge class groups (#2619) [world-vercel] Enable HTTP/2 for the events API and stream writes (#2573) Remove shadow from off-screen marker indicator button (#2614) Fix discovery of dotted JS workflow imports (#2594) Version Packages (beta) (#2597) Thread occurredAt into web-shared entities (#2608) Propagate trace context to vercel-workflow.com in workbench instrumentation (#2601) Reduce workflow build log noise (#2565) Version Packages (beta) (#2596) Use text-gray-900 for trace shortcut helper text (#2595) Trace /flow route initialization (#2592) Version Packages (beta) (#2591) feat(web): add trace step shortcut helper (#2582) ... # Conflicts: # workbench/nextjs-turbopack/instrumentation.ts # workbench/nextjs-webpack/instrumentation.ts
Summary
This instruments the Workflow SDK
/flowroute path so we can explain delay before the route makes its first workflow-serverrun_startedPOST.Instrumentation contract
workflow.route.flowNew server span around each generated
/flowroute request.Attributes:
workflow.route.type: currentlyflowworkflow.route.handler_cached: whether this invocation reused the in-memory route handlerworkflow.route.invocation_count: per-process invocation count for this route entrypointworkflow.route.entrypoint_age_ms: milliseconds sinceworkflowEntrypoint()constructed this route entrypointworkflow.route.module_body_init_ms: process-level milliseconds from the generated route module-body timestamp toworkflowEntrypoint()construction, when generated routes provide the timestamphttp.request.method: request methodhttp.route:/.well-known/workflow/v1/flowhttp.response.status_code: response status when the handler returns aResponseworkflow.route.initNew child span under
workflow.route.flow, emitted when the route creates the cached queue handler.Use this to separate first-hit handler construction from normal warm-route request handling. Under concurrent cold requests, more than one request can observe an empty cache and emit
workflow.route.init; that is pre-existing harmless last-write-wins behavior.workflow.route.get_world_handlersNew child span under
workflow.route.initaroundgetWorldHandlers().Use this to identify latency from loading/creating the world handler layer during route setup.
workflow.route.get_worldNew child span under
workflow.route.flow, emitted for each workflow invocation beforeworkflow.execute.Use this to identify latency from resolving the per-invocation world before SDK runtime work posts
run_started.workflow.execute <workflowName>Existing workflow execution span. This PR adds:
Attributes:
workflow.turbo: whether this invocation is using the turbo first-delivery pathSpan events:
workflow.run_started.create.start: emitted immediately beforeworld.events.create(... run_started ...), i.e. right before the first workflow-serverrun_startedPOST beginsEvent attributes:
workflow.run_started.skip_preload: whether therun_startedcreate call is using the turboskipPreloadpathReading the signal
workflow.route.flowstart toworkflow.run_started.create.start: SDK/runtime work before the first workflow-serverrun_startedPOST begins.workflow.route.module_body_init_ms: generated route module body work after static imports, before the SDK route handler is created. This value is computed once per route entrypoint and emitted on every request from that in-memory entrypoint.workflow.route.entrypoint_age_ms: the route entrypoint was just created for this request, so this request hit a cold SDK route instance.workflow.route.handler_cached=falseplusworkflow.route.init: the request paid route handler creation. Sequentially this happens once per warm instance; concurrent cold requests may briefly produce more than one init span.workflow.route.handler_cached=true: route handler was already created; delay is not from handler construction.workflow.turbo=true: this invocation is the turbo first-delivery path.workflow.run_started.skip_preload=trueis the finer-grained marker for the associatedrun_startedcreate call.Static ESM import evaluation still happens before generated route body code can run, so this does not directly measure the entire import graph. It gives us the earliest SDK-controlled marker in the generated
/flowmodule, plus the exact pre-run_startedmarker inside the SDK handler.Testing
PATH=/Users/karthikkalyanaraman/.nvm/versions/node/v24.13.1/bin:$PATH pnpm exec vitest run packages/core/src/runtime-trace-mode.test.ts packages/builders/src/constants.test.tsPATH=/Users/karthikkalyanaraman/.nvm/versions/node/v24.13.1/bin:$PATH pnpm --filter @workflow/core typecheckPATH=/Users/karthikkalyanaraman/.nvm/versions/node/v24.13.1/bin:$PATH pnpm --filter @workflow/builders typecheckPATH=/Users/karthikkalyanaraman/.nvm/versions/node/v24.13.1/bin:$PATH pnpm exec biome check .changeset/flow-route-init-traces.md packages/builders/src/base-builder.ts packages/builders/src/constants.ts packages/builders/src/constants.test.ts packages/core/src/runtime.ts packages/core/src/runtime-trace-mode.test.ts packages/core/src/telemetry/semantic-conventions.ts(exit 0; reports existing complexity/unused-suppression warnings)@workflow/coresuite under Node 24: all 1322 tests passed, but Vitest exited 1 due an existing pending-fetch shutdown error;packages/core/src/abort-controller-step.test.tspassed by itself.