feat(core): measure hook-triggered time to resume - #3437
Conversation
🦋 Changeset detectedLatest commit: ae416cb The changes in this PR will be included in the next version bump. This PR includes changesets to release 20 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 ❌ Failed E2E Tests🐘 Local Postgres (1 failed)nextjs-webpack-stable-quickjs (1 failed):
E2E Test SummarySummary
Details by Category✅ ▲ Vercel Production
✅ 💻 Local Development
✅ 📦 Local Production
❌ 🐘 Local Postgres
✅ 🪟 Windows
✅ vercel-multi-region
|
📊 Workflow Benchmarkscommit Backend:
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 179622ms → this run 176355ms (Δ -3267ms, -2%) 📜 Previous results (3)a27474aTue, 11 Aug 2026 19:06:07 GMT · run logs
9b75a61Tue, 11 Aug 2026 15:43:09 GMT · run logs
2346afaMon, 10 Aug 2026 23:45:52 GMT · run logs
ℹ️ Metric definitions & methodologyThe 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: Best/P75/P90/P99 deltas compare against the most recent benchmark run on Metrics — TTFS: time to first step body (in-deployment start() → first step body, deployment clocks) · 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 · 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 ( Cold starts are kept in the numbers on purpose — they are part of real bursty-workload latency. The workbench deployment cold-starts the |
Sim WorldSimulated world deterministic testing for races. Traces 🟠 Mint-ordered log — 6 fail of 41 total
Full trace: 🟢 Append-only log — 0 fail of 41 total
Full trace: |
a27474a to
cc1a14c
Compare
TooTallNate
left a comment
TooTallNate
left a comment
There was a problem hiding this comment.
Reviewed at cc1a14c (based on current main, 0 behind). Full core suite green locally (93 files, 2105 passed / 3 expected fail), including the 66 TTR-specific tests.
Verified — the properties the design claims:
- The phase sum telescopes exactly: total = T7−T0 and the phases are consecutive differences, so sum-equals-total holds by construction — including the optimistic-start case where T6 doesn't exist and
step_preparespans T5→T7 rather than inventing a claim-completion instant. Dropping a non-monotonic set instead of clamping is the right call for a decomposition whose whole value is that the phases are trustworthy; the one skew direction that can't be detected (consumer clock ahead inflatingqueue_delivery) is inherent to any cross-machine measurement. - The re-route attribution is exact, not approximate — this was my main verification target given the deployment-affinity work. All three forwarding sites carry
hookResumeTimingverbatim with the right phase in mind: the misrouted-flow re-routes forward it unmodified (no T2 stamp) so the extra hop lands inqueue_deliveryand T2 is the final consumer's entry; the step re-route keeps its hop insidestep_dispatch. The comments at each site say exactly why. - One resumption, one sample: the
reportedlatch is shared across an inline batch and set only on successful emission, so the sample isn't pinned to a step that loses its create-claim, retries are excluded (attempt !== 1), and a resumption whose boundaries never validate emits nothing rather than something wrong. The dispatched-step handoff (resumeTimingForMessage→ message →resumeTrackingFromMessage) round-trips verbatim, with a test pinning it. - The schema has internalized the capabilities-schema lesson:
.catch(undefined)on the payload field with the burn-the-delivery-budget rationale written down,strategy/setupSourceas plain strings so a future producer's value can't fail the invocation parse, and the three-direction rolling-deploy compatibility stated explicitly. TheNaNplaceholder for a producer-only message is delicate but fail-closed —validateBoundariesrejects it if the overwrite ever doesn't happen, and there's a test for exactly that. - T0 opens at both public entry points (API and webhook handler), with the comment explaining why the webhook path must include its by-token lookup — otherwise webhook resumes would systematically under-report into the same metric. The
event_loadhonest-default dimension being documented as not-currently-produced rather than silently dead is a nice touch.
One ask: the @workflow/world changeset should be minor, not patch — HookResumeTimingSchema/HookResumeTiming are new exported API and hookResumeTiming is new wire surface, same class as the deploymentId field which shipped as minor.
CI: only the ubiquitous python-workbench baseline deploy failure. Test coverage hits every edge I went looking for (sum exactness, claim omission, inversion drop, zero-length phases, old-producer/old-consumer compat).
This closes the observability gap between resumeHook() and the ttfs/rsfs work — the resume path was the last leg without a decomposition. Approving.
Report end-to-end TTR for a hook resumption — entry into the public resume
API through to the first line of the next durable step — on that step's
`step.execute` span, decomposed into non-overlapping phases that sum
exactly to the total:
workflow.resume.total_ms
workflow.resume.phase.{producer_prep,queue_delivery,resume_setup,
replay,step_dispatch,step_claim,step_prepare}_ms
dimensioned by trigger, dispatch strategy, setup source, and whether the
step ran inline or was dispatched to another invocation.
T0 is stamped by whichever public entry point the caller used, so
`resumeWebhook` — which does its own by-token lookup and key resolution
before reaching the shared implementation — measures the same window as
`resumeHook` rather than a systematically shorter one. T7 is taken inside
`contextStorage.run`, immediately before `stepFn.apply()`, so the
`step_prepare` phase covers the step-context setup it is defined to cover.
`resumeHook()` puts the producer boundaries on an optional
`hookResumeTiming` field on the queue message (both dispatch paths); the
consuming invocation adds its own and hands them to the execution that
will actually ATTEMPT the next durable step. That decision is made against
the dispatch loop's own classification, so an owned-recovery step keeps
the measurement here instead of it riding off on a queued sibling, and a
step converted into a delayed backstop wake — which this delivery does not
attempt — never takes it. Within an inline batch the tracking is shared
and a one-shot latch picks the single step that reaches user code, so the
sample survives the batch's first step losing its create-claim. A
deployment-affinity re-route forwards the timing untouched, keeping the
wasted hop inside `queue_delivery`.
The field is optional in every direction (new producer/old consumer, new
consumer/old message, no workflow-server change) and parses with
`.catch(undefined)` so a malformed value can never fail a delivery. A
sample is emitted only when every required boundary is present, finite,
and monotonic — a skewed or incomplete set is dropped rather than
reported as a negative phase.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
No backport to This is feature work: it adds a new OTEL telemetry surface ( To override, re-run the Backport to stable workflow manually via |
2 participants
Adds SDK-side OTEL telemetry for hook-triggered time-to-resume, so we can see where the latency between
resumeHook()and the next step actually goes.workflow.resume.total_ms— entry into the public resume API → the first line of the next durable step — plus a non-overlapping phase breakdown that sums exactly to it:producer_prep·queue_delivery·resume_setup·replay·step_dispatch·step_claim·step_prepareDimensioned by
trigger,strategy(parallel/sequential),setup_source, andstep_execution(inline/dispatched). All on the first step'sstep.executespan — one resumption, one sample.The boundaries travel on a new optional
hookResumeTimingfield on the queue message. No workflow-server change; the field is optional in both directions and parses with.catch(undefined)so a malformed value can't fail a delivery. A sample is emitted only when every boundary is present, finite, and monotonic — a clock-skewed set is dropped rather than reported as a negative phase.