From 448ee394c516973b6e076d336520d71da0bf15c4 Mon Sep 17 00:00:00 2001 From: "vercel[bot]" <35613825+vercel[bot]@users.noreply.github.com> Date: Thu, 30 Jul 2026 21:52:15 +0000 Subject: [PATCH] [benchmarks] Add local inline-step STSO benchmark MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Measures step-to-step overhead for steps that run eagerly inline — many sequential steps inside a single flow-handler invocation, no queue hop. Runs against @workflow/world-local, so it needs no deployment (unlike packages/core/e2e/benchmark.test.ts). Findings at 1000 null steps (see RESULTS-1000.txt): - The in-process loop re-executes the workflow function once per step: 1000 steps => 1 flow invocation, 1001 replays, 3 events/step in the log. - STSO(i) ~= 7.3 ms + 0.074 ms * i. First few steps ~8 ms, step 1000 ~80 ms (~10x). Total is quadratic: 44 s, of which 35 s is replay and ~1 ms is step-body work. - Replay overtakes world I/O around step 15-20 and is ~80% of the gap past step 300. A step's return value doubles the slope, but not because of its size (RESULTS-payload-600.txt). ReplayPayloadCache memoizes the hydrated value only for primitives <= MAX_MEMOIZED_PRIMITIVE_LENGTH; everything else re-hydrates against each fresh VM realm. So a 4000-char string costs the same as returning nothing (0.028 ms/step) while a 5000-char string costs 0.074, and a 40-byte object costs the same as a 5 KB string. 15x the object payload moves the slope 7% — the penalty is mostly the per-hydration reviver-table construction, not decoding. Co-Authored-By: Claude Opus 5 (1M context) Signed-off-by: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com> Co-Authored-By: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com> --- .changeset/large-parrots-invite.md | 4 + pnpm-lock.yaml | 28 + workbench/inline-step-bench/.gitignore | 4 + workbench/inline-step-bench/README.md | 367 +++++++++ workbench/inline-step-bench/RESULTS-1000.txt | 284 +++++++ .../inline-step-bench/RESULTS-payload-600.txt | 221 ++++++ workbench/inline-step-bench/bench.mjs | 726 ++++++++++++++++++ workbench/inline-step-bench/package.json | 25 + workbench/inline-step-bench/server.mjs | 122 +++ .../inline-step-bench/workflows/null-steps.ts | 155 ++++ 10 files changed, 1936 insertions(+) create mode 100644 .changeset/large-parrots-invite.md create mode 100644 workbench/inline-step-bench/.gitignore create mode 100644 workbench/inline-step-bench/README.md create mode 100644 workbench/inline-step-bench/RESULTS-1000.txt create mode 100644 workbench/inline-step-bench/RESULTS-payload-600.txt create mode 100644 workbench/inline-step-bench/bench.mjs create mode 100644 workbench/inline-step-bench/package.json create mode 100644 workbench/inline-step-bench/server.mjs create mode 100644 workbench/inline-step-bench/workflows/null-steps.ts diff --git a/.changeset/large-parrots-invite.md b/.changeset/large-parrots-invite.md new file mode 100644 index 0000000000..2aeadec09a --- /dev/null +++ b/.changeset/large-parrots-invite.md @@ -0,0 +1,4 @@ +--- +--- + +Add `workbench/inline-step-bench`, a local benchmark for step-to-step overhead of eagerly inlined steps. No published package is affected. diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index faa3bf5768..de118a3c90 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -1848,6 +1848,34 @@ importers: specifier: 'catalog:' version: 4.3.6 + workbench/inline-step-bench: + dependencies: + '@hono/node-server': + specifier: 1.19.13 + version: 1.19.13(hono@4.12.25) + '@workflow/cli': + specifier: workspace:* + version: link:../../packages/cli + '@workflow/core': + specifier: workspace:* + version: link:../../packages/core + '@workflow/world': + specifier: workspace:* + version: link:../../packages/world + '@workflow/world-local': + specifier: workspace:* + version: link:../../packages/world-local + hono: + specifier: 4.12.25 + version: 4.12.25 + workflow: + specifier: workspace:* + version: link:../../packages/workflow + devDependencies: + '@types/node': + specifier: 'catalog:' + version: 22.19.0 + workbench/nest: dependencies: '@nestjs/common': diff --git a/workbench/inline-step-bench/.gitignore b/workbench/inline-step-bench/.gitignore new file mode 100644 index 0000000000..ce0a5d1eb9 --- /dev/null +++ b/workbench/inline-step-bench/.gitignore @@ -0,0 +1,4 @@ +.well-known +.workflow-data +.swc +results diff --git a/workbench/inline-step-bench/README.md b/workbench/inline-step-bench/README.md new file mode 100644 index 0000000000..e7fe2f6164 --- /dev/null +++ b/workbench/inline-step-bench/README.md @@ -0,0 +1,367 @@ +# inline-step-bench + +A local benchmark for **step-to-step overhead (STSO) when steps run eagerly +inline** — many sequential steps executed inside a *single* flow-handler +invocation, with no queue hop between them. + +It answers three questions: + +1. What does the runtime cost between two adjacent no-op steps in that regime? +2. Does the runtime really re-execute the whole workflow function, over the + whole event log, before every single step? +3. How does the cost of the 1000th step compare to the first few? + +Short answers: **~7 ms, yes, and ~10× worse.** + +--- + +## Running it + +```bash +pnpm install # from the repo root +pnpm --filter @workflow/inline-step-bench build # wf build → .well-known/ +pnpm --filter @workflow/inline-step-bench bench # 1000 steps, all scenarios + +# or directly, with knobs: +node bench.mjs --steps 300 +node bench.mjs --only replay-profile +node bench.mjs --steps 1000 --keep-data +``` + +`RESULTS-1000.txt` in this directory is the full output of a 1000-step run on +the machine described at the top of that file. Per-run JSON and per-step CSVs +are written to `results/`. + +A full `pnpm build` at the repo root needs Rust, because +`packages/swc-plugin-workflow` compiles its WASM transform with cargo. On a box +without cargo you can drop in the published artifact instead — it only has to +match the workspace version: + +```bash +npm pack @workflow/swc-plugin@ +tar xzf workflow-swc-plugin-*.tgz +cp package/swc_plugin_workflow.wasm package/build-hash.json packages/swc-plugin-workflow/ +# then skip that package's build task +``` + +## What's here + +| file | what it is | +| --- | --- | +| `workflows/null-steps.ts` | `timedNullStepsWorkflow(n)` and `voidNullStepsWorkflow(n)` — `n` sequential steps that do nothing | +| `server.mjs` | minimal local host (trimmed copy of `packages/world-testing/src/server.mts`): mounts the generated flow route, counts flow-handler invocations per run, exposes the run output and raw event log | +| `bench.mjs` | driver: spawns the server against `@workflow/world-local`, runs the workflow, computes STSO, and parses the runtime's own debug log for per-replay timings | + +## Method + +`timedNullStepsWorkflow(n)` is a `"use workflow"` function that awaits `n` +sequential `"use step"` calls. Each step body does nothing except stamp +`performance.now()` on entry and exit. Step bodies run in Node (not in the +workflow VM), so those clocks are real. + +``` +STSO[i] = t0[i] − t1[i−1] +``` + +i.e. the wall-clock between the end of one step body and the start of the next. +The bodies are empty, so **that gap is the runtime overhead** and nothing else: + +- append the previous step's `step_completed` to the event log, +- load the new events, +- build a fresh workflow VM context, +- **replay the workflow function from the top against the entire event log**, +- reach the next `await`, write `step_started` for the next step, +- run its body. + +Timings are also reconstructed independently from the event log +(`step_started` / `step_completed` `createdAt`) for the `void` variant, which +returns nothing at all, as a control against the sample array the timed variant +accumulates. + +Two env vars are raised so the whole chain stays in one invocation: +`WORKFLOW_V2_TIMEOUT_MS` (default 120 s of wall time) and +`WORKFLOW_REPLAY_TIMEOUT_MS` (default 240 s of non-step time). At 1000 steps on +world-local the run finishes in ~44 s, so the defaults would not have forced a +hop anyway. Extrapolating the quadratic fit below, the 120 s wall-clock limit +would bind at roughly 1700 steps — after which the chain *does* start paying +queue hops. + +### Caveats + +- **`@workflow/world-local` is a filesystem world.** Its per-event cost (one + JSON file per event, plus a `readdir`-backed cursor query) is not Vercel's + network cost. The *fixed* per-step term here is therefore not a prediction of + production latency. The *replay* term is CPU work that is identical wherever + it runs. +- `performance.now()` is meaningful across steps because everything happens in + one process. Event-log timestamps are `Date.now()`, i.e. 1 ms granularity. +- The `replay-profile*` scenarios enable `DEBUG=workflow:runtime:debug`. The + logging itself inflates STSO by roughly 5–10%, so the absolute STSO numbers + should be read off `turbo-on`; the replay decomposition should be read off + `replay-profile`. + +--- + +## Results (1000 null steps, world-local, 16-core Xeon @ 2.9 GHz, node 22) + +### 1. Every step really does replay every prior step + +``` +flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation +events in the log : 3003 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":1000,"step_created":1000,"step_completed":1000,"run_completed":1} +step bodies executed : 1000 (each exactly once) + +runtime replay log: 1001 in-process loop iterations + ✓ 1000 step-scheduling replays + 1 final replay that ran the workflow to completion +``` + +One invocation, no queue hop between steps, 1000 step bodies — and **1001 executions of +the workflow function**. Each one re-runs the loop from `i = 0` and re-consumes +the whole event log, which by then holds 3 events per completed step: + +``` + iterations events@end mean replayMs max replayMs + ──────────── ─────────── ────────────── ───────────── + 1–100 299 6.15 9.00 + 101–200 599 11.62 16.00 + 201–300 899 18.19 24.00 + 301–400 1199 25.68 50.00 + 401–500 1499 30.74 36.00 + 501–600 1799 37.86 61.00 + 601–700 2099 45.71 69.00 + 701–800 2399 51.91 84.00 + 801–900 2699 58.04 73.00 + 901–1000 2999 65.95 101.00 + 1001–1001 3002 120.00 120.00 +``` + +`replayMs` is the runtime's own measurement: from just before `runWorkflow()` to +the moment the suspension for the next step is caught. No world I/O, no step +body — pure replay. It rises **from ~6 ms to ~66 ms**, linear in event count: + +``` +replayMs ≈ 1.75 + 0.022 × eventCount (≈ 0.067 ms per already-completed step) +Σ replayMs = 35 305 ms out of a 45 032 ms run +``` + +This is by design, not a bug. `packages/core/src/runtime.ts` runs a +`while (true)` loop whose body calls `runWorkflow(workflowCode, workflowRun, +events, …)` with the *full* event array, and `packages/core/src/vm/script-cache.ts` +says it outright: + +> Replaying a workflow re-evaluates the workflow bundle against a fresh VM +> context on every iteration of the inline replay loop […] O(N) full re-parses +> for a sequential workflow of N steps + +(The compiled `vm.Script` is cached across replays; the *context* and the +*event replay* are not.) + +### 2. Step-to-step overhead vs. step index + +`turbo-on`, the shipped default config: + +``` + steps n mean p50 p90 min max +─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 14.00 14.00 14.00 14.00 14.00 + 2–10 9 8.32 8.06 9.09 7.51 10.53 + 11–50 40 9.99 9.86 11.56 8.38 12.16 + 51–100 50 12.90 12.72 14.06 10.82 22.66 + 101–200 100 19.05 18.99 23.43 13.24 28.25 + 201–300 100 25.71 25.37 28.87 20.45 45.16 + 301–400 100 33.36 32.26 37.36 26.46 52.48 + 401–500 100 41.11 40.03 45.15 34.16 68.53 + 501–600 100 47.96 47.92 51.68 42.06 78.91 + 601–700 100 55.10 54.08 58.13 49.00 81.27 + 701–800 100 61.56 61.55 65.83 54.46 71.26 + 801–900 100 69.89 69.08 75.81 63.32 100.11 + 901–999 99 80.08 77.68 89.15 72.51 140.93 +``` + +- **first few steps: ~8 ms** +- **around step 1000: ~80 ms** +- **ratio: ~10×** + +``` +STSO(i) ≈ 7.3 ms + 0.074 ms × i +``` + +The fit is the whole story: + +- **7.3 ms fixed** — two world writes (`step_started` carrying the input, which + the world turns into a synthetic `step_created` + `step_started`, then + `step_completed`) plus suspension bookkeeping and a fresh VM context. On + world-local this is filesystem cost; on Vercel it is two network round-trips. +- **0.074 ms × i marginal** — replaying the `i` steps already in the log. + +Total wall time is therefore **quadratic in step count**: 1000 null steps take +**44 s**, of which 35 s is replay and ~1 ms is actual step-body work. + +### 3. Where the gap goes + +`replay-profile` splits each gap into replay vs everything-else: + +``` + steps gap replay other replay% +─────────── ──────── ──────── ──────── ──────── + 1–1 8.90 2.00 6.90 22.48 + 2–10 7.36 3.11 4.25 42.25 + 11–50 10.30 5.25 5.05 50.95 + 51–100 12.75 7.52 5.23 58.99 + 101–200 17.56 11.68 5.88 66.50 + 201–300 25.30 18.26 7.04 72.17 + 301–400 34.46 25.76 8.70 74.76 + 401–500 39.57 30.79 8.78 77.80 + 501–600 47.86 37.94 9.92 79.28 + 601–700 56.96 45.77 11.19 80.35 + 701–800 65.03 51.95 13.08 79.88 + 801–900 71.98 58.11 13.87 80.73 + 901–999 81.14 66.02 15.12 81.36 +``` + +Replay overtakes world I/O at roughly **step 15–20** and is **~80% of the gap** +past step 300. (`other` also drifts up, 4 ms → 15 ms; that part is a +world-local artifact — its inline-delta cursor query does a `readdir` over a +directory that now holds 3000 event files. A network world would keep that term +roughly flat.) + +### 4. The step's return value doubles the slope — but *not* because of its size + +`void-steps` runs the identical chain with steps that return `undefined`: + +``` + scenario invocations STSO 1–10 STSO last10 growth fixed ms ms/step total ms +──────────────────── ──────────── ────────── ──────────── ──────── ───────── ───────── ────────── + turbo-on 1 8.89 87.78 9.88x 7.309 0.074 44437.27 + turbo-off 1 7.90 79.48 10.06x 5.551 0.077 43768.78 + void-steps 1 5.50 33.80 6.15x 4.412 0.029 21230.00 + replay-profile 1 7.52 85.77 11.41x 6.121 0.078 45031.89 + replay-profile-void 1 5.30 36.50 6.89x 4.561 0.032 22597.00 +``` + +Dropping a four-field object from each step's return value halves the marginal +cost (0.074 → 0.029 ms per prior step) and the total run (44 s → 21 s). + +The obvious reading — "bigger payloads cost more to re-deserialize" — is wrong. +`node bench.mjs --suite payload` (full output in `RESULTS-payload-600.txt`) runs +six identical 600-step chains that differ only in what the step returns: + +``` + scenario STSO 1–10 STSO last10 growth fixed ms ms/step total ms +──────────────────── ────────── ──────────── ──────── ───────── ───────── ────────── + void 5.60 22.20 3.96x 5.453 0.028 9964.00 + number 5.00 20.90 4.18x 4.818 0.028 9325.00 + str4000 5.20 21.60 4.15x 4.804 0.028 9469.00 + str5000 6.40 47.90 7.48x 4.817 0.074 17766.00 + obj4 5.40 48.60 9.00x 3.213 0.072 16423.00 + obj40 5.20 49.30 9.48x 4.549 0.077 18107.00 +``` + +| returns | payload | slope ms/step | +| --- | --- | --- | +| `undefined` | 0 B | 0.028 | +| a number | ~1 B | 0.028 | +| **a 4000-char string** | **4 KB** | **0.028** | +| **a 5000-char string** | **5 KB** | **0.074** | +| a 4-field object | ~40 B | 0.072 | +| a 40-field object | ~600 B | 0.077 | + +Read those pairs carefully: + +- A **4 KB string is exactly as cheap as returning nothing.** +- Making that string **25% longer** (4000 → 5000 chars) **multiplies the slope + by 2.6×.** +- A **40-byte object costs the same as a 5 KB string** — 100× less data, same + price. +- **15× the object payload** (obj4 → obj40) moves the slope by **7%**. + +Size is nearly irrelevant. The step function is 4096. + +### Why: the cache can memoize primitives but not object graphs + +The event log *is* fully in memory, and so are the payload bytes. What can't be +reused across replays is the **deserialized value**, because +`packages/core/src/workflow.ts` builds a **fresh VM context per replay** and an +object minted in one realm can't be handed to the next — its prototypes, its +revived `Workflow` objects, step proxies, streams, and registered class +instances all belong to the old realm's globals. + +`packages/core/src/replay-payload-cache.ts` splits the work along exactly that +line: + +> This cache keeps the VM-independent decrypt/decompress result across those +> replays. **Deserialization still runs against each VM's globals** so every +> replay receives fresh object graphs and correctly revived Workflow objects. + +So decrypt/decompress *is* cached (`preparedPayloads`), and on top of that there +is a second cache for final values — with a guard: + +```ts +async getStepResult(eventId, hydrate) { + if (this.primitiveStepResults.has(eventId)) return this.primitiveStepResults.get(eventId); + const value = await hydrate(); + if (isMemoizablePrimitive(value)) this.primitiveStepResults.set(eventId, value); + return value; +} +``` + +`isMemoizablePrimitive` is "not an object or function, and — for strings and +bigints — no longer than `MAX_MEMOIZED_PRIMITIVE_LENGTH = 4096`". Sharing a +primitive between realms is unobservable, so it's safe to memoize; the 4096 cap +bounds how much the memo table can pin for the invocation's lifetime. That +constant is the cliff the benchmark walks off between `str4000` and `str5000`. + +On a miss, `step.ts:299` re-runs the full hydrate for that step, on every +replay, via `deserializePreparedReplayPayload`: + +```ts +return workflowModule.deserialize(prepared.data, { + global, + extraRevivers: { ...getStreamAndRequestRevivers(getWorkflowRevivers(global)), ...extraRevivers }, +}); +``` + +`getWorkflowRevivers(global)` is not a constant — it *constructs* a table of +closures on every call (`{...getClassRevivers(global), ...getCommonReviversFromModule(global), +...getStepFunctionReviver(global), Request: …, WorkflowFunction: …}`), then +`getStreamAndRequestRevivers` builds another, then two more object spreads. All +of that is bound to `global`, so it can't be hoisted out of the per-replay, +per-step loop as long as the realm keeps changing. + +That explains the shape of the data: the ~0.045 ms/step penalty for an +unmemoizable value is **mostly fixed per-hydration setup**, not decoding. If it +were decoding, obj40 would cost ~15× obj4; it costs 7% more. + +### 5. Turbo mode is not what's driving this + +`WORKFLOW_TURBO=0` leaves the slope alone (0.074 vs 0.077 ms per prior step) and +moves the fixed term by less than run-to-run variance — across two full runs the +turbo-on/turbo-off intercepts came out 7.31/5.55 and 6.23/6.98 ms, i.e. the sign +flipped. That is expected here: turbo's per-step effect is forcing optimistic +inline start (running the body without awaiting `step_started`), and on +world-local that write is sub-millisecond. On a network world it would be a full +round-trip per step and would show. Turbo's real job is removing *start-up* +round-trips on the first delivery; it does not touch the replay loop. See +`docs/content/docs/v5/changelog/turbo-mode.md`, which also records the +deliberate decision *not* to run ahead of durable writes ("run-ahead") and why. + +--- + +## Takeaways + +- In the eager-inline regime the floor is **two world round-trips plus one full + replay per step**. Locally that floor is ~7 ms; on Vercel the fixed part is + network-bound and larger, but the replay part is the same CPU work. +- Replay cost is **O(events in the log)** per step, so a sequential chain is + **O(N²)** overall. At N = 1000 the last step pays ~10× the first. +- The practical knee is where replay overtakes the fixed cost. Locally that is + ~step 15–20. +- **A step's return value doubles the per-step replay slope when it is not a + memoizable primitive — and payload size barely matters.** `undefined`, a + number, and a 4000-char string are all 0.028 ms/step; a 4001-char string, a + 40-byte object, and a 600-byte object are all ~0.075. Returning a small + object is *more* expensive than returning 4 KB of string. +- Anything that shrinks the replayed log helps super-linearly: fewer/larger + steps, or splitting a long chain across child workflows. Shrinking a return + value only helps if it crosses back over the memoizable-primitive line. diff --git a/workbench/inline-step-bench/RESULTS-1000.txt b/workbench/inline-step-bench/RESULTS-1000.txt new file mode 100644 index 0000000000..d56f598173 --- /dev/null +++ b/workbench/inline-step-bench/RESULTS-1000.txt @@ -0,0 +1,284 @@ +inline-step-bench — step-to-step overhead for eagerly inlined steps +node v22.22.2 · Intel(R) Xeon(R) Processor @ 2.90GHz × 16 +workflow SDK 5.0.0-beta.38 · repo HEAD 8bda7ce + +══════════════════════════════════════════════════════════════════════════════ +▶ turbo-on: default config (turbo mode ON — the shipped default) + 1000 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 3003 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":1000,"step_created":1000,"step_completed":1000,"run_completed":1} + step bodies executed : 1000 (each exactly once) + first-step-start → last-step-end : 44437.27 ms + Σ step body time : 0.96 ms (0.00% of the span) + Σ step-to-step overhead : 44436.31 ms (100.00% of the span) + client-observed run wall time : 44672.65 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 14.00 14.00 14.00 14.00 14.00 + 2–10 9 8.32 8.06 9.09 7.51 10.53 + 11–50 40 9.99 9.86 11.56 8.38 12.16 + 51–100 50 12.90 12.72 14.06 10.82 22.66 + 101–200 100 19.05 18.99 23.43 13.24 28.25 + 201–300 100 25.71 25.37 28.87 20.45 45.16 + 301–400 100 33.36 32.26 37.36 26.46 52.48 + 401–500 100 41.11 40.03 45.15 34.16 68.53 + 501–600 100 47.96 47.92 51.68 42.06 78.91 + 601–700 100 55.10 54.08 58.13 49.00 81.27 + 701–800 100 61.56 61.55 65.83 54.46 71.26 + 801–900 100 69.89 69.08 75.81 63.32 100.11 + 901–999 99 80.08 77.68 89.15 72.51 140.93 + + mean STSO, steps 1–10 : 8.89 ms + mean STSO, last 10 steps : 87.78 ms + ratio (last 10 / first 10) : 9.88× + OLS fit STSO(i) ≈ 7.309 ms + 0.074 ms × i + → fixed per-step cost ≈ 7.309 ms, marginal cost of each additional + already-completed step in the log ≈ 0.074 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +▶ turbo-off: WORKFLOW_TURBO=0 (await step_started before running each body) + 1000 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 3003 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":1000,"step_created":1000,"step_completed":1000,"run_completed":1} + step bodies executed : 1000 (each exactly once) + first-step-start → last-step-end : 43768.78 ms + Σ step body time : 1.38 ms (0.00% of the span) + Σ step-to-step overhead : 43767.40 ms (100.00% of the span) + client-observed run wall time : 44006.32 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 8.90 8.90 8.90 8.90 8.90 + 2–10 9 7.79 7.88 8.03 7.41 8.05 + 11–50 40 9.91 9.62 11.73 7.58 19.92 + 51–100 50 12.32 12.14 13.58 10.95 15.50 + 101–200 100 17.27 17.41 20.45 12.79 22.18 + 201–300 100 24.90 25.49 28.37 20.05 37.24 + 301–400 100 31.64 31.12 34.79 26.18 57.11 + 401–500 100 38.83 38.97 41.68 33.25 66.30 + 501–600 100 45.46 43.80 50.76 39.14 71.32 + 601–700 100 55.98 55.54 62.79 47.45 80.20 + 701–800 100 63.45 62.50 67.84 57.09 105.64 + 801–900 100 70.18 69.21 73.93 64.84 89.49 + 901–999 99 79.85 78.24 88.28 69.38 108.56 + + mean STSO, steps 1–10 : 7.90 ms + mean STSO, last 10 steps : 79.48 ms + ratio (last 10 / first 10) : 10.06× + OLS fit STSO(i) ≈ 5.551 ms + 0.077 ms × i + → fixed per-step cost ≈ 5.551 ms, marginal cost of each additional + already-completed step in the log ≈ 0.077 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +▶ void-steps: void steps, timings reconstructed from the event log (control) + 1000 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 3003 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":1000,"step_created":1000,"step_completed":1000,"run_completed":1} + step bodies executed : 1000 (each exactly once) + first-step-start → last-step-end : 21230.00 ms + Σ step_started→step_completed: 2419.00 ms (11.39% of the span) ← event-log timestamps, so this is body + the step_started write, not body alone + Σ step-to-step overhead : 18811.00 ms (88.61% of the span) + client-observed run wall time : 21305.94 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 6.00 6.00 6.00 6.00 6.00 + 2–10 9 5.44 5.00 6.00 5.00 6.00 + 11–50 40 6.00 6.00 7.00 5.00 8.00 + 51–100 50 6.78 7.00 7.10 6.00 9.00 + 101–200 100 9.12 9.00 10.10 6.00 31.00 + 201–300 100 11.46 11.00 13.00 9.00 16.00 + 301–400 100 14.10 14.00 15.00 12.00 18.00 + 401–500 100 17.26 17.00 19.00 14.00 26.00 + 501–600 100 19.78 19.50 22.00 17.00 24.00 + 601–700 100 22.65 23.00 24.00 19.00 33.00 + 701–800 100 26.65 26.00 29.00 23.00 37.00 + 801–900 100 29.12 28.00 31.00 26.00 53.00 + 901–999 99 31.95 31.00 34.00 28.00 58.00 + + mean STSO, steps 1–10 : 5.50 ms + mean STSO, last 10 steps : 33.80 ms + ratio (last 10 / first 10) : 6.15× + OLS fit STSO(i) ≈ 4.412 ms + 0.029 ms × i + → fixed per-step cost ≈ 4.412 ms, marginal cost of each additional + already-completed step in the log ≈ 0.029 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +▶ replay-profile: runtime debug log: replayMs + eventCount per loop iteration + 1000 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 3003 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":1000,"step_created":1000,"step_completed":1000,"run_completed":1} + step bodies executed : 1000 (each exactly once) + first-step-start → last-step-end : 45031.89 ms + Σ step body time : 1.00 ms (0.00% of the span) + Σ step-to-step overhead : 45030.88 ms (100.00% of the span) + client-observed run wall time : 45279.28 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 8.90 8.90 8.90 8.90 8.90 + 2–10 9 7.36 7.38 7.48 6.96 7.61 + 11–50 40 10.30 9.92 12.02 7.61 15.90 + 51–100 50 12.75 12.70 13.98 11.09 14.88 + 101–200 100 17.56 18.00 20.44 12.60 22.15 + 201–300 100 25.30 25.41 28.79 20.19 35.01 + 301–400 100 34.46 33.29 38.26 28.68 64.48 + 401–500 100 39.57 39.22 43.01 35.49 46.04 + 501–600 100 47.86 47.30 53.03 41.40 71.95 + 601–700 100 56.96 55.71 61.25 51.11 80.24 + 701–800 100 65.03 64.34 70.82 57.81 107.52 + 801–900 100 71.98 71.06 76.95 64.31 92.83 + 901–999 99 81.14 81.05 86.39 70.33 121.34 + + mean STSO, steps 1–10 : 7.52 ms + mean STSO, last 10 steps : 85.77 ms + ratio (last 10 / first 10) : 11.41× + OLS fit STSO(i) ≈ 6.121 ms + 0.078 ms × i + → fixed per-step cost ≈ 6.121 ms, marginal cost of each additional + already-completed step in the log ≈ 0.078 ms per replay + + runtime replay log: 1001 in-process loop iterations ✓ 1000 step-scheduling replays + 1 final replay that ran the workflow to completion + → the workflow function was re-executed from the top 1001 times; + each step body executed exactly once + iterations events@end mean replayMs max replayMs + ──────────── ─────────── ────────────── ───────────── + 1–100 299 6.15 9.00 + 101–200 599 11.62 16.00 + 201–300 899 18.19 24.00 + 301–400 1199 25.68 50.00 + 401–500 1499 30.74 36.00 + 501–600 1799 37.86 61.00 + 601–700 2099 45.71 69.00 + 701–800 2399 51.91 84.00 + 801–900 2699 58.04 73.00 + 901–1000 2999 65.95 101.00 + 1001–1001 3002 120.00 120.00 + OLS fit replayMs ≈ 1.746 + 0.022 × eventCount + Σ replayMs = 35305.00 ms across all iterations + (event log grows by 3 events per step, so 0.022 ms/event ≈ 0.067 ms per prior step) + + where the gap goes (ms): replay (fresh VM + re-run the workflow + function over the whole event log) vs everything else (world writes, + incremental events.list, suspension bookkeeping) + steps gap replay other replay% + ─────────── ──────── ──────── ──────── ──────── + 1–1 8.90 2.00 6.90 22.48 + 2–10 7.36 3.11 4.25 42.25 + 11–50 10.30 5.25 5.05 50.95 + 51–100 12.75 7.52 5.23 58.99 + 101–200 17.56 11.68 5.88 66.50 + 201–300 25.30 18.26 7.04 72.17 + 301–400 34.46 25.76 8.70 74.76 + 401–500 39.57 30.79 8.78 77.80 + 501–600 47.86 37.94 9.92 79.28 + 601–700 56.96 45.77 11.19 80.35 + 701–800 65.03 51.95 13.08 79.88 + 801–900 71.98 58.11 13.87 80.73 + 901–999 81.14 66.02 15.12 81.36 + +══════════════════════════════════════════════════════════════════════════════ +▶ replay-profile-void: same, but for void steps (no per-step payload to re-deserialize) + 1000 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 3003 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":1000,"step_created":1000,"step_completed":1000,"run_completed":1} + step bodies executed : 1000 (each exactly once) + first-step-start → last-step-end : 22597.00 ms + Σ step_started→step_completed: 2214.00 ms (9.80% of the span) ← event-log timestamps, so this is body + the step_started write, not body alone + Σ step-to-step overhead : 20383.00 ms (90.20% of the span) + client-observed run wall time : 22657.90 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 5.00 5.00 5.00 5.00 5.00 + 2–10 9 5.33 5.00 6.00 4.00 6.00 + 11–50 40 6.63 6.00 8.00 5.00 11.00 + 51–100 50 7.34 7.00 8.00 6.00 17.00 + 101–200 100 9.22 9.00 11.10 7.00 18.00 + 201–300 100 12.10 12.00 14.00 10.00 19.00 + 301–400 100 15.33 15.00 17.00 13.00 22.00 + 401–500 100 18.99 19.00 21.00 15.00 30.00 + 501–600 100 21.69 22.00 23.10 19.00 25.00 + 601–700 100 24.89 25.00 27.00 23.00 29.00 + 701–800 100 28.92 29.00 31.00 25.00 34.00 + 801–900 100 31.02 31.00 33.00 28.00 35.00 + 901–999 99 35.17 35.00 38.00 31.00 42.00 + + mean STSO, steps 1–10 : 5.30 ms + mean STSO, last 10 steps : 36.50 ms + ratio (last 10 / first 10) : 6.89× + OLS fit STSO(i) ≈ 4.561 ms + 0.032 ms × i + → fixed per-step cost ≈ 4.561 ms, marginal cost of each additional + already-completed step in the log ≈ 0.032 ms per replay + + runtime replay log: 1001 in-process loop iterations ✓ 1000 step-scheduling replays + 1 final replay that ran the workflow to completion + → the workflow function was re-executed from the top 1001 times; + each step body executed exactly once + iterations events@end mean replayMs max replayMs + ──────────── ─────────── ────────────── ───────────── + 1–100 299 4.16 14.00 + 101–200 599 5.79 15.00 + 201–300 899 7.69 10.00 + 301–400 1199 10.12 13.00 + 401–500 1499 12.52 22.00 + 501–600 1799 14.59 18.00 + 601–700 2099 17.21 19.00 + 701–800 2399 19.47 23.00 + 801–900 2699 21.40 26.00 + 901–1000 2999 24.21 30.00 + 1001–1001 3002 22.00 22.00 + OLS fit replayMs ≈ 2.465 + 0.007 × eventCount + Σ replayMs = 13738.00 ms across all iterations + (event log grows by 3 events per step, so 0.007 ms/event ≈ 0.022 ms per prior step) + + where the gap goes (ms): replay (fresh VM + re-run the workflow + function over the whole event log) vs everything else (world writes, + incremental events.list, suspension bookkeeping) + steps gap replay other replay% + ─────────── ──────── ──────── ──────── ──────── + 1–1 5.00 2.00 3.00 40.00 + 2–10 5.33 2.78 2.56 52.08 + 11–50 6.63 3.95 2.67 59.62 + 51–100 7.34 4.68 2.66 63.76 + 101–200 9.22 5.82 3.40 63.12 + 201–300 12.10 7.69 4.41 63.55 + 301–400 15.33 10.16 5.17 66.28 + 401–500 18.99 12.55 6.44 66.09 + 501–600 21.69 14.61 7.08 67.36 + 601–700 24.89 17.23 7.66 69.22 + 701–800 28.92 19.47 9.45 67.32 + 801–900 31.02 21.43 9.59 69.08 + 901–999 35.17 24.23 10.94 68.90 + +══════════════════════════════════════════════════════════════════════════════ +summary +══════════════════════════════════════════════════════════════════════════════ + scenario invocations STSO 1–10 STSO last10 growth fixed ms ms/step total ms + ──────────────────── ──────────── ────────── ──────────── ──────── ───────── ───────── ────────── + turbo-on 1 8.89 87.78 9.88x 7.309 0.074 44437.27 + turbo-off 1 7.90 79.48 10.06x 5.551 0.077 43768.78 + void-steps 1 5.50 33.80 6.15x 4.412 0.029 21230.00 + replay-profile 1 7.52 85.77 11.41x 6.121 0.078 45031.89 + replay-profile-void 1 5.30 36.50 6.89x 4.561 0.032 22597.00 + +raw results → /home/vercel-sandbox/workflow/workbench/inline-step-bench/results/bench-1000-2026-07-30T21-27-08-189Z.json diff --git a/workbench/inline-step-bench/RESULTS-payload-600.txt b/workbench/inline-step-bench/RESULTS-payload-600.txt new file mode 100644 index 0000000000..3ffa760e45 --- /dev/null +++ b/workbench/inline-step-bench/RESULTS-payload-600.txt @@ -0,0 +1,221 @@ +inline-step-bench — step-to-step overhead for eagerly inlined steps +node v22.22.2 · Intel(R) Xeon(R) Processor @ 2.90GHz × 16 +workflow SDK 5.0.0-beta.38 · repo HEAD 8bda7ce + +══════════════════════════════════════════════════════════════════════════════ +▶ void: step returns undefined (memoized) + 600 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 1803 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":600,"step_created":600,"step_completed":600,"run_completed":1} + step bodies executed : 600 (each exactly once) + first-step-start → last-step-end : 9964.00 ms + Σ step_started→step_completed: 1609.00 ms (16.15% of the span) ← event-log timestamps, so this is body + the step_started write, not body alone + Σ step-to-step overhead : 8355.00 ms (83.85% of the span) + client-observed run wall time : 10064.48 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 6.00 6.00 6.00 6.00 6.00 + 2–10 9 5.56 5.00 6.20 5.00 7.00 + 11–50 40 7.28 6.00 8.00 5.00 20.00 + 51–100 50 7.42 7.00 9.00 6.00 11.00 + 101–200 100 9.40 9.00 11.00 7.00 23.00 + 201–300 100 12.74 12.00 14.00 9.00 24.00 + 301–400 100 14.74 15.00 16.00 12.00 21.00 + 401–500 100 18.43 18.00 20.10 15.00 30.00 + 501–599 99 21.27 21.00 23.00 18.00 34.00 + + mean STSO, steps 1–10 : 5.60 ms + mean STSO, last 10 steps : 22.20 ms + ratio (last 10 / first 10) : 3.96× + OLS fit STSO(i) ≈ 5.453 ms + 0.028 ms × i + → fixed per-step cost ≈ 5.453 ms, marginal cost of each additional + already-completed step in the log ≈ 0.028 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +▶ number: step returns a number — primitive, tiny (memoized) + 600 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 1803 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":600,"step_created":600,"step_completed":600,"run_completed":1} + step bodies executed : 600 (each exactly once) + first-step-start → last-step-end : 9325.00 ms + Σ step_started→step_completed: 1406.00 ms (15.08% of the span) ← event-log timestamps, so this is body + the step_started write, not body alone + Σ step-to-step overhead : 7919.00 ms (84.92% of the span) + client-observed run wall time : 9403.32 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 5.00 5.00 5.00 5.00 5.00 + 2–10 9 5.00 5.00 6.00 4.00 6.00 + 11–50 40 6.10 6.00 7.00 5.00 10.00 + 51–100 50 6.88 7.00 8.00 5.00 10.00 + 101–200 100 8.75 9.00 10.00 7.00 14.00 + 201–300 100 11.98 12.00 14.00 9.00 16.00 + 301–400 100 14.47 14.00 16.00 13.00 20.00 + 401–500 100 17.72 17.00 20.00 15.00 31.00 + 501–599 99 20.09 20.00 22.00 16.00 30.00 + + mean STSO, steps 1–10 : 5.00 ms + mean STSO, last 10 steps : 20.90 ms + ratio (last 10 / first 10) : 4.18× + OLS fit STSO(i) ≈ 4.818 ms + 0.028 ms × i + → fixed per-step cost ≈ 4.818 ms, marginal cost of each additional + already-completed step in the log ≈ 0.028 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +▶ str4000: step returns a 4000-char string — primitive, 4 KB, UNDER the 4096 cap (memoized) + 600 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 1803 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":600,"step_created":600,"step_completed":600,"run_completed":1} + step bodies executed : 600 (each exactly once) + first-step-start → last-step-end : 9469.00 ms + Σ step_started→step_completed: 1495.00 ms (15.79% of the span) ← event-log timestamps, so this is body + the step_started write, not body alone + Σ step-to-step overhead : 7974.00 ms (84.21% of the span) + client-observed run wall time : 9568.54 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 5.00 5.00 5.00 5.00 5.00 + 2–10 9 5.22 5.00 6.00 4.00 6.00 + 11–50 40 6.58 6.00 8.00 5.00 18.00 + 51–100 50 6.72 7.00 7.00 6.00 8.00 + 101–200 100 8.88 9.00 10.00 7.00 12.00 + 201–300 100 11.63 12.00 13.00 9.00 20.00 + 301–400 100 14.44 14.00 16.10 12.00 34.00 + 401–500 100 18.12 18.00 20.00 15.00 39.00 + 501–599 99 20.36 20.00 22.00 18.00 45.00 + + mean STSO, steps 1–10 : 5.20 ms + mean STSO, last 10 steps : 21.60 ms + ratio (last 10 / first 10) : 4.15× + OLS fit STSO(i) ≈ 4.804 ms + 0.028 ms × i + → fixed per-step cost ≈ 4.804 ms, marginal cost of each additional + already-completed step in the log ≈ 0.028 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +▶ str5000: step returns a 5000-char string — primitive, 5 KB, OVER the 4096 cap (NOT memoized) + 600 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 1803 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":600,"step_created":600,"step_completed":600,"run_completed":1} + step bodies executed : 600 (each exactly once) + first-step-start → last-step-end : 17766.00 ms + Σ step_started→step_completed: 1640.00 ms (9.23% of the span) ← event-log timestamps, so this is body + the step_started write, not body alone + Σ step-to-step overhead : 16126.00 ms (90.77% of the span) + client-observed run wall time : 17866.38 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 10.00 10.00 10.00 10.00 10.00 + 2–10 9 6.00 6.00 6.00 6.00 6.00 + 11–50 40 7.92 8.00 10.00 6.00 12.00 + 51–100 50 9.98 10.00 11.00 9.00 12.00 + 101–200 100 16.05 16.00 19.00 11.00 31.00 + 201–300 100 22.75 23.00 26.00 18.00 31.00 + 301–400 100 30.47 29.50 34.00 26.00 57.00 + 401–500 100 37.75 37.00 41.00 34.00 46.00 + 501–599 99 45.90 46.00 49.00 40.00 71.00 + + mean STSO, steps 1–10 : 6.40 ms + mean STSO, last 10 steps : 47.90 ms + ratio (last 10 / first 10) : 7.48× + OLS fit STSO(i) ≈ 4.817 ms + 0.074 ms × i + → fixed per-step cost ≈ 4.817 ms, marginal cost of each additional + already-completed step in the log ≈ 0.074 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +▶ obj4: step returns a 4-field object — ~40 bytes (NOT memoized) + 600 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 1803 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":600,"step_created":600,"step_completed":600,"run_completed":1} + step bodies executed : 600 (each exactly once) + first-step-start → last-step-end : 16423.00 ms + Σ step_started→step_completed: 1506.00 ms (9.17% of the span) ← event-log timestamps, so this is body + the step_started write, not body alone + Σ step-to-step overhead : 14917.00 ms (90.83% of the span) + client-observed run wall time : 16543.00 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 5.00 5.00 5.00 5.00 5.00 + 2–10 9 5.44 5.00 6.00 5.00 6.00 + 11–50 40 7.33 7.50 8.10 5.00 11.00 + 51–100 50 9.34 9.00 10.10 8.00 12.00 + 101–200 100 13.96 14.00 16.10 10.00 18.00 + 201–300 100 20.14 20.00 23.00 16.00 24.00 + 301–400 100 27.59 27.00 31.00 23.00 45.00 + 401–500 100 35.49 36.00 38.10 29.00 53.00 + 501–599 99 44.29 43.00 49.00 36.00 76.00 + + mean STSO, steps 1–10 : 5.40 ms + mean STSO, last 10 steps : 48.60 ms + ratio (last 10 / first 10) : 9.00× + OLS fit STSO(i) ≈ 3.213 ms + 0.072 ms × i + → fixed per-step cost ≈ 3.213 ms, marginal cost of each additional + already-completed step in the log ≈ 0.072 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +▶ obj40: step returns a 40-field object — ~600 bytes (NOT memoized) + 600 sequential null steps · world-local +══════════════════════════════════════════════════════════════════════════════ + + flow-handler invocations for this run : 1 ✓ entire chain ran eagerly in ONE invocation + events in the log : 1803 (3.00 per step) + {"run_created":1,"run_started":1,"step_started":600,"step_created":600,"step_completed":600,"run_completed":1} + step bodies executed : 600 (each exactly once) + first-step-start → last-step-end : 18107.00 ms + Σ step_started→step_completed: 1606.00 ms (8.87% of the span) ← event-log timestamps, so this is body + the step_started write, not body alone + Σ step-to-step overhead : 16501.00 ms (91.13% of the span) + client-observed run wall time : 18210.40 ms (includes 100 ms status polling) + + step-to-step overhead by step index (ms) + steps n mean p50 p90 min max + ─────────── ───── ──────── ──────── ──────── ──────── ──────── + 1–1 1 5.00 5.00 5.00 5.00 5.00 + 2–10 9 5.22 5.00 6.00 5.00 6.00 + 11–50 40 7.25 7.00 9.00 5.00 9.00 + 51–100 50 10.50 10.00 12.00 9.00 15.00 + 101–200 100 15.19 15.00 18.00 11.00 21.00 + 201–300 100 23.22 23.00 27.00 17.00 48.00 + 301–400 100 32.39 31.00 36.10 27.00 57.00 + 401–500 100 40.60 40.00 43.00 33.00 85.00 + 501–599 99 45.39 45.00 49.00 40.00 66.00 + + mean STSO, steps 1–10 : 5.20 ms + mean STSO, last 10 steps : 49.30 ms + ratio (last 10 / first 10) : 9.48× + OLS fit STSO(i) ≈ 4.549 ms + 0.077 ms × i + → fixed per-step cost ≈ 4.549 ms, marginal cost of each additional + already-completed step in the log ≈ 0.077 ms per replay + +══════════════════════════════════════════════════════════════════════════════ +summary +══════════════════════════════════════════════════════════════════════════════ + scenario invocations STSO 1–10 STSO last10 growth fixed ms ms/step total ms + ──────────────────── ──────────── ────────── ──────────── ──────── ───────── ───────── ────────── + void 1 5.60 22.20 3.96x 5.453 0.028 9964.00 + number 1 5.00 20.90 4.18x 4.818 0.028 9325.00 + str4000 1 5.20 21.60 4.15x 4.804 0.028 9469.00 + str5000 1 6.40 47.90 7.48x 4.817 0.074 17766.00 + obj4 1 5.40 48.60 9.00x 3.213 0.072 16423.00 + obj40 1 5.20 49.30 9.48x 4.549 0.077 18107.00 + +raw results → /home/vercel-sandbox/workflow/workbench/inline-step-bench/results/bench-600-2026-07-30T21-40-59-202Z.json diff --git a/workbench/inline-step-bench/bench.mjs b/workbench/inline-step-bench/bench.mjs new file mode 100644 index 0000000000..154cd267ab --- /dev/null +++ b/workbench/inline-step-bench/bench.mjs @@ -0,0 +1,726 @@ +#!/usr/bin/env node +// +// Local benchmark: step-to-step overhead (STSO) for steps that run *eagerly +// inline* — many sequential steps executed inside a single flow-handler +// invocation, with no queue hop between them. +// +// What it measures +// ---------------- +// A workflow of N sequential no-op ("null") steps. Each step body stamps +// performance.now() on entry and exit. STSO[i] = t0[i] - t1[i-1], i.e. the +// wall-clock the runtime spends between the end of one step body and the start +// of the next. Because the step bodies do nothing, that gap IS the runtime +// overhead: reload/append the event log, build a fresh workflow VM, replay the +// workflow function from the top over the whole event log, and write +// step_started / step_completed for the next step. +// +// The point of interest is how that gap scales with the step index. The +// in-process loop in packages/core/src/runtime.ts re-runs the entire workflow +// function on every iteration against the full event log, so step N's gap is +// expected to grow with N. +// +// Usage +// node bench.mjs # default scenarios +// node bench.mjs --steps 1000 # override step count +// node bench.mjs --only turbo-on # run a single scenario +// node bench.mjs --keep-data # don't delete the world's data dir + +import cp from 'node:child_process'; +import { randomUUID } from 'node:crypto'; +import fs from 'node:fs'; +import fsp from 'node:fs/promises'; +import os from 'node:os'; +import path from 'node:path'; +import { setTimeout as delay } from 'node:timers/promises'; +import { fileURLToPath } from 'node:url'; + +const HERE = path.dirname(fileURLToPath(import.meta.url)); + +// ---------------------------------------------------------------- CLI args + +function parseArgs(argv) { + const out = { + steps: undefined, + only: undefined, + keepData: false, + runs: 1, + suite: 'default', + }; + for (let i = 0; i < argv.length; i++) { + const a = argv[i]; + if (a === '--steps') out.steps = Number(argv[++i]); + else if (a === '--only') out.only = argv[++i]; + else if (a === '--runs') out.runs = Number(argv[++i]); + else if (a === '--keep-data') out.keepData = true; + else if (a === '--suite') out.suite = argv[++i]; + else if (a === '--help' || a === '-h') { + console.log( + fs.readFileSync(new URL(import.meta.url), 'utf8').slice(0, 1600) + ); + process.exit(0); + } else throw new Error(`unknown arg: ${a}`); + } + return out; +} + +const ARGS = parseArgs(process.argv.slice(2)); +const STEPS = ARGS.steps ?? 1000; + +// Keep the whole chain inside one invocation: the runtime otherwise bails out +// to the queue after WORKFLOW_V2_TIMEOUT_MS (default 120s) of wall time or +// WORKFLOW_REPLAY_TIMEOUT_MS (default 240s) of non-step time. +const LONG_INVOCATION_ENV = { + WORKFLOW_V2_TIMEOUT_MS: '3600000', + WORKFLOW_REPLAY_TIMEOUT_MS: '780000', +}; + +/** + * Scenarios. `debug` runs turn on the runtime's debug log so we can read + * per-replay `replayMs` / `eventCount` straight from the runtime; they are + * reported separately because the logging itself perturbs the STSO numbers. + */ +const SCENARIOS = [ + { + name: 'turbo-on', + title: 'default config (turbo mode ON — the shipped default)', + workflow: 'timedNullStepsWorkflow', + env: {}, + }, + { + name: 'turbo-off', + title: 'WORKFLOW_TURBO=0 (await step_started before running each body)', + workflow: 'timedNullStepsWorkflow', + env: { WORKFLOW_TURBO: '0' }, + }, + { + name: 'void-steps', + title: 'void steps, timings reconstructed from the event log (control)', + workflow: 'voidNullStepsWorkflow', + env: {}, + fromEventLog: true, + }, + { + name: 'replay-profile', + title: 'runtime debug log: replayMs + eventCount per loop iteration', + workflow: 'timedNullStepsWorkflow', + env: { DEBUG: 'workflow:runtime:debug' }, + debug: true, + }, + { + name: 'replay-profile-void', + title: 'same, but for void steps (no per-step payload to re-deserialize)', + workflow: 'voidNullStepsWorkflow', + env: { DEBUG: 'workflow:runtime:debug' }, + debug: true, + fromEventLog: true, + }, +]; + +/** + * `--suite payload`: does the replay cost of a step's return value track its + * SIZE, or whether ReplayPayloadCache can memoize it across replays? + * + * All six run the identical chain and are measured identically (event-log + * timestamps), so only the step's return value differs. The pairs that matter: + * str4000 vs str5000 (same type, 25% size difference, opposite sides of the + * 4096-char memoize cap) and obj4 vs obj40 (both unmemoizable, 10× size). + */ +const PAYLOAD_SCENARIOS = [ + { + name: 'void', + title: 'step returns undefined (memoized)', + workflow: 'voidNullStepsWorkflow', + }, + { + name: 'number', + title: 'step returns a number — primitive, tiny (memoized)', + workflow: 'numberStepsWorkflow', + }, + { + name: 'str4000', + title: + 'step returns a 4000-char string — primitive, 4 KB, UNDER the 4096 cap (memoized)', + workflow: 'str4000StepsWorkflow', + }, + { + name: 'str5000', + title: + 'step returns a 5000-char string — primitive, 5 KB, OVER the 4096 cap (NOT memoized)', + workflow: 'str5000StepsWorkflow', + }, + { + name: 'obj4', + title: 'step returns a 4-field object — ~40 bytes (NOT memoized)', + workflow: 'obj4StepsWorkflow', + }, + { + name: 'obj40', + title: 'step returns a 40-field object — ~600 bytes (NOT memoized)', + workflow: 'obj40StepsWorkflow', + }, +].map((s) => ({ ...s, env: {}, fromEventLog: true })); + +// ------------------------------------------------------------ server harness + +async function startServer(extraEnv) { + const dataDir = path.join( + os.tmpdir(), + `inline-step-bench-${process.pid}-${randomUUID()}` + ); + const proc = cp.spawn('node', [path.join(HERE, 'server.mjs')], { + cwd: HERE, + stdio: ['ignore', 'pipe', 'pipe', 'pipe'], + env: { + ...process.env, + WORKFLOW_TARGET_WORLD: '@workflow/world-local', + WORKFLOW_LOCAL_DATA_DIR: dataDir, + CONTROL_FD: '3', + ...LONG_INVOCATION_ENV, + ...extraEnv, + }, + }); + + let out = ''; + proc.stdout.on('data', (c) => { + out += c; + }); + proc.stderr.on('data', (c) => { + out += c; + }); + + const port = await new Promise((resolve, reject) => { + let buf = ''; + const timer = setTimeout( + () => reject(new Error(`server did not start:\n${out}`)), + 60_000 + ); + proc.stdio[3].on('data', (chunk) => { + buf += chunk; + const nl = buf.indexOf('\n'); + if (nl === -1) return; + clearTimeout(timer); + resolve(JSON.parse(buf.slice(0, nl)).port); + }); + proc.once('exit', (code) => { + clearTimeout(timer); + reject(new Error(`server exited (${code}):\n${out}`)); + }); + }); + + return { + port, + base: `http://127.0.0.1:${port}`, + getOutput: () => out, + async stop() { + if (proc.exitCode === null) { + const exited = new Promise((r) => proc.once('exit', r)); + proc.kill(); + await Promise.race([exited, delay(5_000)]); + } + if (!ARGS.keepData) { + await fsp + .rm(dataDir, { recursive: true, force: true, maxRetries: 5 }) + .catch(() => {}); + } + }, + }; +} + +async function json(url, init) { + const res = await fetch(url, init); + if (!res.ok) + throw new Error( + `${init?.method ?? 'GET'} ${url}: ${res.status} ${await res.text()}` + ); + return res.json(); +} + +async function runWorkflowToCompletion(server, workflow, count) { + const { runId } = await json(`${server.base}/invoke`, { + method: 'POST', + headers: { 'content-type': 'application/json' }, + body: JSON.stringify({ + file: 'workflows/null-steps.ts', + workflow, + args: [count], + }), + }); + + const t0 = performance.now(); + const deadline = Date.now() + 900_000; + for (;;) { + const run = await json(`${server.base}/runs/${runId}`); + if (run.status === 'completed') + return { runId, run, wallMs: performance.now() - t0 }; + if (run.status === 'failed' || run.status === 'cancelled') { + throw new Error( + `run ${runId} ${run.status}: ${JSON.stringify(run.error)}` + ); + } + if (Date.now() > deadline) + throw new Error(`run ${runId} timed out (${run.status})`); + await delay(100); + } +} + +// ------------------------------------------------------------------- stats + +const sum = (xs) => xs.reduce((a, b) => a + b, 0); +const mean = (xs) => (xs.length ? sum(xs) / xs.length : NaN); +function quantile(xs, q) { + if (!xs.length) return NaN; + const s = [...xs].sort((a, b) => a - b); + const pos = (s.length - 1) * q; + const lo = Math.floor(pos); + const hi = Math.ceil(pos); + return lo === hi ? s[lo] : s[lo] + (s[hi] - s[lo]) * (pos - lo); +} + +/** Ordinary least squares y = a + b*x. */ +function linreg(xs, ys) { + const n = xs.length; + const mx = mean(xs); + const my = mean(ys); + let num = 0; + let den = 0; + for (let i = 0; i < n; i++) { + num += (xs[i] - mx) * (ys[i] - my); + den += (xs[i] - mx) ** 2; + } + const b = den === 0 ? 0 : num / den; + return { a: my - b * mx, b }; +} + +const f2 = (x) => (Number.isFinite(x) ? x.toFixed(2) : 'n/a'); +const f3 = (x) => (Number.isFinite(x) ? x.toFixed(3) : 'n/a'); + +/** STSO[i] (i >= 1) = start of step i minus end of step i-1. */ +function stsoSeries(samples) { + const gaps = []; + for (let i = 1; i < samples.length; i++) { + gaps.push({ i, ms: samples[i].t0 - samples[i - 1].t1 }); + } + return gaps; +} + +function bucketReport(gaps, buckets) { + const rows = []; + for (const [lo, hi] of buckets) { + const inRange = gaps.filter((g) => g.i >= lo && g.i <= hi).map((g) => g.ms); + if (!inRange.length) continue; + rows.push({ + range: `${lo}–${Math.min(hi, gaps[gaps.length - 1].i)}`, + n: inRange.length, + mean: mean(inRange), + p50: quantile(inRange, 0.5), + p90: quantile(inRange, 0.9), + min: Math.min(...inRange), + max: Math.max(...inRange), + }); + } + return rows; +} + +function printTable(rows, cols) { + const header = cols.map((c) => c.label.padStart(c.w)).join(' '); + console.log(` ${header}`); + console.log(` ${cols.map((c) => '─'.repeat(c.w)).join(' ')}`); + for (const r of rows) { + console.log( + ` ${cols.map((c) => String(c.get(r)).padStart(c.w)).join(' ')}` + ); + } +} + +// -------------------------------------------------- event-log reconstruction + +/** + * Rebuild per-step timings from the world event log. `step_started.createdAt` + * approximates body entry and `step_completed.createdAt` body exit, both at + * ms resolution (coarser than performance.now(), but independent of anything + * the workflow returns). + */ +function samplesFromEventLog(events) { + const started = new Map(); + const out = []; + for (const e of events) { + if (e.eventType === 'step_started') + started.set(e.correlationId, e.createdAt); + else if (e.eventType === 'step_completed') { + const t0 = started.get(e.correlationId); + if (t0 === undefined) continue; + out.push({ i: out.length, t0, t1: e.createdAt, wall: t0 }); + } + } + return out; +} + +function eventHistogram(events) { + const h = {}; + for (const e of events) h[e.eventType] = (h[e.eventType] ?? 0) + 1; + return h; +} + +// ---------------------------------------------------- debug-log replay parse + +/** + * Pull the runtime's own per-iteration replay accounting out of its debug log. + * + * "Starting workflow replay" { loopIteration, eventCount } + * — logged just before the fresh workflow VM replays the event log. + * "Workflow suspended" { loopIteration, replayMs, steps, ... } + * — logged when that replay reaches the next un-run step, i.e. once per + * inline step. `replayMs` is measured from just before `runWorkflow()` + * to the moment the suspension is caught, so it is the *replay only*: + * no world writes, no step body. + * "Workflow replay completed" { loopIteration, replayMs } + * — the final iteration, where the workflow ran to its return. + * + * `loopIteration` restarts at 1 on every new flow-handler invocation, so a + * non-monotonic sequence also reveals a queue hop. + */ +function parseReplayLog(text) { + const field = (blob, name) => { + const m = blob.match(new RegExp(`${name}:\\s*(\\d+)`)); + return m ? Number(m[1]) : undefined; + }; + const starts = []; + for (const m of text.matchAll( + /Starting workflow replay\s*(\{[\s\S]{0,300}?\})/g + )) { + const it = field(m[1], 'loopIteration'); + const ec = field(m[1], 'eventCount'); + if (it !== undefined && ec !== undefined) + starts.push({ iteration: it, eventCount: ec }); + } + const rows = []; + const re = + /(Workflow suspended|Workflow replay completed)\s*(\{[\s\S]{0,300}?\})/g; + for (const m of text.matchAll(re)) { + const it = field(m[2], 'loopIteration'); + const ms = field(m[2], 'replayMs'); + if (it === undefined || ms === undefined) continue; + rows.push({ + iteration: it, + replayMs: ms, + terminal: m[1] === 'Workflow replay completed', + eventCount: starts[rows.length]?.eventCount, + }); + } + return rows; +} + +// -------------------------------------------------------------- scenario run + +const BUCKETS = [ + [1, 1], + [2, 10], + [11, 50], + [51, 100], + [101, 200], + [201, 300], + [301, 400], + [401, 500], + [501, 600], + [601, 700], + [701, 800], + [801, 900], + [901, 1000], + [1001, Number.MAX_SAFE_INTEGER], +]; + +async function runScenario(scenario, steps) { + console.log(''); + console.log('═'.repeat(78)); + console.log(`▶ ${scenario.name}: ${scenario.title}`); + console.log(` ${steps} sequential null steps · world-local`); + console.log('═'.repeat(78)); + + const server = await startServer(scenario.env); + try { + // Warm-up: JIT the flow route, the VM bootstrap, the world's fs paths. + await runWorkflowToCompletion(server, scenario.workflow, 5); + + const { runId, run, wallMs } = await runWorkflowToCompletion( + server, + scenario.workflow, + steps + ); + const { count: invocations } = await json( + `${server.base}/_flow-invocations/${runId}` + ); + const { events } = await json(`${server.base}/runs/${runId}/events`); + + const samples = scenario.fromEventLog + ? samplesFromEventLog(events) + : run.output; + + if (!Array.isArray(samples) || samples.length !== steps) { + throw new Error( + `expected ${steps} samples, got ${Array.isArray(samples) ? samples.length : typeof samples}` + ); + } + + const gaps = stsoSeries(samples); + const bodyMs = samples.map((s) => s.t1 - s.t0); + const spanMs = samples[samples.length - 1].t1 - samples[0].t0; + const { a, b } = linreg( + gaps.map((g) => g.i), + gaps.map((g) => g.ms) + ); + + console.log(''); + console.log( + ` flow-handler invocations for this run : ${invocations}` + + (invocations === 1 + ? ' ✓ entire chain ran eagerly in ONE invocation' + : ' ⚠ chain spanned multiple invocations') + ); + console.log( + ` events in the log : ${events.length} (${(events.length / steps).toFixed(2)} per step)` + ); + console.log(` ${JSON.stringify(eventHistogram(events))}`); + console.log( + ` step bodies executed : ${samples.length} (each exactly once)` + ); + console.log(` first-step-start → last-step-end : ${f2(spanMs)} ms`); + // For event-log-derived samples "body time" is really + // step_completed.createdAt − step_started.createdAt, i.e. body + the + // step_started write, not the body alone. + console.log( + ` Σ ${scenario.fromEventLog ? 'step_started→step_completed' : 'step body time '}: ${f2(sum(bodyMs))} ms (${((100 * sum(bodyMs)) / spanMs).toFixed(2)}% of the span)` + + (scenario.fromEventLog + ? ' ← event-log timestamps, so this is body + the step_started write, not body alone' + : '') + ); + console.log( + ` Σ step-to-step overhead : ${f2(sum(gaps.map((g) => g.ms)))} ms (${((100 * sum(gaps.map((g) => g.ms))) / spanMs).toFixed(2)}% of the span)` + ); + console.log( + ` client-observed run wall time : ${f2(wallMs)} ms (includes 100 ms status polling)` + ); + console.log(''); + console.log(' step-to-step overhead by step index (ms)'); + printTable(bucketReport(gaps, BUCKETS), [ + { label: 'steps', w: 11, get: (r) => r.range }, + { label: 'n', w: 5, get: (r) => r.n }, + { label: 'mean', w: 8, get: (r) => f2(r.mean) }, + { label: 'p50', w: 8, get: (r) => f2(r.p50) }, + { label: 'p90', w: 8, get: (r) => f2(r.p90) }, + { label: 'min', w: 8, get: (r) => f2(r.min) }, + { label: 'max', w: 8, get: (r) => f2(r.max) }, + ]); + + const first10 = gaps.filter((g) => g.i <= 10).map((g) => g.ms); + const last10 = gaps.slice(-10).map((g) => g.ms); + console.log(''); + console.log(` mean STSO, steps 1–10 : ${f2(mean(first10))} ms`); + console.log(` mean STSO, last 10 steps : ${f2(mean(last10))} ms`); + console.log( + ` ratio (last 10 / first 10) : ${f2(mean(last10) / mean(first10))}×` + ); + console.log(` OLS fit STSO(i) ≈ ${f3(a)} ms + ${f3(b)} ms × i`); + console.log( + ` → fixed per-step cost ≈ ${f3(a)} ms, marginal cost of each additional` + ); + console.log( + ` already-completed step in the log ≈ ${f3(b)} ms per replay` + ); + + let replayRows; + if (scenario.debug) { + // The warm-up run shares the server process, so its debug lines are in + // the same buffer. `loopIteration` restarts at 1 per invocation, so drop + // everything up to the second reset — that's where the measured run + // begins. + replayRows = parseReplayLog(server.getOutput()); + const resets = replayRows + .map((r, idx) => (r.iteration === 1 ? idx : -1)) + .filter((idx) => idx >= 0); + if (resets.length > 1) replayRows = replayRows.slice(resets[1]); + if (replayRows.length) { + console.log(''); + console.log( + ` runtime replay log: ${replayRows.length} in-process loop iterations` + + (replayRows.length === steps + 1 + ? ` ✓ ${steps} step-scheduling replays + 1 final replay that ran the workflow to completion` + : '') + ); + console.log( + ` → the workflow function was re-executed from the top ${replayRows.length} times;` + ); + console.log(` each step body executed exactly once`); + const bucketed = []; + const size = Math.max(1, Math.floor(replayRows.length / 10)); + for (let i = 0; i < replayRows.length; i += size) { + const chunk = replayRows.slice(i, i + size); + bucketed.push({ + range: `${chunk[0].iteration}–${chunk[chunk.length - 1].iteration}`, + events: chunk[chunk.length - 1].eventCount ?? '?', + mean: mean(chunk.map((r) => r.replayMs)), + max: Math.max(...chunk.map((r) => r.replayMs)), + }); + } + printTable(bucketed, [ + { label: 'iterations', w: 12, get: (r) => r.range }, + { label: 'events@end', w: 11, get: (r) => r.events }, + { label: 'mean replayMs', w: 14, get: (r) => f2(r.mean) }, + { label: 'max replayMs', w: 13, get: (r) => f2(r.max) }, + ]); + const withEvents = replayRows.filter( + (r) => typeof r.eventCount === 'number' + ); + const fit = linreg( + withEvents.map((r) => r.eventCount), + withEvents.map((r) => r.replayMs) + ); + console.log( + ` OLS fit replayMs ≈ ${f3(fit.a)} + ${f3(fit.b)} × eventCount` + ); + console.log( + ` Σ replayMs = ${f2(sum(replayRows.map((r) => r.replayMs)))} ms across all iterations` + ); + console.log( + ` (event log grows by 3 events per step, so ${f3(fit.b)} ms/event ≈ ${f3(fit.b * 3)} ms per prior step)` + ); + + // Split each gap into "replay" and "everything else". Loop iteration + // k schedules step k-1, so the replay that precedes step i is + // iteration i+1's. + const split = gaps + .map((g) => { + const row = replayRows[g.i]; + if (!row) return null; + return { + i: g.i, + total: g.ms, + replay: row.replayMs, + other: g.ms - row.replayMs, + }; + }) + .filter(Boolean); + if (split.length) { + console.log(''); + console.log( + ' where the gap goes (ms): replay (fresh VM + re-run the workflow' + ); + console.log( + ' function over the whole event log) vs everything else (world writes,' + ); + console.log(' incremental events.list, suspension bookkeeping)'); + const rows2 = []; + for (const [lo, hi] of BUCKETS) { + const chunk = split.filter((s) => s.i >= lo && s.i <= hi); + if (!chunk.length) continue; + rows2.push({ + range: `${lo}–${Math.min(hi, split[split.length - 1].i)}`, + total: mean(chunk.map((s) => s.total)), + replay: mean(chunk.map((s) => s.replay)), + other: mean(chunk.map((s) => s.other)), + }); + } + printTable(rows2, [ + { label: 'steps', w: 11, get: (r) => r.range }, + { label: 'gap', w: 8, get: (r) => f2(r.total) }, + { label: 'replay', w: 8, get: (r) => f2(r.replay) }, + { label: 'other', w: 8, get: (r) => f2(r.other) }, + { + label: 'replay%', + w: 8, + get: (r) => f2((100 * r.replay) / r.total), + }, + ]); + } + } else { + console.log( + ' (no replay debug lines parsed — is DEBUG set correctly?)' + ); + } + } + + return { + scenario: scenario.name, + title: scenario.title, + steps, + invocations, + eventCount: events.length, + eventHistogram: eventHistogram(events), + spanMs, + bodyTotalMs: sum(bodyMs), + stsoTotalMs: sum(gaps.map((g) => g.ms)), + stsoFirst10Mean: mean(first10), + stsoLast10Mean: mean(last10), + stsoFit: { interceptMs: a, slopeMsPerStep: b }, + buckets: bucketReport(gaps, BUCKETS), + gaps, + replayRows, + }; + } finally { + await server.stop(); + } +} + +// ---------------------------------------------------------------------- main + +const suite = ARGS.suite === 'payload' ? PAYLOAD_SCENARIOS : SCENARIOS; +const wanted = ARGS.only ? suite.filter((s) => s.name === ARGS.only) : suite; +if (!wanted.length) throw new Error(`no scenario named ${ARGS.only}`); + +console.log( + 'inline-step-bench — step-to-step overhead for eagerly inlined steps' +); +console.log( + `node ${process.version} · ${os.cpus()[0]?.model ?? 'unknown cpu'} × ${os.cpus().length}` +); +const sdkVersion = JSON.parse( + fs.readFileSync(path.join(HERE, 'node_modules/workflow/package.json'), 'utf8') +).version; +console.log( + `workflow SDK ${sdkVersion} · repo HEAD ${process.env.BENCH_GIT_SHA ?? '(local)'}` +); + +const results = []; +for (const scenario of wanted) { + results.push(await runScenario(scenario, STEPS)); +} + +const outDir = path.join(HERE, 'results'); +await fsp.mkdir(outDir, { recursive: true }); +const stamp = new Date().toISOString().replace(/[:.]/g, '-'); +const jsonPath = path.join(outDir, `bench-${STEPS}-${stamp}.json`); +await fsp.writeFile( + jsonPath, + JSON.stringify({ steps: STEPS, node: process.version, results }, null, 2) +); + +for (const r of results) { + const csv = [ + 'step,stso_ms', + ...r.gaps.map((g) => `${g.i},${g.ms.toFixed(4)}`), + ].join('\n'); + await fsp.writeFile( + path.join(outDir, `stso-${r.scenario}-${STEPS}.csv`), + csv + ); +} + +console.log(''); +console.log('═'.repeat(78)); +console.log('summary'); +console.log('═'.repeat(78)); +printTable(results, [ + { label: 'scenario', w: 20, get: (r) => r.scenario }, + { label: 'invocations', w: 12, get: (r) => r.invocations }, + { label: 'STSO 1–10', w: 10, get: (r) => f2(r.stsoFirst10Mean) }, + { label: 'STSO last10', w: 12, get: (r) => f2(r.stsoLast10Mean) }, + { + label: 'growth', + w: 8, + get: (r) => `${f2(r.stsoLast10Mean / r.stsoFirst10Mean)}x`, + }, + { label: 'fixed ms', w: 9, get: (r) => f3(r.stsoFit.interceptMs) }, + { label: 'ms/step', w: 9, get: (r) => f3(r.stsoFit.slopeMsPerStep) }, + { label: 'total ms', w: 10, get: (r) => f2(r.spanMs) }, +]); +console.log(''); +console.log(`raw results → ${jsonPath}`); diff --git a/workbench/inline-step-bench/package.json b/workbench/inline-step-bench/package.json new file mode 100644 index 0000000000..8310636878 --- /dev/null +++ b/workbench/inline-step-bench/package.json @@ -0,0 +1,25 @@ +{ + "name": "@workflow/inline-step-bench", + "private": true, + "type": "module", + "version": "0.0.0", + "license": "Apache-2.0", + "description": "Local benchmark for step-to-step overhead of eagerly-inlined steps (single invocation, no queue hop)", + "scripts": { + "build": "wf build", + "bench": "node bench.mjs", + "clean": "rm -rf .well-known .workflow-data .swc results" + }, + "dependencies": { + "@hono/node-server": "1.19.13", + "@workflow/cli": "workspace:*", + "@workflow/core": "workspace:*", + "@workflow/world": "workspace:*", + "@workflow/world-local": "workspace:*", + "hono": "4.12.25", + "workflow": "workspace:*" + }, + "devDependencies": { + "@types/node": "catalog:" + } +} diff --git a/workbench/inline-step-bench/server.mjs b/workbench/inline-step-bench/server.mjs new file mode 100644 index 0000000000..c6ba891c5c --- /dev/null +++ b/workbench/inline-step-bench/server.mjs @@ -0,0 +1,122 @@ +// Minimal local workflow host for the inline-step benchmark. +// +// Trimmed-down copy of packages/world-testing/src/server.mts: it mounts the +// generated flow route, counts flow-handler invocations per run (so the +// benchmark can assert the whole chain really did stay in ONE invocation), and +// exposes the run's hydrated output plus its raw event log with timestamps. + +import fs from 'node:fs'; +import { serve } from '@hono/node-server'; +import { hydrateWorkflowReturnValue } from '@workflow/core/serialization'; +import { Hono } from 'hono'; +import { start } from 'workflow/api'; +import { getWorld } from 'workflow/runtime'; +import { POST as flowPOST } from './.well-known/workflow/v1/flow.mjs'; +import manifest from './.well-known/workflow/v1/manifest.json' with { + type: 'json', +}; + +if (!process.env.WORKFLOW_TARGET_WORLD) { + console.error('Error: WORKFLOW_TARGET_WORLD is not set.'); + process.exit(1); +} + +/** runId -> number of POSTs to the flow route. */ +const flowInvocationCounts = new Map(); + +const app = new Hono() + .post('/.well-known/workflow/v1/flow', async (ctx) => { + // Count before awaiting, so a run that completes inside this call is never + // observed as completed-with-zero-invocations. + const cloned = ctx.req.raw.clone(); + try { + const body = await cloned.json(); + const runId = + typeof body?.runId === 'string' + ? body.runId + : typeof body?.payload?.runId === 'string' + ? body.payload.runId + : undefined; + if (runId) { + flowInvocationCounts.set( + runId, + (flowInvocationCounts.get(runId) ?? 0) + 1 + ); + } + } catch { + // health check / non-JSON — ignore + } + return flowPOST(ctx.req.raw); + }) + .get('/_flow-invocations/:runId', (ctx) => + ctx.json({ count: flowInvocationCounts.get(ctx.req.param('runId')) ?? 0 }) + ) + .post('/invoke', async (ctx) => { + const { file, workflow, args = [] } = await ctx.req.json(); + const entry = manifest.workflows[file]?.[workflow]; + if (!entry) { + return ctx.json({ error: `unknown workflow ${file}#${workflow}` }, 400); + } + const startedAt = Date.now(); + const handler = await start(entry, args); + return ctx.json({ runId: handler.runId, startedAt }); + }) + .get('/runs/:runId', async (ctx) => { + const world = await getWorld(); + const run = await world.runs.get(ctx.req.param('runId')); + let output; + if (run.output) { + output = await hydrateWorkflowReturnValue( + run.output, + run.runId, + undefined + ); + } + return ctx.json({ + runId: run.runId, + status: run.status, + error: run.error ?? null, + createdAt: run.createdAt, + startedAt: run.startedAt ?? null, + completedAt: run.completedAt ?? null, + output, + }); + }) + .get('/runs/:runId/events', async (ctx) => { + const runId = ctx.req.param('runId'); + const world = await getWorld(); + const events = []; + let cursor; + for (;;) { + const page = await world.events.list({ + runId, + pagination: { sortOrder: 'asc', cursor }, + }); + for (const e of page.data) { + events.push({ + eventType: e.eventType, + correlationId: e.correlationId, + createdAt: +new Date(e.createdAt), + }); + } + if (!page.hasMore) break; + cursor = page.cursor ?? undefined; + if (!cursor) break; + } + return ctx.json({ events }); + }); + +serve( + { fetch: app.fetch, port: Number(process.env.PORT) || 0 }, + async (info) => { + process.env.PORT = String(info.port); + const world = await getWorld(); + if (world.start) await world.start(); + if (process.env.CONTROL_FD === '3') { + const control = fs.createWriteStream('', { fd: 3 }); + control.write( + `${JSON.stringify({ state: 'listening', port: info.port })}\n` + ); + } + } +); diff --git a/workbench/inline-step-bench/workflows/null-steps.ts b/workbench/inline-step-bench/workflows/null-steps.ts new file mode 100644 index 0000000000..f510a07173 --- /dev/null +++ b/workbench/inline-step-bench/workflows/null-steps.ts @@ -0,0 +1,155 @@ +// Null-step workflows used to measure step-to-step overhead (STSO) when steps +// are executed *eagerly inline* — i.e. inside a single flow-handler invocation, +// with no queue hop between them. +// +// The runtime's in-process loop (packages/core/src/runtime.ts, `while (true)`) +// replays the whole workflow function from the top on every iteration, feeding +// it the full event log, and runs the next uncreated step inline. So step N's +// "overhead" includes replaying steps 0..N-1 from the event log. These +// workflows are deliberately as close to zero user-work as possible so the +// measured gaps are pure runtime overhead. + +/** One sample recorded from inside a step body (real Node clock, not the VM's + * replay-stable clock — step bodies run outside the workflow VM). */ +export interface StepSample { + /** Step index in the sequential chain. */ + i: number; + /** `performance.now()` at body entry (sub-ms, same process for a local run). */ + t0: number; + /** `performance.now()` at body exit. */ + t1: number; + /** `Date.now()` at body entry, to correlate with event-log timestamps. */ + wall: number; +} + +/** A step that does nothing except stamp the clock on the way in and out. */ +async function timedNullStep(i: number): Promise { + 'use step'; + const t0 = performance.now(); + return { i, t0, t1: performance.now(), wall: Date.now() }; +} + +/** A step that does nothing at all and returns nothing. */ +async function voidNullStep(_i: number): Promise { + 'use step'; +} + +// --------------------------------------------------------------------------- +// Return-value shape probes. +// +// ReplayPayloadCache (packages/core/src/replay-payload-cache.ts) memoizes a +// step's *final hydrated value* across the invocation's replays — but only +// when sharing one value between VM realms is unobservable, i.e. when it is a +// primitive and, for strings/bigints, no longer than +// MAX_MEMOIZED_PRIMITIVE_LENGTH (4096). Anything else re-runs `hydrate()` +// against the fresh VM's globals on every replay. +// +// These steps are designed to cross that boundary in both directions so the +// benchmark can tell "payload is big" apart from "payload is not memoizable": +// +// number — primitive, tiny → memoized +// str4000 — primitive, 4 KB payload → memoized (4000 <= 4096) +// str5000 — primitive, 5 KB payload → NOT memoized (5000 > 4096) +// obj4 — object, ~40 byte payload → NOT memoized +// obj40 — object, ~600 byte payload → NOT memoized +// +// If cost tracked payload size, str4000 would be the expensive one and obj4 +// the cheap one. If it tracks memoizability, it is the other way around. +// --------------------------------------------------------------------------- + +async function numberStep(i: number): Promise { + 'use step'; + return i; +} + +async function str4000Step(i: number): Promise { + 'use step'; + return String(i % 10).repeat(4000); +} + +async function str5000Step(i: number): Promise { + 'use step'; + return String(i % 10).repeat(5000); +} + +async function obj4Step(i: number): Promise> { + 'use step'; + return { a: i, b: i + 1, c: i + 2, d: i + 3 }; +} + +async function obj40Step(i: number): Promise> { + 'use step'; + const out: Record = {}; + for (let k = 0; k < 40; k++) out[`f${k}`] = i + k; + return out; +} + +/** + * `count` sequential null steps, each returning its own timing sample. + * + * Sequential + no hooks/waits/sleeps/streams means the runtime keeps the whole + * chain inline in one invocation (see docs/content/docs/v5/changelog/ + * lazy-event-creation.md, "Queue messages: inline steps don't pay a + * round-trip"), which is exactly the regime we want to measure. + */ +export async function timedNullStepsWorkflow( + count: number +): Promise { + 'use workflow'; + const samples: StepSample[] = []; + for (let i = 0; i < count; i++) { + samples.push(await timedNullStep(i)); + } + return samples; +} + +/** + * `count` sequential steps that return nothing and are never collected, so the + * workflow's in-VM state stays O(1) instead of growing with the step count. + * + * Used as a control: timings for this one are reconstructed from the event log + * (`step_started` / `step_completed` `createdAt`), which proves the STSO curve + * is not an artifact of the sample array the timed variant accumulates. + */ +export async function voidNullStepsWorkflow(count: number): Promise { + 'use workflow'; + for (let i = 0; i < count; i++) { + await voidNullStep(i); + } + return count; +} + +/** `count` sequential steps returning a memoizable primitive number. */ +export async function numberStepsWorkflow(count: number): Promise { + 'use workflow'; + for (let i = 0; i < count; i++) await numberStep(i); + return count; +} + +/** `count` sequential steps returning a 4000-char string (memoizable). */ +export async function str4000StepsWorkflow(count: number): Promise { + 'use workflow'; + for (let i = 0; i < count; i++) await str4000Step(i); + return count; +} + +/** `count` sequential steps returning a 5000-char string (over the cap). */ +export async function str5000StepsWorkflow(count: number): Promise { + 'use workflow'; + for (let i = 0; i < count; i++) await str5000Step(i); + return count; +} + +/** `count` sequential steps returning a tiny 4-field object. */ +export async function obj4StepsWorkflow(count: number): Promise { + 'use workflow'; + for (let i = 0; i < count; i++) await obj4Step(i); + return count; +} + +/** `count` sequential steps returning a 40-field object. */ +export async function obj40StepsWorkflow(count: number): Promise { + 'use workflow'; + for (let i = 0; i < count; i++) await obj40Step(i); + return count; +}