authorgravatar for me@t3.ggTheo Browne <me@t3.gg> 2026-09-25 20:38:56-07:00
committergravatar for noreply@github.comGitHub <noreply@github.com> 2026-09-25 20:38:56-07:00
logee18e56f902f2ccd74dffdc50363051be02ae0ab
tree89b090389db25f73a72ee034eb864a1f157477ae
parentecd3237b184e87af5d744a9dc28422cc1eb68e1a
signature Signed by PGP key B5690EEEBB952194

feat(observability): record event loop stalls in the server trace (#13697)

Co-authored-by: Claude Opus 5.5 (1M context) <noreply@anthropic.com>

4 files changed, 248 insertions(+), 1 deletions(-)

apps/server/src/observability/EventLoopMonitor.test.ts created+77
...@@ -0,0 +1,77 @@
1import { assert, describe, it } from "@effect/vitest";
2import * as Effect from "effect/Effect";
3import * as Layer from "effect/Layer";
4import * as Tracer from "effect/Tracer";
5import * as TestClock from "effect/testing/TestClock";
6
7import { type EventLoopReadings, layerWith, stallMs } from "./EventLoopMonitor.ts";
8
9const ms = (value: number) => value * 1e6;
10
11// Node reports a stall of S as a gap of up to S + 1 s, the histogram resolution.
12const stalled: EventLoopReadings = {
13 delayMaxNs: ms(5_950),
14 activeMs: 6_200,
15 utilization: 0.176,
16 usage: {
17 userCPUTime: 310_400,
18 systemCPUTime: 95_600,
19 majorPageFault: 8_412,
20 minorPageFault: 20_031,
21 involuntaryContextSwitches: 57,
22 },
23 rssBytes: 1536 * 1024 * 1024,
24};
25// Over the threshold as read, but not once the resolution is subtracted.
26const quiet: EventLoopReadings = { ...stalled, delayMaxNs: ms(2_950) };
27
28describe("EventLoopMonitor", () => {
29 it.effect("records a warning span only for samples that saw a stall", () =>
30 Effect.gen(function* () {
31 const spans: Array<Tracer.NativeSpan> = [];
32 const tracer = Tracer.make({
33 span: (options) => {
34 const span = new Tracer.NativeSpan(options);
35 spans.push(span);
36 return span;
37 },
38 });
39 // The first sample covers startup, so the monitor discards it.
40 const samples = [stalled, quiet, stalled];
41
42 yield* Effect.gen(function* () {
43 yield* Layer.build(layerWith(Effect.succeed(Effect.sync(() => samples.shift() ?? quiet))));
44 yield* TestClock.adjust("60 seconds");
45 assert.lengthOf(spans, 0);
46 yield* TestClock.adjust("30 seconds");
47 }).pipe(Effect.scoped, Effect.withTracer(tracer));
48
49 assert.deepStrictEqual(
50 spans.map((span) => span.name),
51 ["server.eventLoop.stall"],
52 );
53 const [span] = spans;
54 assert.deepStrictEqual(Object.fromEntries(span!.attributes), {
55 delayMaxMs: 4_950,
56 utilization: 0.18,
57 cpuUserMs: 310,
58 cpuSystemMs: 96,
59 majorPageFaults: 8_412,
60 minorPageFaults: 20_031,
61 involuntaryContextSwitches: 57,
62 rssMb: 1536,
63 });
64 assert.deepStrictEqual(
65 span!.events.map(([name, , attributes]) => [name, attributes["effect.logLevel"]]),
66 [["event loop stalled for 4950 ms", "WARN"]],
67 );
68 }),
69 );
70
71 it("ignores delay the loop spent idle, such as a system sleep", () => {
72 // Waking from sleep reads as a long gap, but the loop was idle in poll for it.
73 const asleep: EventLoopReadings = { ...stalled, delayMaxNs: ms(600_000), activeMs: 900 };
74 assert.isUndefined(stallMs(asleep));
75 assert.strictEqual(stallMs({ ...asleep, activeMs: 600_000 }), 599_000);
76 });
77});
apps/server/src/observability/EventLoopMonitor.ts created+135
...@@ -0,0 +1,135 @@
1// @effect-diagnostics nodeBuiltinImport:off - only node:perf_hooks exposes the event loop delay histogram.
2import * as NodePerfHooks from "node:perf_hooks";
3
4import * as Effect from "effect/Effect";
5import * as Layer from "effect/Layer";
6import type * as Scope from "effect/Scope";
7
8// Node's delay histogram wakes a native timer every RESOLUTION_MS and records the
9// gap between wakeups, so an idle loop reads about RESOLUTION_MS and a stall of S
10// reads between S and S + RESOLUTION_MS. We subtract the resolution, so a delay can
11// undercount a stall by up to RESOLUTION_MS. With these values every stall over 3 s
12// is caught, at 1 wakeup per second that never enters JS.
13const RESOLUTION_MS = 1000;
14const STALL_THRESHOLD_MS = 2000;
15const SAMPLE_INTERVAL = "30 seconds";
16
17/** One sample interval as Node reports it. Delay in ns, active time in ms, CPU in µs. */
18export interface EventLoopReadings {
19 readonly delayMaxNs: number;
20 readonly activeMs: number;
21 readonly utilization: number;
22 readonly usage: Pick<
23 NodeJS.ResourceUsage,
24 | "userCPUTime"
25 | "systemCPUTime"
26 | "majorPageFault"
27 | "minorPageFault"
28 | "involuntaryContextSwitches"
29 >;
30 readonly rssBytes: number;
31}
32
33// Enables the delay histogram for the layer's lifetime. Each read returns the
34// readings since the previous read and resets the histogram. Node skips the first
35// gap after a reset, so a stall right at a sample boundary can be missed.
36const makeNodeSampler = Effect.gen(function* () {
37 const histogram = yield* Effect.acquireRelease(
38 Effect.sync(() => {
39 const histogram = NodePerfHooks.monitorEventLoopDelay({ resolution: RESOLUTION_MS });
40 histogram.enable();
41 return histogram;
42 }),
43 (histogram) => Effect.sync(() => histogram.disable()),
44 );
45 let elu = NodePerfHooks.performance.eventLoopUtilization();
46 let usage = process.resourceUsage();
47
48 // @effect-diagnostics-next-line returnEffectInGen:off - the read effect is the result.
49 return Effect.sync(() => {
50 const nextElu = NodePerfHooks.performance.eventLoopUtilization();
51 const nextUsage = process.resourceUsage();
52 const loop = NodePerfHooks.performance.eventLoopUtilization(nextElu, elu);
53 const readings: EventLoopReadings = {
54 delayMaxNs: histogram.max,
55 activeMs: loop.active,
56 utilization: loop.utilization,
57 usage: {
58 userCPUTime: nextUsage.userCPUTime - usage.userCPUTime,
59 systemCPUTime: nextUsage.systemCPUTime - usage.systemCPUTime,
60 majorPageFault: nextUsage.majorPageFault - usage.majorPageFault,
61 minorPageFault: nextUsage.minorPageFault - usage.minorPageFault,
62 involuntaryContextSwitches:
63 nextUsage.involuntaryContextSwitches - usage.involuntaryContextSwitches,
64 },
65 rssBytes: process.memoryUsage.rss(),
66 };
67 histogram.reset();
68 elu = nextElu;
69 usage = nextUsage;
70 return readings;
71 });
72});
73
74/**
75 * Returns the stall to report for one sample in ms, or undefined when there was none.
76 */
77export const stallMs = ({ delayMaxNs, activeMs }: EventLoopReadings) => {
78 const delayMs = Math.round(delayMaxNs / 1e6) - RESOLUTION_MS;
79 // A stall is time the loop spent running code, so it counts as active time. libuv's
80 // clock keeps running while the system sleeps on macOS and Windows, so a sleep also
81 // reads as delay, but the loop spent it idle in poll.
82 if (delayMs <= STALL_THRESHOLD_MS || activeMs < delayMs) return undefined;
83 return delayMs;
84};
85
86/**
87 * Samples event loop health every 30 s and records a `server.eventLoop.stall` span
88 * with a warning when the loop stalled for more than 2 s, so stalls land in
89 * the local trace file and Settings > Diagnostics without OTLP. Takes the sampler
90 * so tests can inject readings.
91 */
92export const layerWith = (
93 makeSampler: Effect.Effect<Effect.Effect<EventLoopReadings>, never, Scope.Scope>,
94) =>
95 Layer.effectDiscard(
96 Effect.gen(function* () {
97 const sample = yield* makeSampler;
98 const tick = Effect.gen(function* () {
99 const readings = yield* sample;
100 const delayMaxMs = stallMs(readings);
101 if (delayMaxMs === undefined) return;
102 const { utilization, usage, rssBytes } = readings;
103 // Root, as the stall has no caller to attach to. Warn level keeps it when
104 // T3CODE_TRACE_MIN_LEVEL is raised to cut trace noise.
105 yield* Effect.logWarning(`event loop stalled for ${delayMaxMs} ms`).pipe(
106 Effect.withSpan("server.eventLoop.stall", {
107 root: true,
108 level: "Warn",
109 attributes: {
110 delayMaxMs,
111 utilization: Math.round(utilization * 100) / 100,
112 cpuUserMs: Math.round(usage.userCPUTime / 1000),
113 cpuSystemMs: Math.round(usage.systemCPUTime / 1000),
114 majorPageFaults: usage.majorPageFault,
115 minorPageFaults: usage.minorPageFault,
116 involuntaryContextSwitches: usage.involuntaryContextSwitches,
117 rssMb: Math.round(rssBytes / 1024 / 1024),
118 },
119 }),
120 );
121 });
122 const wait = Effect.sleep(SAMPLE_INTERVAL);
123 // The layer builds before the rest of the server, so the first sample covers
124 // startup work such as migrations and projection bootstrap. That can block the
125 // loop for seconds on a large database, so skip it rather than warn at every
126 // launch. Layers build outside any span, so this fiber retains no parent span.
127 yield* wait.pipe(
128 Effect.andThen(sample),
129 Effect.andThen(wait.pipe(Effect.andThen(tick), Effect.forever)),
130 Effect.forkScoped,
131 );
132 }),
133 );
134
135export const layer = layerWith(makeNodeSampler);
apps/server/src/server.ts+3-1
...@@ -120,6 +120,7 @@ import * as ProjectSetupScriptRunner from "./project/ProjectSetupScriptRunner.ts...@@ -120,6 +120,7 @@ import * as ProjectSetupScriptRunner from "./project/ProjectSetupScriptRunner.ts
120import * as WorktreeSetupTracker from "./project/WorktreeSetupTracker.ts";120import * as WorktreeSetupTracker from "./project/WorktreeSetupTracker.ts";
121import { ObservabilityLive } from "./observability/Layers/Observability.ts";121import { ObservabilityLive } from "./observability/Layers/Observability.ts";
122import * as HeapSnapshot from "./observability/HeapSnapshot.ts";122import * as HeapSnapshot from "./observability/HeapSnapshot.ts";
123import * as EventLoopMonitor from "./observability/EventLoopMonitor.ts";
123import * as ServerEnvironment from "./environment/ServerEnvironment.ts";124import * as ServerEnvironment from "./environment/ServerEnvironment.ts";
124import * as RemoteOpenTargets from "./environment/RemoteOpenTargets.ts";125import * as RemoteOpenTargets from "./environment/RemoteOpenTargets.ts";
125import { authHttpApiLayer, environmentAuthenticatedAuthLayer } from "./auth/http.ts";126import { authHttpApiLayer, environmentAuthenticatedAuthLayer } from "./auth/http.ts";
...@@ -183,7 +184,8 @@ export const HTTP_ROUTER_CONFIG = {...@@ -183,7 +184,8 @@ export const HTTP_ROUTER_CONFIG = {
183// those finalizers get a chance to run.184// those finalizers get a chance to run.
184const HTTP_PREEMPTIVE_SHUTDOWN_GRACE_MS = 0;185const HTTP_PREEMPTIVE_SHUTDOWN_GRACE_MS = 0;
185const ResourceAttributionLayerLive = ResourceAttribution.layer;186const ResourceAttributionLayerLive = ResourceAttribution.layer;
186const ApplicationObservabilityLive = ObservabilityLive.pipe(187const ApplicationObservabilityLive = EventLoopMonitor.layer.pipe(
188 Layer.provideMerge(ObservabilityLive),
187 Layer.provideMerge(ResourceAttributionLayerLive),189 Layer.provideMerge(ResourceAttributionLayerLive),
188);190);
189191
docs/operations/observability.md+33
...@@ -87,6 +87,38 @@ Metrics are not written to a local file....@@ -87,6 +87,38 @@ Metrics are not written to a local file.
8787
88If OTLP is not configured, metrics still exist in-process, but you will not have a local artifact to inspect.88If OTLP is not configured, metrics still exist in-process, but you will not have a local artifact to inspect.
8989
90### Event Loop Stalls
91
92`apps/server/src/observability/EventLoopMonitor.ts` samples the server's event loop every 30 s. When
93the loop stalled for more than 2 s since the previous sample, it records a root
94`server.eventLoop.stall` span with a warning. The span has trace level `Warn`, so it stays when
95`T3CODE_TRACE_MIN_LEVEL` is `Warn`. The warning shows in Settings > Diagnostics unless OTLP logs are
96on. The span time is when the sample ran, not when the stall happened.
97
98Some delay is not recorded:
99
100- `delayMaxMs` is the longest stall, and can undercount it by up to 1 s. The 2 s threshold applies to
101 this value, so a stall over 3 s is normally recorded, and a shorter one can be missed. A stall
102 that ends just as a sample runs can be missed too.
103- Time the computer spends asleep reads as delay on macOS and Windows. So a sample only counts when
104 the loop was busy, not waiting for events, for at least `delayMaxMs`. Busy time covers the whole
105 window, so a short sleep in an otherwise busy window can still record a false stall. The span then
106 shows CPU time far below `delayMaxMs`.
107- The first sample after launch is skipped. Startup work such as migrations and projection bootstrap
108 can block the loop for seconds on a large database.
109
110CPU times and page faults cover the whole process over the whole window since the previous sample.
111The window is nominally 30 s, but a long stall delays the sample and makes the window longer. Other
112work in the window can hide a wait, so only CPU time far below `delayMaxMs` proves the thread was
113waiting. Read CPU together with page faults:
114
115- High `cpuSystemMs` with many page faults means memory pressure. Major faults are reads from disk or swap.
116 On macOS, reads from compressed memory are minor faults plus system CPU.
117- High `cpuUserMs` with few page faults means JavaScript work or garbage collection.
118- Low CPU with few major page faults points at synchronous disk I/O, such as SQLite reads or trace
119 file writes.
120- Many `involuntaryContextSwitches` mean other processes were competing for the CPU.
121
90### Related Artifacts122### Related Artifacts
91123
92Provider event NDJSON files still exist for provider runtime streams. Those are separate from the main server trace file.124Provider event NDJSON files still exist for provider runtime streams. Those are separate from the main server trace file.
...@@ -612,6 +644,7 @@ Current high-value span and metric boundaries include:...@@ -612,6 +644,7 @@ Current high-value span and metric boundaries include:
612- git command execution and git hook events644- git command execution and git hook events
613- terminal session lifecycle645- terminal session lifecycle
614- sqlite query execution646- sqlite query execution
647- event loop stalls (`server.eventLoop.stall`)
615648
616### Current Constraints649### Current Constraints
617650