Skip to content

[core] Record step execution duration metric - #3526

Open
shalabhc wants to merge 1 commit into
mainfrom
identify-datadog-span-duration-metrics
Open

[core] Record step execution duration metric#3526
shalabhc wants to merge 1 commit into
mainfrom
identify-datadog-span-duration-metrics

Conversation

@shalabhc

@shalabhc shalabhc commented Aug 13, 2026

Copy link
Copy Markdown
Collaborator

Summary

  • record workflow.step.execute.duration as an OpenTelemetry histogram around the inner user-code step span
  • rely on resource service.name for the service dimension and add only a bounded status attribute
  • cover the histogram name, unit, and attributes with a focused unit test

Validation

  • pnpm exec vitest run packages/core/src/telemetry-metrics.test.ts
  • pnpm --filter @workflow/core typecheck

Co-Authored-By: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com>
@changeset-bot

changeset-bot Bot commented Aug 13, 2026

Copy link
Copy Markdown

⚠️ No Changeset found

Latest commit: 0287155

Merging this PR will not cause a version bump for any packages. If these changes should not result in a new version, you're good to go. If these changes should result in a version bump, you need to add a changeset.

This PR includes no changesets

When changesets are added to this PR, you'll see the packages that this PR includes changesets for and the associated semver types

Click here to learn what changesets are, and how to add one.

Click here if you're a maintainer who wants to add a changeset to this PR

@vercel

vercel Bot commented Aug 13, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

Project Deployment Actions Updated (UTC)
example-nextjs-workflow-turbopack Ready Ready Preview Aug 13, 2026 8:38pm
example-nextjs-workflow-webpack Ready Ready Preview Aug 13, 2026 8:38pm
example-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-astro-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-express-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-fastify-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-hono-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-nestjs-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-nitro-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-nuxt-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-python-workflow Error Error Aug 13, 2026 8:38pm
workbench-sveltekit-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-tanstack-start-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workbench-vite-workflow Ready Ready Preview Aug 13, 2026 8:38pm
workflow-docs Ready Ready Preview, v0 Aug 13, 2026 8:38pm
workflow-swc-playground Ready Ready Preview Aug 13, 2026 8:38pm
workflow-tarballs Ready Ready Preview Aug 13, 2026 8:38pm
workflow-web Ready Ready Preview Aug 13, 2026 8:38pm

@github-actions

github-actions Bot commented Aug 13, 2026

Copy link
Copy Markdown
Contributor

📊 Workflow Benchmarks

commit 0287155 · Thu, 13 Aug 2026 20:57:01 GMT · run logs

Backend: vercel · app: nextjs-turbopack

Metric Scenario Best (ms) P75 (ms) P90 (ms) P99 (ms) Samples
TTFS step 262 (+42%) 🔻 1391 🔴 (+26%) 🔻 1418 🔴 (+17%) 🔻 1486 🔴 (-6.6%) 30
TTFS stream 234 (-1.3%) 1403 🔴 (+27%) 🔻 1425 🔴 (+25%) 🔻 1468 🔴 (+22%) 🔻 30
TTFS hook + stream 442 (+15%) 🔻 1678 🔴 (+22%) 🔻 1746 🔴 (+25%) 🔻 1835 🔴 (+20%) 🔻 30
Fan-out TTFS Promise.all(100 steps) 9107 (+1.0%) 10476 (+1.2%) 10715 (-11%) 11193 (-96%) 💚 10
Fan-out TTLS Promise.all(100 steps) 17466 (-1.6%) 19157 (-6.6%) 19813 (-71%) 💚 21056 (-93%) 💚 10
STSO 1020 steps (inline) 140 (-7.3%) 189 (-16%) 💚 220 (-15%) 340 (-35%) 💚 1019
WO 1020 steps 188071 (-18%) 💚 188071 (-18%) 💚 188071 (-18%) 💚 188071 (-18%) 💚 1
SL stream latency 98 (+4.3%) 381 🔴 (+154%) 🔻 462 🔴 (+187%) 🔻 5193 🔴 (+1367%) 🔻 30
SO stream overhead (text) 137 (-13%) 265 🔴 (-10%) 486 (+12%) 4163 🔴 (+177%) 🔻 30
SO stream overhead (structured) 127 (+7.6%) 344 🔴 (-15%) 💚 366 (-34%) 💚 812 (-68%) 💚 30
📈 STSO distribution vs main (inline / queue-hop histograms)

