Skip to content

Commit 60d71da

Browse files
authored
perf(webapp,run-engine): cut CPU on the engine-facing worker-action routes (#4746)
Cuts CPU on the `engine/v1/worker-actions/*` routes a managed supervisor calls, and adds the benchmark harness the numbers come from. Measured on a local stack: **on-CPU per completed run 9.07ms → 6.59ms (−27%)**, busy fraction 45.6% → 33.8%, with every worker-action p50 down 23–27%. Load was 5,000 runs / 24 virtual supervisors / 90s window / 30,120 requests / 0 errors. Query-count work from the same investigation is deliberately **not** here — it will follow as a separate PR. ## The three changes **1. Split the event-loop monitor in two (~14% of on-CPU, plus ~5pp of GC).** `eventLoopMonitor.server.ts` installs a global `async_hooks` hook: `init` writes a `Map` entry for *every* async resource the process creates, `before` calls `process.hrtime()` and `context.active()` on every one. Enabling any async hook also puts V8 on the slow path for promise instrumentation process-wide. `EVENT_LOOP_MONITOR_ENABLED` defaulted to `"1"`, so this was the shipping configuration. The blocked-loop detector is now opt-in (`EVENT_LOOP_MONITOR_ENABLED`, default `0`). The event-loop *utilization* gauge — a single interval timer with no per-request cost — moves to its own flag (`EVENT_LOOP_UTILIZATION_MONITOR_ENABLED`, default `1`) and stays on, so the useful half survives without the expensive half. A/B under identical load: | | monitor on | monitor off | change | |---|---|---|---| | on-CPU per run | 9.08ms | 7.25ms | −20% | | GC self time | 9.80% | 5.05% | −4.75pp | | dequeue p50 | 76.6ms | 62.8ms | −18% | | attempts/start p50 | 56.3ms | 43.5ms | −23% | **2. Bucket route matching by first static path segment (10.4% → 3.9% of on-CPU).** `patches/@remix-run__router@1.23.3.patch` already memoized flattened branches and compiled path regexes. What remained was the linear scan: `matchRouteBranch` walked the ranked branch list calling `matchPath` per branch across 521 route files, so every worker-action request paid a scan proportional to the whole route table. Branches are now indexed by their lowercased leading segment, with one always-considered list for branches whose leading segment is dynamic, splat or optional (and for root/pathless paths). A request walks only its own bucket merged with that list. Route-matching self time dropped 64% (3.6s → 1.3s over a 90s window). Ordering is preserved exactly: both lists hold indexes into the already rank-sorted branch array and are walked in ascending-index order, so the first match found is the same branch the full scan would have found. Bucketing lowercases on both sides, so case-insensitive matching still resolves and `caseSensitive: true` routes are still rejected by `matchPath` itself. A pathname whose own leading segment can't be bucketed falls back to the full scan. Verified equivalent to the unpatched matcher over 20,050 pathnames (literal, dynamic, splat, optional, case variants, basenames, percent-encoded) with zero mismatches. `apps/webapp/test/routeMatchingPatch.test.ts` pins the matching semantics rather than the optimisation, so it still passes without the patch. **3. Demote per-heartbeat and per-dequeue `info` logs to `debug`.** These are the two highest-rate engine calls and each wrote a synchronous structured log line on every request. Synchronous `console` writes can block the loop when stdout backs up, which costs more than the ~1.3% CPU share suggests. ## The harness Two benchmarks, neither in the default suite (they run for minutes, attach the V8 profiler, and report numbers rather than assert on them). See `apps/webapp/test/bench/README.md`. - `apps/webapp/test/bench/engineHttp.bench.test.ts` — spawns a real webapp against throwaway Postgres/Redis containers, seeds a production environment with a promoted managed deployment, and drives a closed-loop supervisor pool through the full lifecycle. Profiling runs over CDP rather than `--cpu-prof` so it covers only the measured window instead of being swamped by boot, and `performance.eventLoopUtilization()` is sampled *inside* the webapp process. - `internal-packages/run-engine/src/engine/bench/runEngineLifecycle.bench.test.ts` — drives `RunEngine` directly, profiling enqueue and lifecycle separately so engine cost isn't mixed with request-stack overhead. - `apps/webapp/test/bench/analyzeProfile.ts` — dependency-free `.cpuprofile` analyzer that symbolicates through the build's source maps and ranks CPU by package, self time and total time. Percentages are shares of on-CPU time (V8's `(idle)`/`(program)` excluded). `startWebapp` gains `overrideEnv`, applied after the worker-disable defaults, so the HTTP bench can re-enable the run engine worker that drains the master queue into the worker queues a supervisor dequeues from. The local OTel collector gains a traces pipeline. It only defined a metrics pipeline, so pointing `INTERNAL_OTEL_TRACE_EXPORTER_URL` at it locally failed and the webapp silently fell back to the console span logger. ## Configuration For operators upgrading: - `EVENT_LOOP_MONITOR_ENABLED` (now defaults to `0`) — the per-async-resource blocked-loop detector. Set to `1` to restore the previous behaviour and keep emitting `event-loop-blocked` spans. - `EVENT_LOOP_UTILIZATION_MONITOR_ENABLED` (new, defaults to `1`) — the `nodejs.event_loop.utilization` gauge. Unchanged in behaviour; it just has its own flag now so it survives turning the detector off. ## Notes for review - `pnpm-lock.yaml` changes only because the router patch content changed, which changes its patch hash. - One thing the profile ruled out: with a real OTLP collector receiving spans, tracing costs ~1.7% of on-CPU at 100% sampling and ~0.8% at the production rate. Span shipping is not a hidden cost, so nothing here touches it. - Caveats on the numbers: a laptop, not production hardware, so DB and Redis *latency* are unrepresentative (client-side CPU is what's ranked); single webapp process; throughput varies ~5% run to run, which is why the claims rest on on-CPU per run rather than req/s. ## Verification - 20,050-pathname router equivalence check vs the unpatched matcher, zero mismatches - `apps/webapp/test/routeMatchingPatch.test.ts` (12 cases) passes - webapp e2e smoke suite (68 tests) passes through the patched router - run-engine suites covering the snapshot/attempt paths pass - `typecheck`, `format`, `lint`, `knip` clean
1 parent 4953128 commit 60d71da

30 files changed

Lines changed: 2346 additions & 37 deletions

.gitignore

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -87,3 +87,6 @@ ailogger-output.log
8787
observability-map.json
8888

8989
.claude/worktrees/
90+
91+
# CPU benchmark artifacts (profiles + summaries)
92+
.bench/
Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
---
2+
area: webapp
3+
type: improvement
4+
---
5+
6+
Cut webapp CPU usage by about a quarter on the routes that workers call most, freeing headroom at the same request rate. Detailed event-loop blocking traces are no longer recorded by default, because producing them was itself a large part of that cost.

apps/webapp/app/entry.server.tsx

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,7 +18,7 @@ import type { OperatingSystemPlatform } from "./components/primitives/OperatingS
1818
import { OperatingSystemContextProvider } from "./components/primitives/OperatingSystemProvider";
1919
import { assertRunOpsSplitSentinel, Prisma } from "./db.server";
2020
import { env } from "./env.server";
21-
import { eventLoopMonitor } from "./eventLoopMonitor.server";
21+
import { eventLoopMonitor, eventLoopUtilizationMonitor } from "./eventLoopMonitor.server";
2222
import { logger } from "./services/logger.server";
2323
import { buildImgSrcDirective, parseCspImageOrigins, withImgSrc } from "./utils/cspImageOrigins";
2424
import { singleton } from "./utils/singleton";
@@ -360,6 +360,10 @@ if (env.EVENT_LOOP_MONITOR_ENABLED === "1") {
360360
eventLoopMonitor.enable();
361361
}
362362

363+
if (env.EVENT_LOOP_UTILIZATION_MONITOR_ENABLED === "1") {
364+
eventLoopUtilizationMonitor.enable();
365+
}
366+
363367
if (remoteBuildsEnabled()) {
364368
console.log("🏗️ Remote builds enabled");
365369
} else {

apps/webapp/app/env.server.ts

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -995,7 +995,8 @@ const EnvironmentSchema = z
995995

996996
CENTS_PER_RUN: z.coerce.number().default(0),
997997

998-
EVENT_LOOP_MONITOR_ENABLED: z.string().default("1"),
998+
EVENT_LOOP_MONITOR_ENABLED: z.string().default("0"),
999+
EVENT_LOOP_UTILIZATION_MONITOR_ENABLED: z.string().default("1"),
9991000
MAXIMUM_LIVE_RELOADING_EVENTS: z.coerce.number().int().default(1000),
10001001
MAXIMUM_TRACE_SUMMARY_VIEW_COUNT: z.coerce.number().int().default(25_000),
10011002
MAXIMUM_TRACE_DETAILED_SUMMARY_VIEW_COUNT: z.coerce.number().int().default(10_000),

apps/webapp/app/eventLoopMonitor.server.ts

Lines changed: 31 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -89,25 +89,51 @@ function after(asyncId: number) {
8989
}
9090
}
9191

92+
/**
93+
* Per-async-resource blocked-loop detection. This is the expensive half: the
94+
* hook fires for every async resource the process creates, and enabling any
95+
* async hook also puts V8 on the slow path for promise instrumentation
96+
* process-wide. On a request-heavy instance it costs roughly a seventh of all
97+
* on-CPU time, which is why it is opt-in rather than on by default.
98+
*/
9299
export const eventLoopMonitor = singleton("eventLoopMonitor", () => {
93100
const hook = createHook({ init, before, after, destroy });
94101

95-
let stopEventLoopUtilizationMonitoring: () => void;
96-
97102
return {
98103
enable: () => {
99104
console.log("🥸 Initializing event loop monitor");
100105

101106
hook.enable();
102-
103-
stopEventLoopUtilizationMonitoring = startEventLoopUtilizationMonitoring();
104107
},
105108
disable: () => {
106109
console.log("🥸 Disabling event loop monitor");
107110

108111
hook.disable();
112+
},
113+
};
114+
});
115+
116+
/**
117+
* The cheap half: a single interval timer reading `eventLoopUtilization()`.
118+
* It costs nothing per request, so it stays on by default and is what a
119+
* high-traffic instance should rely on when the async hook is too expensive.
120+
*/
121+
export const eventLoopUtilizationMonitor = singleton("eventLoopUtilizationMonitor", () => {
122+
let stop: (() => void) | undefined;
109123

110-
stopEventLoopUtilizationMonitoring?.();
124+
return {
125+
enable: () => {
126+
if (stop) {
127+
return;
128+
}
129+
130+
console.log("🥸 Initializing event loop utilization monitor");
131+
132+
stop = startEventLoopUtilizationMonitoring();
133+
},
134+
disable: () => {
135+
stop?.();
136+
stop = undefined;
111137
},
112138
};
113139
});

apps/webapp/package.json

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,8 @@
2525
"upload:sourcemaps": "bash ./upload-sourcemaps.sh",
2626
"test": "vitest --no-file-parallelism",
2727
"test:perf": "vitest --config ./vitest.perf.config.ts --run",
28-
"eval:dev": "evalite watch"
28+
"eval:dev": "evalite watch",
29+
"test:bench": "vitest --config ./vitest.bench.config.ts --run"
2930
},
3031
"dependencies": {
3132
"@ai-sdk/openai": "^3.0.0",

apps/webapp/test/bench/README.md

Lines changed: 91 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,91 @@
1+
# Engine CPU benchmarks
2+
3+
Two benchmarks for the paths the production engine service spends its CPU in, plus a
4+
`.cpuprofile` analyzer. Neither runs in CI: they take minutes, attach the V8 profiler, and
5+
report numbers rather than assert on them.
6+
7+
| bench | what it covers | where |
8+
| --- | --- | --- |
9+
| `engineHttp.bench.test.ts` | the full request stack for `engine/v1/worker-actions/*` | `apps/webapp` |
10+
| `runEngineLifecycle.bench.test.ts` | run-engine and run-queue with no HTTP in the way | `internal-packages/run-engine` |
11+
12+
Artifacts (profiles + JSON summaries) land in `.bench/` at the repo root, which is gitignored.
13+
14+
## HTTP bench
15+
16+
Measures what a managed supervisor actually does: dequeue, start attempt, heartbeat,
17+
read latest snapshot, complete attempt. Needs a built webapp.
18+
19+
```bash
20+
pnpm run build --filter webapp
21+
cd apps/webapp
22+
pnpm run test:bench
23+
```
24+
25+
It spawns a real webapp against throwaway Postgres and Redis containers, seeds a production
26+
environment with a promoted managed deployment, fills the worker queue over the public
27+
trigger API, then drives a closed-loop supervisor pool for the measured window.
28+
29+
The webapp is spawned with `--inspect` and profiled over CDP, so the profile covers only the
30+
measured window rather than boot. Event-loop utilization is sampled **inside** the webapp
31+
process over the same connection.
32+
33+
Knobs:
34+
35+
| var | default | meaning |
36+
| --- | --- | --- |
37+
| `BENCH_RUNS` | 1200 | runs queued before the window opens |
38+
| `BENCH_SUPERVISORS` | 16 | concurrent virtual supervisors |
39+
| `BENCH_HEARTBEATS` | 2 | heartbeats per run |
40+
| `BENCH_DURATION_MS` | 60000 | measured window |
41+
| `BENCH_SAMPLING_INTERVAL_US` | 200 | V8 sampling interval |
42+
| `BENCH_PROFILE_NAME` | `engine-http` | artifact basename |
43+
| `BENCH_EXTRA_ENV` || JSON merged into the webapp's env |
44+
| `BENCH_OUT_DIR` | `<repo>/.bench` | artifact directory |
45+
46+
`BENCH_EXTRA_ENV` plus `BENCH_PROFILE_NAME` is how you A/B a single flag:
47+
48+
```bash
49+
BENCH_RUNS=5000 BENCH_SUPERVISORS=24 BENCH_DURATION_MS=90000 \
50+
BENCH_PROFILE_NAME=engine-http-no-elm \
51+
BENCH_EXTRA_ENV='{"EVENT_LOOP_MONITOR_ENABLED":"0"}' \
52+
pnpm run test:bench
53+
```
54+
55+
Run the same size for both arms and compare `on-cpu ms per completed run` rather than
56+
throughput: throughput on a laptop moves ~5% run to run, on-CPU per unit of work is far
57+
steadier.
58+
59+
## Run-engine bench
60+
61+
No HTTP, no webapp: drives `RunEngine` directly so engine and queue costs are not mixed with
62+
request-stack overhead. Profiles two phases separately, because blending them hides which one
63+
owns a hot frame.
64+
65+
```bash
66+
cd internal-packages/run-engine
67+
pnpm run test:bench
68+
```
69+
70+
Knobs: `BENCH_RUNS`, `BENCH_CONSUMERS`, `BENCH_HEARTBEATS`, `BENCH_CONCURRENCY_LIMIT`,
71+
`BENCH_SAMPLING_INTERVAL_US`, `BENCH_OUT_DIR`.
72+
73+
The driver shares a process with the code under measurement, so its own cost is in the
74+
profile. It is a thin await loop and appears under its own frames rather than smeared across
75+
engine frames.
76+
77+
## Analyzing a profile
78+
79+
```bash
80+
pnpm --filter webapp exec tsx test/bench/analyzeProfile.ts .bench/engine-http.cpuprofile --top 30
81+
```
82+
83+
Three views: CPU by bucket (which package owns the cycles), hottest frames by self time (what
84+
to go fix), and hottest frames by total time (entry points, and a check that the load
85+
exercised the route mix you intended). Frames are symbolicated through the build's source
86+
maps, so bundled chunks report as the source files they came from.
87+
88+
Percentages are shares of **on-CPU** time, with V8's `(idle)` and `(program)` excluded. A
89+
share of wall clock would make everything look cheap whenever the bench was IO-bound.
90+
91+
`--json <path>` writes the full analysis for diffing two runs.
Lines changed: 66 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,66 @@
1+
#!/usr/bin/env tsx
2+
/**
3+
* Ranks where a `.cpuprofile` spent its cycles.
4+
*
5+
* pnpm --filter webapp exec tsx test/bench/analyzeProfile.ts <profile> [--top 40] [--json out.json]
6+
*
7+
* `--root` overrides the repo root used to make source paths relative and to
8+
* find the build's source maps; it defaults to the repo containing this file.
9+
*/
10+
import { readFileSync, writeFileSync } from "node:fs";
11+
import { resolve } from "node:path";
12+
import { analyzeProfile, formatAnalysis, type CpuProfile } from "./lib/profileAnalysis";
13+
14+
function parseArgs(argv: string[]): {
15+
profilePath?: string;
16+
top: number;
17+
json?: string;
18+
root: string;
19+
} {
20+
const here = typeof __dirname === "string" ? __dirname : import.meta.dirname;
21+
22+
const defaults = {
23+
top: 30,
24+
root: resolve(here, "..", "..", "..", ".."),
25+
};
26+
27+
let profilePath: string | undefined;
28+
let top = defaults.top;
29+
let json: string | undefined;
30+
let root = defaults.root;
31+
32+
for (let i = 0; i < argv.length; i++) {
33+
const arg = argv[i]!;
34+
if (arg === "--top") {
35+
const raw = argv[++i];
36+
const parsed = Number(raw);
37+
if (!Number.isFinite(parsed) || parsed <= 0) {
38+
console.error(`--top expects a positive number, got "${raw ?? ""}"`);
39+
process.exit(1);
40+
}
41+
top = parsed;
42+
} else if (arg === "--json") json = argv[++i];
43+
else if (arg === "--root") root = resolve(argv[++i]!);
44+
else if (!arg.startsWith("--")) profilePath = arg;
45+
}
46+
47+
return { profilePath, top, json, root };
48+
}
49+
50+
const { profilePath, top, json, root } = parseArgs(process.argv.slice(2));
51+
52+
if (!profilePath) {
53+
console.error("usage: analyzeProfile.ts <path-to-.cpuprofile> [--top N] [--json out.json]");
54+
process.exit(1);
55+
}
56+
57+
const profile = JSON.parse(readFileSync(profilePath, "utf8")) as CpuProfile;
58+
const analysis = analyzeProfile(profile, root);
59+
60+
console.log(`\n=== ${profilePath} ===`);
61+
console.log(formatAnalysis(analysis, top));
62+
63+
if (json) {
64+
writeFileSync(json, JSON.stringify(analysis, null, 2));
65+
console.log(`\nwrote ${json}`);
66+
}

0 commit comments

Comments
 (0)