1020 steps (inline)

Cumulative STSO time: main 228513ms → this run 186682ms (Δ -41831ms, -18%)

  100-150 ms  ┃                         main   0  this  40   +40
  150-200 ms  ███████████████░░░░░░░░┃  main 512  this 805  +293
  200-250 ms  ███┃███████               main 385  this 124  -261
  250-300 ms  ┃█                        main  71  this  24   -47
  300-350 ms  ┃                         main  22  this  17    -5
  350-400 ms  ┃                         main  11  this   6    -5
  400-450 ms  ┃                         main   5  this   0    -5
  450-500 ms  ┃                         main   1  this   1    +0
  500-550 ms  ┃                         main   4  this   0    -4
  600-650 ms  ┃                         main   1  this   0    -1
  650-700 ms  ┃                         main   1  this   0    -1
  800-850 ms  ┃                         main   0  this   1    +1
  900-950 ms  ┃                         main   1  this   0    -1
1000-1050 ms  ┃                         main   0  this   1    +1
1200-1250 ms  ┃                         main   1  this   0    -1
1600-1650 ms  ┃                         main   1  this   0    -1
2000-2050 ms  ┃                         main   1  this   0    -1
2400-2450 ms  ┃                         main   1  this   0    -1
6050-6100 ms  ┃                         main   1  this   0    -1
ℹ️ Metric definitions & methodology

The collapsed STSO distribution section above buckets every step gap of the sequential-steps run (not a sampled window), split by whether the step ending the gap ran inline — in the same warm process as the step before it, so the gap is pure framework overhead — or after a queue-hop — the first step of a fresh process, which pays queue dispatch, client reinit and event-log replay. Bars overlay the two runs: is main, marks where this run lands, bridges the gap when this run has more samples in a bucket.

Best/P75/P90/P99 deltas compare against the most recent benchmark run on main at the time of this run. 🔻 flags a delta worse than +15%, 💚 one better than −15%.

Metrics — TTFS: time to first step body (in-deployment start() → first step body, deployment clocks) · Fan-out TTFS: fan-out time to first step (in-deployment start() → first of the parallel step bodies to complete) · Fan-out TTLS: fan-out time to last step (in-deployment start() → last of the parallel step bodies to complete, i.e. when the Promise.all resolves) · STSO: step-to-step overhead (gap between consecutive step bodies) · WO: workflow overhead (whole-run time outside step bodies, in-deployment anchored) · SL: stream latency (in-deployment write → read propagation, readAt - writtenAt) · SO: stream overhead (end-to-end write+consume time beyond the modelled generation window)

Scenarios — step: one trivial no-op step, no stream; no hooks, so the run stays in turbo mode (in-process fast path) · stream: one streaming step; no hooks, so the run stays in turbo mode (in-process fast path) · hook + stream: registers a hook before one step, which exits turbo mode (dispatch path) · 1020 steps: 1020 trivial sequential steps; STSO is measured between consecutive steps in the given step ranges, and WO is the whole-run overhead outside step bodies · Promise.all(100 steps): 100 trivial no-op steps started together in a single Promise.all; Fan-out TTFS is the first of them to complete and Fan-out TTLS the last, both from the in-deployment clientStart, so their gap is the spread the runtime adds across the fan-out · stream latency: parallel reader/writer steps on a dedicated stream; SL is the in-deployment write->read propagation (readAt - writtenAt) · stream overhead (text): writer streams 300 variable-length text token deltas paced at 100/s for 3s (a haiku-size LLM's token throughput) while a parallel reader drains the whole stream; SO is the end-to-end write+consume time beyond the 3s generation window (overhead/backpressure) · stream overhead (structured): same workload as stream overhead (text), but each delta is an AI-SDK-style structured object ({ type: 'text-delta', id, text }) instead of a raw string, so the SO gap vs the text scenario is the added serialization cost

🔴 marks a percentile over its target (within target is left unmarked). Targets (p75/p90/p99, ms) — TTFS 200/300/600 · SL 50/60/125 · SO 250/500/1000

All metrics are measured from deployment-side timestamps only. Runs are triggered by an in-deployment route that stamps the anchor (clientStart) right before start(), so the CI runner’s request and its path through api.vercel.com sit outside every measured window. TTFS = in-deployment start() → first step body (turbo uses the in-process fast path, non-turbo the dispatch path), and includes the VQS dispatch hop plus any /flow cold start. Fan-out TTFS/TTLS are the first and last step completions of a single Promise.all over trivial steps, from the same anchor, so the gap between the two rows is the spread the runtime adds across the fan-out. STSO/WO are measured between step bodies on the deployment. SL is measured inside the workflow (parallel reader/writer steps), so it no longer includes the api.vercel.com read path.

Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the /flow invocation for a large fraction of runs, inflating P75+; the Best column shows the fastest (warm-start) sample for comparison.

@github-actions

github-actions Bot commented Aug 13, 2026

Copy link
Copy Markdown
Contributor

🧪 E2E Test Results

Some tests failed

❌ Failed E2E Tests

💻 Local Development (1 failed)

nextjs-webpack-stable-node (1 failed):

  • plainModuleDoneHook resumed via plain API route (o2flow shape) | wrun_41KZYED31A0GPKQNKKMNKFD1H6

E2E Test Summary

Summary
Passed Failed Skipped Total
✅ ▲ Vercel Production 3466 0 590 4056
❌ 💻 Local Development 3672 1 539 4212
✅ 📦 Local Production 3810 0 558 4368
✅ 🐘 Local Postgres 3810 0 558 4368
✅ 🪟 Windows 312 0 0 312
✅ vercel-multi-region 27 0 0 27
Total 15097 1 2245 17343
Details by Category

✅ ▲ Vercel Production

App Passed Failed Skipped
✅ astro-node 128 0 28
✅ astro-quickjs 128 0 28
✅ example-node 128 0 28
✅ example-quickjs 128 0 28
✅ express-node 128 0 28
✅ express-quickjs 128 0 28
✅ fastify-node 128 0 28
✅ fastify-quickjs 128 0 28
✅ hono-node 128 0 28
✅ hono-quickjs 128 0 28
✅ nest-node 128 0 28
✅ nest-quickjs 128 0 28
✅ nextjs-turbopack-node 153 0 3
✅ nextjs-turbopack-quickjs 153 0 3
✅ nextjs-webpack-node 153 0 3
✅ nextjs-webpack-quickjs 153 0 3
✅ nitro-node 128 0 28
✅ nitro-quickjs 128 0 28
✅ nuxt-node 128 0 28
✅ nuxt-quickjs 128 0 28
✅ sveltekit-node 147 0 9
✅ sveltekit-quickjs 147 0 9
✅ tanstack-start-node 128 0 28
✅ tanstack-start-quickjs 128 0 28
✅ vite-node 128 0 28
✅ vite-quickjs 128 0 28

❌ 💻 Local Development

App Passed Failed Skipped
✅ astro-stable-node 130 0 26
✅ astro-stable-quickjs 130 0 26
✅ express-stable-node 130 0 26
✅ express-stable-quickjs 130 0 26
✅ fastify-stable-node 130 0 26
✅ fastify-stable-quickjs 130 0 26
✅ hono-stable-node 130 0 26
✅ hono-stable-quickjs 130 0 26
✅ nest-stable-node 130 0 26
✅ nest-stable-quickjs 130 0 26
✅ nextjs-turbopack-canary-node 137 0 19
✅ nextjs-turbopack-canary-quickjs 137 0 19
✅ nextjs-turbopack-stable-node 156 0 0
✅ nextjs-turbopack-stable-quickjs 156 0 0
✅ nextjs-webpack-canary-node 137 0 19
❌ nextjs-webpack-stable-node 155 1 0
✅ nextjs-webpack-stable-quickjs 156 0 0
✅ nitro-stable-node 130 0 26
✅ nitro-stable-quickjs 130 0 26
✅ nuxt-stable-node 130 0 26
✅ nuxt-stable-quickjs 130 0 26
✅ sveltekit-stable-node 149 0 7
✅ sveltekit-stable-quickjs 149 0 7
✅ tanstack-start-node 130 0 26
✅ tanstack-start-quickjs 130 0 26
✅ vite-stable-node 130 0 26
✅ vite-stable-quickjs 130 0 26

✅ 📦 Local Production

App Passed Failed Skipped
✅ astro-stable-node 130 0 26
✅ astro-stable-quickjs 130 0 26
✅ express-stable-node 130 0 26
✅ express-stable-quickjs 130 0 26
✅ fastify-stable-node 130 0 26
✅ fastify-stable-quickjs 130 0 26
✅ hono-stable-node 130 0 26
✅ hono-stable-quickjs 130 0 26
✅ nest-stable-node 130 0 26
✅ nest-stable-quickjs 130 0 26
✅ nextjs-turbopack-canary-node 137 0 19
✅ nextjs-turbopack-canary-quickjs 137 0 19
✅ nextjs-turbopack-stable-node 156 0 0
✅ nextjs-turbopack-stable-quickjs 156 0 0
✅ nextjs-webpack-canary-node 137 0 19
✅ nextjs-webpack-canary-quickjs 137 0 19
✅ nextjs-webpack-stable-node 156 0 0
✅ nextjs-webpack-stable-quickjs 156 0 0
✅ nitro-stable-node 130 0 26
✅ nitro-stable-quickjs 130 0 26
✅ nuxt-stable-node 130 0 26
✅ nuxt-stable-quickjs 130 0 26
✅ sveltekit-stable-node 149 0 7
✅ sveltekit-stable-quickjs 149 0 7
✅ tanstack-start-node 130 0 26
✅ tanstack-start-quickjs 130 0 26
✅ vite-stable-node 130 0 26
✅ vite-stable-quickjs 130 0 26

✅ 🐘 Local Postgres

App Passed Failed Skipped
✅ astro-stable-node 130 0 26
✅ astro-stable-quickjs 130 0 26
✅ express-stable-node 130 0 26
✅ express-stable-quickjs 130 0 26
✅ fastify-stable-node 130 0 26
✅ fastify-stable-quickjs 130 0 26
✅ hono-stable-node 130 0 26
✅ hono-stable-quickjs 130 0 26
✅ nest-stable-node 130 0 26
✅ nest-stable-quickjs 130 0 26
✅ nextjs-turbopack-canary-node 137 0 19
✅ nextjs-turbopack-canary-quickjs 137 0 19
✅ nextjs-turbopack-stable-node 156 0 0
✅ nextjs-turbopack-stable-quickjs 156 0 0
✅ nextjs-webpack-canary-node 137 0 19
✅ nextjs-webpack-canary-quickjs 137 0 19
✅ nextjs-webpack-stable-node 156 0 0
✅ nextjs-webpack-stable-quickjs 156 0 0
✅ nitro-stable-node 130 0 26
✅ nitro-stable-quickjs 130 0 26
✅ nuxt-stable-node 130 0 26
✅ nuxt-stable-quickjs 130 0 26
✅ sveltekit-stable-node 149 0 7
✅ sveltekit-stable-quickjs 149 0 7
✅ tanstack-start-node 130 0 26
✅ tanstack-start-quickjs 130 0 26
✅ vite-stable-node 130 0 26
✅ vite-stable-quickjs 130 0 26

✅ 🪟 Windows

App Passed Failed Skipped
✅ nextjs-turbopack-node 156 0 0
✅ nextjs-turbopack-quickjs 156 0 0

✅ vercel-multi-region

App Passed Failed Skipped
✅ nextjs-turbopack 27 0 0

📋 View full workflow run

@github-actions

Copy link
Copy Markdown
Contributor

Sim World

Simulated world deterministic testing for races. Traces

🟠 Mint-ordered log — 6 fail of 41 total

log=mint-ordered · fence=per-spec

scenario outcome events virt replay violations
smoke-no-steps completed 3 0ms ok 0
smoke-one-step completed 6 0ms ok 0
hook-at-step-started completed 12 0ms ok 0
hook-at-step-completed completed 12 0ms ok 0
hook-at-hook-created completed 12 0ms ok 0
deadline-hook-wins completed 7 1.0h ok 0
deadline-expires completed 7 1.0h ok 0
long-sleep completed 11 30.0d ok 0
hook-never-arrives stalled 3 0ms skipped 0
step-retries-twice completed 10 2.0s ok 0
parallel-steps completed 9 0ms ok 0
hook-on-execution-state completed 12 0ms ok 0
peek-hook-before-branch completed 12 0ms ok 0
peek-hook-after-branch completed 12 0ms ok 0
peek-hook-at-registration completed 12 0ms ok 0
race-hook-before-probe completed 12 0ms ok 0
race-hook-after-probe completed 12 0ms ok 0
race-duplicate-delivery completed 13 0ms ok 0
attr-hook-before-step completed 11 0ms ok 0
attr-hook-after-step completed 11 0ms ok 0
attr-from-step-body completed 13 0ms ok 0
fork-hook-after-timeout completed 14 1.0m ok 0
fork-hook-before-timeout completed 14 1.0m ok 0
count-hook-after-timeout completed 17 1.0m ok 0
count-hook-before-timeout completed 20 1.0m ok 0
stale-read-step-count-fork completed 17 1.0m MISMATCH 1
stale-read-equal-step-counts completed 14 1.0m MISMATCH 1
step-vs-step-fork completed 12 0ms MISMATCH 1
step-vs-step-fork-fenced completed 12 0ms MISMATCH 1
fence-catches-benign-direction completed 12 5ms ok 0
in-flight-before-decision completed 17 1.0m MISMATCH 1
in-flight-before-decision-counted completed 20 1.0m ok 0
in-flight-after-decision failed 14 2.0m MISMATCH 1
stale-read-step-count-fork-fenced completed 20 1.0m ok 0
fork-hook-wins completed 13 1.0m ok 0
fork-timeout-wins completed 13 1.0m ok 0
unclaimed-payload-under-fork completed 17 1.0m ok 0
claimed-payload-under-fork completed 17 1.0m ok 0
writers-independent-step-bodies completed 12 0ms ok 0
writers-scripted-tempo completed 12 0ms ok 0
cancel-mid-step cancelled 7 0ms skipped 0

Full trace: world-sim-mint.txt

🟢 Append-only log — 0 fail of 41 total

log=append-only · fence=per-spec

scenario outcome events virt replay violations
smoke-no-steps completed 3 0ms ok 0
smoke-one-step completed 6 0ms ok 0
hook-at-step-started completed 12 0ms ok 0
hook-at-step-completed completed 12 0ms ok 0
hook-at-hook-created completed 12 0ms ok 0
deadline-hook-wins completed 7 1.0h ok 0
deadline-expires completed 7 1.0h ok 0
long-sleep completed 11 30.0d ok 0
hook-never-arrives stalled 3 0ms skipped 0
step-retries-twice completed 10 2.0s ok 0
parallel-steps completed 9 0ms ok 0
hook-on-execution-state completed 12 0ms ok 0
peek-hook-before-branch completed 12 0ms ok 0
peek-hook-after-branch completed 12 0ms ok 0
peek-hook-at-registration completed 12 0ms ok 0
race-hook-before-probe completed 12 0ms ok 0
race-hook-after-probe completed 12 0ms ok 0
race-duplicate-delivery completed 13 0ms ok 0
attr-hook-before-step completed 11 0ms ok 0
attr-hook-after-step completed 11 0ms ok 0
attr-from-step-body completed 13 0ms ok 0
fork-hook-after-timeout completed 14 1.0m ok 0
fork-hook-before-timeout completed 14 1.0m ok 0
count-hook-after-timeout completed 17 1.0m ok 0
count-hook-before-timeout completed 20 1.0m ok 0
stale-read-step-count-fork completed 20 1.0m ok 0
stale-read-equal-step-counts completed 14 1.0m ok 0
step-vs-step-fork completed 12 0ms ok 0
step-vs-step-fork-fenced completed 12 0ms ok 0
fence-catches-benign-direction completed 12 5ms ok 0
in-flight-before-decision completed 17 1.0m ok 0
in-flight-before-decision-counted completed 17 1.0m ok 0
in-flight-after-decision completed 19 2.0m ok 0
stale-read-step-count-fork-fenced completed 20 1.0m ok 0
fork-hook-wins completed 13 1.0m ok 0
fork-timeout-wins completed 13 1.0m ok 0
unclaimed-payload-under-fork completed 17 1.0m ok 0
claimed-payload-under-fork completed 17 1.0m ok 0
writers-independent-step-bodies completed 12 0ms ok 0
writers-scripted-tempo completed 12 0ms ok 0
cancel-mid-step cancelled 7 0ms skipped 0

Full trace: world-sim-append-only.txt

@shalabhc
shalabhc marked this pull request as ready for review August 13, 2026 20:59
@shalabhc
shalabhc requested a review from a team as a code owner August 13, 2026 20:59

@karthikscale3 karthikscale3 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

looks good

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants