From d429d1eca93a220776ce96feddd01a2357071629 Mon Sep 17 00:00:00 2001 From: Theo Browne Date: Fri, 25 Sep 2026 14:10:00 -0700 Subject: [PATCH 1/5] feat(observability): record event loop stalls in the server trace Nothing measured event loop stalls, so long-uptime reports could only infer them from late timers. Metrics and out-of-span logs never reach disk without OTLP, so a gauge alone would not help most users. Add an EventLoopMonitor layer next to the app observability layer. It enables a 200 ms monitorEventLoopDelay histogram and samples every 30 s: delay max/p99/mean, event loop utilization, process CPU, page faults, involuntary context switches, and RSS. When the worst delay passes 1 s, it records a root server.eventLoop.stall span at Warn trace level with a warning, so the stall lands in server.trace.ndjson and Settings > Diagnostics. The max delay is also a t3_event_loop_delay_max_ms gauge for OTLP users. Co-Authored-By: Claude Opus 5.5 (1M context) --- .../observability/EventLoopMonitor.test.ts | 97 +++++++++++++ .../src/observability/EventLoopMonitor.ts | 131 ++++++++++++++++++ apps/server/src/observability/Metrics.ts | 4 + apps/server/src/server.ts | 4 +- docs/operations/observability.md | 38 +++++ 5 files changed, 273 insertions(+), 1 deletion(-) create mode 100644 apps/server/src/observability/EventLoopMonitor.test.ts create mode 100644 apps/server/src/observability/EventLoopMonitor.ts diff --git a/apps/server/src/observability/EventLoopMonitor.test.ts b/apps/server/src/observability/EventLoopMonitor.test.ts new file mode 100644 index 000000000000..e407e314a48a --- /dev/null +++ b/apps/server/src/observability/EventLoopMonitor.test.ts @@ -0,0 +1,97 @@ +import { assert, describe, it } from "@effect/vitest"; +import * as Effect from "effect/Effect"; +import * as Layer from "effect/Layer"; +import * as Tracer from "effect/Tracer"; +import * as TestClock from "effect/testing/TestClock"; + +import { type EventLoopReadings, layerWith, stallAttributes } from "./EventLoopMonitor.ts"; + +const ms = (value: number) => value * 1e6; + +const readings = (overrides: Partial): EventLoopReadings => ({ + delayMaxNs: ms(202), + delayP99Ns: ms(202), + delayMeanNs: ms(201), + utilization: 0.02, + usage: { + userCPUTime: 40_000, + systemCPUTime: 10_000, + majorPageFault: 0, + minorPageFault: 12, + involuntaryContextSwitches: 3, + }, + rssBytes: 256 * 1024 * 1024, + ...overrides, +}); + +const stalled = readings({ + delayMaxNs: ms(5_150), + delayP99Ns: ms(5_150), + delayMeanNs: ms(460), + utilization: 0.987, + usage: { + userCPUTime: 310_400, + systemCPUTime: 95_600, + majorPageFault: 8_412, + minorPageFault: 20_031, + involuntaryContextSwitches: 57, + }, + rssBytes: 1536 * 1024 * 1024, +}); + +const stalledAttributes = { + delayMaxMs: 4_950, + delayP99Ms: 4_950, + delayMeanMs: 260, + utilization: 0.99, + cpuUserMs: 310, + cpuSystemMs: 96, + majorPageFaults: 8_412, + minorPageFaults: 20_031, + involuntaryContextSwitches: 57, + rssMb: 1536, +}; + +describe("stallAttributes", () => { + it("treats an idle loop as no stall", () => { + assert.isUndefined(stallAttributes(readings({}), 1000)); + }); + + it("reports a stall past the threshold without the histogram resolution", () => { + assert.deepStrictEqual(stallAttributes(stalled, 1000), stalledAttributes); + assert.isUndefined(stallAttributes(stalled, 5000)); + }); +}); + +describe("EventLoopMonitor", () => { + it.effect("records a stall span with a warning after one sample interval", () => + Effect.gen(function* () { + const spans: Array = []; + const tracer = Tracer.make({ + span: (options) => { + const span = new Tracer.NativeSpan(options); + spans.push(span); + return span; + }, + }); + + yield* Effect.gen(function* () { + yield* Layer.build(layerWith(Effect.succeed(Effect.succeed(stalled)))); + yield* TestClock.adjust("29 seconds"); + assert.lengthOf(spans, 0); + yield* TestClock.adjust("1 second"); + }).pipe(Effect.scoped, Effect.withTracer(tracer)); + + assert.deepStrictEqual( + spans.map((span) => span.name), + ["server.eventLoop.stall"], + ); + const [span] = spans; + assert.deepStrictEqual(Object.fromEntries(span!.attributes), stalledAttributes); + assert.deepStrictEqual( + span!.events.map(([name, , attributes]) => [name, attributes["effect.logLevel"]]), + [["event loop stalled for 4950 ms", "WARN"]], + ); + }), + ); +}); diff --git a/apps/server/src/observability/EventLoopMonitor.ts b/apps/server/src/observability/EventLoopMonitor.ts new file mode 100644 index 000000000000..e48adc6d41d7 --- /dev/null +++ b/apps/server/src/observability/EventLoopMonitor.ts @@ -0,0 +1,131 @@ +// @effect-diagnostics nodeBuiltinImport:off +import * as NodePerfHooks from "node:perf_hooks"; + +import * as Effect from "effect/Effect"; +import * as Layer from "effect/Layer"; +import * as Metric from "effect/Metric"; +import * as Schedule from "effect/Schedule"; +import type * as Scope from "effect/Scope"; + +import { eventLoopDelayMax } from "./Metrics.ts"; + +// Node's delay histogram wakes a native timer every RESOLUTION_MS and records the +// gap between wakeups, so an idle loop reads about RESOLUTION_MS and a stall of S +// reads between S and S + RESOLUTION_MS. We subtract the resolution, so a delay can +// undercount a stall by up to RESOLUTION_MS. Keeping it at a fifth of the threshold +// catches every stall of 1.2 s or more, at 5 wakeups per second that never enter JS. +const RESOLUTION_MS = 200; +const STALL_THRESHOLD_MS = 1000; +const SAMPLE_INTERVAL = "30 seconds"; + +/** One sample interval as Node reports it. Delays in ns, CPU times in µs. */ +export interface EventLoopReadings { + readonly delayMaxNs: number; + readonly delayP99Ns: number; + readonly delayMeanNs: number; + readonly utilization: number; + readonly usage: Pick< + NodeJS.ResourceUsage, + | "userCPUTime" + | "systemCPUTime" + | "majorPageFault" + | "minorPageFault" + | "involuntaryContextSwitches" + >; + readonly rssBytes: number; +} + +const delayMs = (ns: number) => Math.max(0, Math.round(ns / 1e6 - RESOLUTION_MS)); + +/** Span attributes for an interval whose worst delay passed `thresholdMs`, or undefined. */ +export const stallAttributes = (readings: EventLoopReadings, thresholdMs: number) => { + const delayMaxMs = delayMs(readings.delayMaxNs); + if (delayMaxMs <= thresholdMs) return undefined; + return { + delayMaxMs, + delayP99Ms: delayMs(readings.delayP99Ns), + delayMeanMs: delayMs(readings.delayMeanNs), + utilization: Math.round(readings.utilization * 100) / 100, + cpuUserMs: Math.round(readings.usage.userCPUTime / 1000), + cpuSystemMs: Math.round(readings.usage.systemCPUTime / 1000), + majorPageFaults: readings.usage.majorPageFault, + minorPageFaults: readings.usage.minorPageFault, + involuntaryContextSwitches: readings.usage.involuntaryContextSwitches, + rssMb: Math.round(readings.rssBytes / 1024 / 1024), + }; +}; + +// Enables the delay histogram for the layer's lifetime. Each read returns the +// readings since the previous read and resets the histogram. Node skips the first +// gap after a reset, so a stall right at a sample boundary can be missed. +const makeNodeSampler = Effect.gen(function* () { + const histogram = yield* Effect.acquireRelease( + Effect.sync(() => { + const histogram = NodePerfHooks.monitorEventLoopDelay({ resolution: RESOLUTION_MS }); + histogram.enable(); + return histogram; + }), + (histogram) => Effect.sync(() => histogram.disable()), + ); + let elu = NodePerfHooks.performance.eventLoopUtilization(); + let usage = process.resourceUsage(); + + // @effect-diagnostics-next-line returnEffectInGen:off - the read effect is the result. + return Effect.sync(() => { + const nextElu = NodePerfHooks.performance.eventLoopUtilization(); + const nextUsage = process.resourceUsage(); + const readings: EventLoopReadings = { + delayMaxNs: histogram.max, + delayP99Ns: histogram.percentile(99), + delayMeanNs: histogram.mean, + utilization: NodePerfHooks.performance.eventLoopUtilization(nextElu, elu).utilization, + usage: { + userCPUTime: nextUsage.userCPUTime - usage.userCPUTime, + systemCPUTime: nextUsage.systemCPUTime - usage.systemCPUTime, + majorPageFault: nextUsage.majorPageFault - usage.majorPageFault, + minorPageFault: nextUsage.minorPageFault - usage.minorPageFault, + involuntaryContextSwitches: + nextUsage.involuntaryContextSwitches - usage.involuntaryContextSwitches, + }, + rssBytes: process.memoryUsage.rss(), + }; + histogram.reset(); + elu = nextElu; + usage = nextUsage; + return readings; + }); +}); + +/** + * Samples event loop health every 30 s and records a `server.eventLoop.stall` span + * with a warning when the loop stalled for more than a second, so stalls land in + * the local trace file and Settings > Diagnostics without OTLP. Takes the sampler + * so tests can inject readings. + */ +export const layerWith = ( + makeSampler: Effect.Effect, never, Scope.Scope>, +) => + Layer.effectDiscard( + Effect.gen(function* () { + const sample = yield* makeSampler; + const tick = Effect.gen(function* () { + const readings = yield* sample; + yield* Metric.update(eventLoopDelayMax, delayMs(readings.delayMaxNs)); + const attributes = stallAttributes(readings, STALL_THRESHOLD_MS); + if (attributes === undefined) return; + // A root span, as the stall has no caller to attach to. Warn level keeps it + // when T3CODE_TRACE_MIN_LEVEL is raised to cut trace noise. + yield* Effect.logWarning(`event loop stalled for ${attributes.delayMaxMs} ms`).pipe( + Effect.withSpan("server.eventLoop.stall", { root: true, level: "Warn", attributes }), + ); + }); + // Layers build outside any span, so this fiber retains no parent span. + yield* tick.pipe( + Effect.repeat(Schedule.spaced(SAMPLE_INTERVAL)), + Effect.delay(SAMPLE_INTERVAL), + Effect.forkScoped, + ); + }), + ); + +export const layer = layerWith(makeNodeSampler); diff --git a/apps/server/src/observability/Metrics.ts b/apps/server/src/observability/Metrics.ts index 886833d6e2c7..48fa0ff536f8 100644 --- a/apps/server/src/observability/Metrics.ts +++ b/apps/server/src/observability/Metrics.ts @@ -74,6 +74,10 @@ export const terminalRestartsTotal = Metric.counter("t3_terminal_restarts_total" description: "Total terminal restart requests handled.", }); +export const eventLoopDelayMax = Metric.gauge("t3_event_loop_delay_max_ms", { + description: "Longest event loop delay in the last 30 s sample, in milliseconds.", +}); + export const metricAttributes = ( attributes: Readonly>, ): ReadonlyArray<[string, string]> => Object.entries(compactMetricAttributes(attributes)); diff --git a/apps/server/src/server.ts b/apps/server/src/server.ts index e64b0702eb83..c22b48519da2 100644 --- a/apps/server/src/server.ts +++ b/apps/server/src/server.ts @@ -120,6 +120,7 @@ import * as ProjectSetupScriptRunner from "./project/ProjectSetupScriptRunner.ts import * as WorktreeSetupTracker from "./project/WorktreeSetupTracker.ts"; import { ObservabilityLive } from "./observability/Layers/Observability.ts"; import * as HeapSnapshot from "./observability/HeapSnapshot.ts"; +import * as EventLoopMonitor from "./observability/EventLoopMonitor.ts"; import * as ServerEnvironment from "./environment/ServerEnvironment.ts"; import * as RemoteOpenTargets from "./environment/RemoteOpenTargets.ts"; import { authHttpApiLayer, environmentAuthenticatedAuthLayer } from "./auth/http.ts"; @@ -183,7 +184,8 @@ export const HTTP_ROUTER_CONFIG = { // those finalizers get a chance to run. const HTTP_PREEMPTIVE_SHUTDOWN_GRACE_MS = 0; const ResourceAttributionLayerLive = ResourceAttribution.layer; -const ApplicationObservabilityLive = ObservabilityLive.pipe( +const ApplicationObservabilityLive = EventLoopMonitor.layer.pipe( + Layer.provideMerge(ObservabilityLive), Layer.provideMerge(ResourceAttributionLayerLive), ); diff --git a/docs/operations/observability.md b/docs/operations/observability.md index d9dac58e2c3b..11f2fd860bbf 100644 --- a/docs/operations/observability.md +++ b/docs/operations/observability.md @@ -87,6 +87,43 @@ Metrics are not written to a local file. If OTLP is not configured, metrics still exist in-process, but you will not have a local artifact to inspect. +### Event Loop Stalls + +`apps/server/src/observability/EventLoopMonitor.ts` samples the server's event loop every 30 s. When +the loop was blocked for more than 1 s in that window, it records a root `server.eventLoop.stall` +span with a warning. The span has trace level `Warn`, so it stays when `T3CODE_TRACE_MIN_LEVEL` is +`Warn`. The span lands in the trace file, and the warning shows in Settings > Diagnostics unless +OTLP logs are on. The span time is when the sample ran; the stall happened in the 30 s before it. + +Attributes cover that 30 s window: + +- `delayMaxMs`, `delayP99Ms`, `delayMeanMs`: how late the loop ran. The max can undercount a stall + by up to 200 ms. +- `utilization`: the fraction of the window the loop was busy. +- `cpuUserMs`, `cpuSystemMs`: CPU time for the whole process, all threads. +- `majorPageFaults`, `minorPageFaults`: major faults read memory back from disk or swap. +- `involuntaryContextSwitches`: times the OS took the CPU away from the process. +- `rssMb`: resident memory at sample time. + +To read a stall, remember that the CPU times cover the full 30 s window and all threads, but +`delayMaxMs` is one stall. Other work in the same window can hide a wait. Only CPU time far below +`delayMaxMs` shows that the thread was waiting. In other cases, read the user and system CPU split +together with the page faults: + +- High `cpuSystemMs` with many page faults means memory pressure. Reads from swap are major faults. + On macOS, reads from compressed memory are minor faults plus system CPU. +- High `cpuUserMs` with few page faults means the process was computing: JavaScript work or garbage + collection. +- Low CPU with few major page faults points at synchronous disk I/O, such as SQLite reads or trace + file writes. +- Many `involuntaryContextSwitches` mean other processes were competing for the CPU. + +The first sample after launch includes server startup, such as migrations and projection bootstrap. +With a large database, this can record a stall at each launch. That stall is real. + +Every sample's max delay is also exported as the `t3_event_loop_delay_max_ms` gauge when OTLP +metrics are on. + ### Related Artifacts Provider event NDJSON files still exist for provider runtime streams. Those are separate from the main server trace file. @@ -612,6 +649,7 @@ Current high-value span and metric boundaries include: - git command execution and git hook events - terminal session lifecycle - sqlite query execution +- event loop stalls (`server.eventLoop.stall`) and the `t3_event_loop_delay_max_ms` gauge ### Current Constraints From 122b1229a1448eececdc783ba35637fda5e2303a Mon Sep 17 00:00:00 2001 From: Theo Browne Date: Fri, 25 Sep 2026 14:35:48 -0700 Subject: [PATCH 2/5] docs(observability): describe the stall window as since the previous sample A stall delays the next sample, so the gauge and span attributes can cover more than 30 s. Say so in the gauge description and the docs, and explain the perf_hooks diagnostic suppression. Co-Authored-By: Claude Opus 5.5 (1M context) --- apps/server/src/observability/EventLoopMonitor.ts | 2 +- apps/server/src/observability/Metrics.ts | 3 ++- docs/operations/observability.md | 9 +++++---- 3 files changed, 8 insertions(+), 6 deletions(-) diff --git a/apps/server/src/observability/EventLoopMonitor.ts b/apps/server/src/observability/EventLoopMonitor.ts index e48adc6d41d7..a415d03fd199 100644 --- a/apps/server/src/observability/EventLoopMonitor.ts +++ b/apps/server/src/observability/EventLoopMonitor.ts @@ -1,4 +1,4 @@ -// @effect-diagnostics nodeBuiltinImport:off +// @effect-diagnostics nodeBuiltinImport:off - only node:perf_hooks exposes the event loop delay histogram. import * as NodePerfHooks from "node:perf_hooks"; import * as Effect from "effect/Effect"; diff --git a/apps/server/src/observability/Metrics.ts b/apps/server/src/observability/Metrics.ts index 48fa0ff536f8..8ccf0dedbe0a 100644 --- a/apps/server/src/observability/Metrics.ts +++ b/apps/server/src/observability/Metrics.ts @@ -75,7 +75,8 @@ export const terminalRestartsTotal = Metric.counter("t3_terminal_restarts_total" }); export const eventLoopDelayMax = Metric.gauge("t3_event_loop_delay_max_ms", { - description: "Longest event loop delay in the last 30 s sample, in milliseconds.", + description: + "Longest event loop delay since the previous sample (nominally 30 s), in milliseconds.", }); export const metricAttributes = ( diff --git a/docs/operations/observability.md b/docs/operations/observability.md index 11f2fd860bbf..0a249c0ad9f8 100644 --- a/docs/operations/observability.md +++ b/docs/operations/observability.md @@ -90,12 +90,13 @@ If OTLP is not configured, metrics still exist in-process, but you will not have ### Event Loop Stalls `apps/server/src/observability/EventLoopMonitor.ts` samples the server's event loop every 30 s. When -the loop was blocked for more than 1 s in that window, it records a root `server.eventLoop.stall` +the loop was blocked for more than 1 s since the previous sample, it records a root `server.eventLoop.stall` span with a warning. The span has trace level `Warn`, so it stays when `T3CODE_TRACE_MIN_LEVEL` is `Warn`. The span lands in the trace file, and the warning shows in Settings > Diagnostics unless -OTLP logs are on. The span time is when the sample ran; the stall happened in the 30 s before it. +OTLP logs are on. The span time is when the sample ran; the stall happened since the previous sample. -Attributes cover that 30 s window: +Attributes cover the window since the previous sample. That is nominally 30 s, but a stall delays the +next sample, so a long stall makes the window longer: - `delayMaxMs`, `delayP99Ms`, `delayMeanMs`: how late the loop ran. The max can undercount a stall by up to 200 ms. @@ -105,7 +106,7 @@ Attributes cover that 30 s window: - `involuntaryContextSwitches`: times the OS took the CPU away from the process. - `rssMb`: resident memory at sample time. -To read a stall, remember that the CPU times cover the full 30 s window and all threads, but +To read a stall, remember that the CPU times cover the full window and all threads, but `delayMaxMs` is one stall. Other work in the same window can hide a wait. Only CPU time far below `delayMaxMs` shows that the thread was waiting. In other cases, read the user and system CPU split together with the page faults: From 3539f06d6ec9870018ba4adb67d1bed0d37f97d8 Mon Sep 17 00:00:00 2001 From: Theo Browne Date: Fri, 25 Sep 2026 18:11:02 -0700 Subject: [PATCH 3/5] refactor(observability): trim the event loop stall monitor Drop the OTLP gauge and the p99 and mean delay attributes. The stall span is the record users need, and the max delay with CPU and page faults is enough to read it. Inline the attribute helper, run the sampler as sleep-then-tick, and cover the threshold, the resolution offset, and the first-sample delay in one test. Shorten the docs section to what a reader needs to interpret a stall. Co-Authored-By: Claude Opus 5.5 (1M context) --- .../observability/EventLoopMonitor.test.ts | 69 ++++++------------- .../src/observability/EventLoopMonitor.ts | 64 +++++++---------- apps/server/src/observability/Metrics.ts | 5 -- docs/operations/observability.md | 46 +++++-------- 4 files changed, 60 insertions(+), 124 deletions(-) diff --git a/apps/server/src/observability/EventLoopMonitor.test.ts b/apps/server/src/observability/EventLoopMonitor.test.ts index e407e314a48a..92b48c6595d8 100644 --- a/apps/server/src/observability/EventLoopMonitor.test.ts +++ b/apps/server/src/observability/EventLoopMonitor.test.ts @@ -4,30 +4,13 @@ import * as Layer from "effect/Layer"; import * as Tracer from "effect/Tracer"; import * as TestClock from "effect/testing/TestClock"; -import { type EventLoopReadings, layerWith, stallAttributes } from "./EventLoopMonitor.ts"; +import { type EventLoopReadings, layerWith } from "./EventLoopMonitor.ts"; const ms = (value: number) => value * 1e6; -const readings = (overrides: Partial): EventLoopReadings => ({ - delayMaxNs: ms(202), - delayP99Ns: ms(202), - delayMeanNs: ms(201), - utilization: 0.02, - usage: { - userCPUTime: 40_000, - systemCPUTime: 10_000, - majorPageFault: 0, - minorPageFault: 12, - involuntaryContextSwitches: 3, - }, - rssBytes: 256 * 1024 * 1024, - ...overrides, -}); - -const stalled = readings({ +// Node reports a stall of S as a gap of up to S + 200 ms, the histogram resolution. +const stalled: EventLoopReadings = { delayMaxNs: ms(5_150), - delayP99Ns: ms(5_150), - delayMeanNs: ms(460), utilization: 0.987, usage: { userCPUTime: 310_400, @@ -37,34 +20,12 @@ const stalled = readings({ involuntaryContextSwitches: 57, }, rssBytes: 1536 * 1024 * 1024, -}); - -const stalledAttributes = { - delayMaxMs: 4_950, - delayP99Ms: 4_950, - delayMeanMs: 260, - utilization: 0.99, - cpuUserMs: 310, - cpuSystemMs: 96, - majorPageFaults: 8_412, - minorPageFaults: 20_031, - involuntaryContextSwitches: 57, - rssMb: 1536, }; - -describe("stallAttributes", () => { - it("treats an idle loop as no stall", () => { - assert.isUndefined(stallAttributes(readings({}), 1000)); - }); - - it("reports a stall past the threshold without the histogram resolution", () => { - assert.deepStrictEqual(stallAttributes(stalled, 1000), stalledAttributes); - assert.isUndefined(stallAttributes(stalled, 5000)); - }); -}); +// Over the threshold as read, but not once the resolution is subtracted. +const quiet: EventLoopReadings = { ...stalled, delayMaxNs: ms(1_150) }; describe("EventLoopMonitor", () => { - it.effect("records a stall span with a warning after one sample interval", () => + it.effect("records a warning span only for samples that saw a stall", () => Effect.gen(function* () { const spans: Array = []; const tracer = Tracer.make({ @@ -74,12 +35,13 @@ describe("EventLoopMonitor", () => { return span; }, }); + const samples = [quiet, stalled]; yield* Effect.gen(function* () { - yield* Layer.build(layerWith(Effect.succeed(Effect.succeed(stalled)))); - yield* TestClock.adjust("29 seconds"); + yield* Layer.build(layerWith(Effect.succeed(Effect.sync(() => samples.shift() ?? quiet)))); + yield* TestClock.adjust("30 seconds"); assert.lengthOf(spans, 0); - yield* TestClock.adjust("1 second"); + yield* TestClock.adjust("30 seconds"); }).pipe(Effect.scoped, Effect.withTracer(tracer)); assert.deepStrictEqual( @@ -87,7 +49,16 @@ describe("EventLoopMonitor", () => { ["server.eventLoop.stall"], ); const [span] = spans; - assert.deepStrictEqual(Object.fromEntries(span!.attributes), stalledAttributes); + assert.deepStrictEqual(Object.fromEntries(span!.attributes), { + delayMaxMs: 4_950, + utilization: 0.99, + cpuUserMs: 310, + cpuSystemMs: 96, + majorPageFaults: 8_412, + minorPageFaults: 20_031, + involuntaryContextSwitches: 57, + rssMb: 1536, + }); assert.deepStrictEqual( span!.events.map(([name, , attributes]) => [name, attributes["effect.logLevel"]]), [["event loop stalled for 4950 ms", "WARN"]], diff --git a/apps/server/src/observability/EventLoopMonitor.ts b/apps/server/src/observability/EventLoopMonitor.ts index a415d03fd199..7931a3f58ea5 100644 --- a/apps/server/src/observability/EventLoopMonitor.ts +++ b/apps/server/src/observability/EventLoopMonitor.ts @@ -3,12 +3,8 @@ import * as NodePerfHooks from "node:perf_hooks"; import * as Effect from "effect/Effect"; import * as Layer from "effect/Layer"; -import * as Metric from "effect/Metric"; -import * as Schedule from "effect/Schedule"; import type * as Scope from "effect/Scope"; -import { eventLoopDelayMax } from "./Metrics.ts"; - // Node's delay histogram wakes a native timer every RESOLUTION_MS and records the // gap between wakeups, so an idle loop reads about RESOLUTION_MS and a stall of S // reads between S and S + RESOLUTION_MS. We subtract the resolution, so a delay can @@ -18,11 +14,9 @@ const RESOLUTION_MS = 200; const STALL_THRESHOLD_MS = 1000; const SAMPLE_INTERVAL = "30 seconds"; -/** One sample interval as Node reports it. Delays in ns, CPU times in µs. */ +/** One sample interval as Node reports it. Delay in ns, CPU times in µs. */ export interface EventLoopReadings { readonly delayMaxNs: number; - readonly delayP99Ns: number; - readonly delayMeanNs: number; readonly utilization: number; readonly usage: Pick< NodeJS.ResourceUsage, @@ -35,26 +29,6 @@ export interface EventLoopReadings { readonly rssBytes: number; } -const delayMs = (ns: number) => Math.max(0, Math.round(ns / 1e6 - RESOLUTION_MS)); - -/** Span attributes for an interval whose worst delay passed `thresholdMs`, or undefined. */ -export const stallAttributes = (readings: EventLoopReadings, thresholdMs: number) => { - const delayMaxMs = delayMs(readings.delayMaxNs); - if (delayMaxMs <= thresholdMs) return undefined; - return { - delayMaxMs, - delayP99Ms: delayMs(readings.delayP99Ns), - delayMeanMs: delayMs(readings.delayMeanNs), - utilization: Math.round(readings.utilization * 100) / 100, - cpuUserMs: Math.round(readings.usage.userCPUTime / 1000), - cpuSystemMs: Math.round(readings.usage.systemCPUTime / 1000), - majorPageFaults: readings.usage.majorPageFault, - minorPageFaults: readings.usage.minorPageFault, - involuntaryContextSwitches: readings.usage.involuntaryContextSwitches, - rssMb: Math.round(readings.rssBytes / 1024 / 1024), - }; -}; - // Enables the delay histogram for the layer's lifetime. Each read returns the // readings since the previous read and resets the histogram. Node skips the first // gap after a reset, so a stall right at a sample boundary can be missed. @@ -76,8 +50,6 @@ const makeNodeSampler = Effect.gen(function* () { const nextUsage = process.resourceUsage(); const readings: EventLoopReadings = { delayMaxNs: histogram.max, - delayP99Ns: histogram.percentile(99), - delayMeanNs: histogram.mean, utilization: NodePerfHooks.performance.eventLoopUtilization(nextElu, elu).utilization, usage: { userCPUTime: nextUsage.userCPUTime - usage.userCPUTime, @@ -109,20 +81,32 @@ export const layerWith = ( Effect.gen(function* () { const sample = yield* makeSampler; const tick = Effect.gen(function* () { - const readings = yield* sample; - yield* Metric.update(eventLoopDelayMax, delayMs(readings.delayMaxNs)); - const attributes = stallAttributes(readings, STALL_THRESHOLD_MS); - if (attributes === undefined) return; - // A root span, as the stall has no caller to attach to. Warn level keeps it - // when T3CODE_TRACE_MIN_LEVEL is raised to cut trace noise. - yield* Effect.logWarning(`event loop stalled for ${attributes.delayMaxMs} ms`).pipe( - Effect.withSpan("server.eventLoop.stall", { root: true, level: "Warn", attributes }), + const { delayMaxNs, utilization, usage, rssBytes } = yield* sample; + const delayMaxMs = Math.round(delayMaxNs / 1e6) - RESOLUTION_MS; + if (delayMaxMs <= STALL_THRESHOLD_MS) return; + // Root, as the stall has no caller to attach to. Warn level keeps it when + // T3CODE_TRACE_MIN_LEVEL is raised to cut trace noise. + yield* Effect.logWarning(`event loop stalled for ${delayMaxMs} ms`).pipe( + Effect.withSpan("server.eventLoop.stall", { + root: true, + level: "Warn", + attributes: { + delayMaxMs, + utilization: Math.round(utilization * 100) / 100, + cpuUserMs: Math.round(usage.userCPUTime / 1000), + cpuSystemMs: Math.round(usage.systemCPUTime / 1000), + majorPageFaults: usage.majorPageFault, + minorPageFaults: usage.minorPageFault, + involuntaryContextSwitches: usage.involuntaryContextSwitches, + rssMb: Math.round(rssBytes / 1024 / 1024), + }, + }), ); }); // Layers build outside any span, so this fiber retains no parent span. - yield* tick.pipe( - Effect.repeat(Schedule.spaced(SAMPLE_INTERVAL)), - Effect.delay(SAMPLE_INTERVAL), + yield* Effect.sleep(SAMPLE_INTERVAL).pipe( + Effect.andThen(tick), + Effect.forever, Effect.forkScoped, ); }), diff --git a/apps/server/src/observability/Metrics.ts b/apps/server/src/observability/Metrics.ts index 8ccf0dedbe0a..886833d6e2c7 100644 --- a/apps/server/src/observability/Metrics.ts +++ b/apps/server/src/observability/Metrics.ts @@ -74,11 +74,6 @@ export const terminalRestartsTotal = Metric.counter("t3_terminal_restarts_total" description: "Total terminal restart requests handled.", }); -export const eventLoopDelayMax = Metric.gauge("t3_event_loop_delay_max_ms", { - description: - "Longest event loop delay since the previous sample (nominally 30 s), in milliseconds.", -}); - export const metricAttributes = ( attributes: Readonly>, ): ReadonlyArray<[string, string]> => Object.entries(compactMetricAttributes(attributes)); diff --git a/docs/operations/observability.md b/docs/operations/observability.md index 0a249c0ad9f8..ef65039282bd 100644 --- a/docs/operations/observability.md +++ b/docs/operations/observability.md @@ -90,40 +90,26 @@ If OTLP is not configured, metrics still exist in-process, but you will not have ### Event Loop Stalls `apps/server/src/observability/EventLoopMonitor.ts` samples the server's event loop every 30 s. When -the loop was blocked for more than 1 s since the previous sample, it records a root `server.eventLoop.stall` -span with a warning. The span has trace level `Warn`, so it stays when `T3CODE_TRACE_MIN_LEVEL` is -`Warn`. The span lands in the trace file, and the warning shows in Settings > Diagnostics unless -OTLP logs are on. The span time is when the sample ran; the stall happened since the previous sample. - -Attributes cover the window since the previous sample. That is nominally 30 s, but a stall delays the -next sample, so a long stall makes the window longer: - -- `delayMaxMs`, `delayP99Ms`, `delayMeanMs`: how late the loop ran. The max can undercount a stall - by up to 200 ms. -- `utilization`: the fraction of the window the loop was busy. -- `cpuUserMs`, `cpuSystemMs`: CPU time for the whole process, all threads. -- `majorPageFaults`, `minorPageFaults`: major faults read memory back from disk or swap. -- `involuntaryContextSwitches`: times the OS took the CPU away from the process. -- `rssMb`: resident memory at sample time. - -To read a stall, remember that the CPU times cover the full window and all threads, but -`delayMaxMs` is one stall. Other work in the same window can hide a wait. Only CPU time far below -`delayMaxMs` shows that the thread was waiting. In other cases, read the user and system CPU split -together with the page faults: - -- High `cpuSystemMs` with many page faults means memory pressure. Reads from swap are major faults. +the loop stalled for more than 1 s since the previous sample, it records a root +`server.eventLoop.stall` span with a warning. The span has trace level `Warn`, so it stays when +`T3CODE_TRACE_MIN_LEVEL` is `Warn`. The warning shows in Settings > Diagnostics unless OTLP logs are +on. The span time is when the sample ran, not when the stall happened. + +`delayMaxMs` is the longest stall, and can undercount it by up to 200 ms. CPU times and page faults +cover the whole process over the whole window since the previous sample. The window is nominally +30 s, but a long stall delays the sample and makes the window longer. Other work in the window can +hide a wait, so only CPU time far below `delayMaxMs` proves the thread was waiting. Read CPU together +with page faults: + +- High `cpuSystemMs` with many page faults means memory pressure. Major faults are reads from disk or swap. On macOS, reads from compressed memory are minor faults plus system CPU. -- High `cpuUserMs` with few page faults means the process was computing: JavaScript work or garbage - collection. +- High `cpuUserMs` with few page faults means JavaScript work or garbage collection. - Low CPU with few major page faults points at synchronous disk I/O, such as SQLite reads or trace file writes. - Many `involuntaryContextSwitches` mean other processes were competing for the CPU. -The first sample after launch includes server startup, such as migrations and projection bootstrap. -With a large database, this can record a stall at each launch. That stall is real. - -Every sample's max delay is also exported as the `t3_event_loop_delay_max_ms` gauge when OTLP -metrics are on. +The first sample after launch includes startup, such as migrations and projection bootstrap. With a +large database, this can record a real stall at each launch. ### Related Artifacts @@ -650,7 +636,7 @@ Current high-value span and metric boundaries include: - git command execution and git hook events - terminal session lifecycle - sqlite query execution -- event loop stalls (`server.eventLoop.stall`) and the `t3_event_loop_delay_max_ms` gauge +- event loop stalls (`server.eventLoop.stall`) ### Current Constraints From 8111baed67d4450d837d55c5cd19b655e01f2356 Mon Sep 17 00:00:00 2001 From: Theo Browne Date: Fri, 25 Sep 2026 18:27:30 -0700 Subject: [PATCH 4/5] fix(observability): skip system sleep and startup in the stall monitor libuv's clock keeps running while macOS and Windows sleep, so each wake read as a stall. A sample now only counts when event loop active time covers the delay. The first sample after launch is discarded, since startup work blocks the loop by design. The histogram resolution is now 1 s with a 2 s threshold, which still catches every stall over 3 s. Co-Authored-By: Claude Opus 5.5 (1M context) --- .../observability/EventLoopMonitor.test.ts | 25 ++++++---- .../src/observability/EventLoopMonitor.ts | 48 +++++++++++++------ docs/operations/observability.md | 23 +++++---- 3 files changed, 65 insertions(+), 31 deletions(-) diff --git a/apps/server/src/observability/EventLoopMonitor.test.ts b/apps/server/src/observability/EventLoopMonitor.test.ts index 92b48c6595d8..fbe30157aec2 100644 --- a/apps/server/src/observability/EventLoopMonitor.test.ts +++ b/apps/server/src/observability/EventLoopMonitor.test.ts @@ -4,14 +4,15 @@ import * as Layer from "effect/Layer"; import * as Tracer from "effect/Tracer"; import * as TestClock from "effect/testing/TestClock"; -import { type EventLoopReadings, layerWith } from "./EventLoopMonitor.ts"; +import { type EventLoopReadings, layerWith, stallMs } from "./EventLoopMonitor.ts"; const ms = (value: number) => value * 1e6; -// Node reports a stall of S as a gap of up to S + 200 ms, the histogram resolution. +// Node reports a stall of S as a gap of up to S + 1 s, the histogram resolution. const stalled: EventLoopReadings = { - delayMaxNs: ms(5_150), - utilization: 0.987, + delayMaxNs: ms(5_950), + activeMs: 6_200, + utilization: 0.176, usage: { userCPUTime: 310_400, systemCPUTime: 95_600, @@ -22,7 +23,7 @@ const stalled: EventLoopReadings = { rssBytes: 1536 * 1024 * 1024, }; // Over the threshold as read, but not once the resolution is subtracted. -const quiet: EventLoopReadings = { ...stalled, delayMaxNs: ms(1_150) }; +const quiet: EventLoopReadings = { ...stalled, delayMaxNs: ms(2_950) }; describe("EventLoopMonitor", () => { it.effect("records a warning span only for samples that saw a stall", () => @@ -35,11 +36,12 @@ describe("EventLoopMonitor", () => { return span; }, }); - const samples = [quiet, stalled]; + // The first sample covers startup, so the monitor discards it. + const samples = [stalled, quiet, stalled]; yield* Effect.gen(function* () { yield* Layer.build(layerWith(Effect.succeed(Effect.sync(() => samples.shift() ?? quiet)))); - yield* TestClock.adjust("30 seconds"); + yield* TestClock.adjust("60 seconds"); assert.lengthOf(spans, 0); yield* TestClock.adjust("30 seconds"); }).pipe(Effect.scoped, Effect.withTracer(tracer)); @@ -51,7 +53,7 @@ describe("EventLoopMonitor", () => { const [span] = spans; assert.deepStrictEqual(Object.fromEntries(span!.attributes), { delayMaxMs: 4_950, - utilization: 0.99, + utilization: 0.18, cpuUserMs: 310, cpuSystemMs: 96, majorPageFaults: 8_412, @@ -65,4 +67,11 @@ describe("EventLoopMonitor", () => { ); }), ); + + it("ignores delay the loop spent idle, such as a system sleep", () => { + // Waking from sleep reads as a long gap, but the loop was idle in poll for it. + const asleep: EventLoopReadings = { ...stalled, delayMaxNs: ms(600_000), activeMs: 900 }; + assert.isUndefined(stallMs(asleep)); + assert.strictEqual(stallMs({ ...asleep, activeMs: 600_000 }), 599_000); + }); }); diff --git a/apps/server/src/observability/EventLoopMonitor.ts b/apps/server/src/observability/EventLoopMonitor.ts index 7931a3f58ea5..13b7b48c4cf7 100644 --- a/apps/server/src/observability/EventLoopMonitor.ts +++ b/apps/server/src/observability/EventLoopMonitor.ts @@ -8,15 +8,16 @@ import type * as Scope from "effect/Scope"; // Node's delay histogram wakes a native timer every RESOLUTION_MS and records the // gap between wakeups, so an idle loop reads about RESOLUTION_MS and a stall of S // reads between S and S + RESOLUTION_MS. We subtract the resolution, so a delay can -// undercount a stall by up to RESOLUTION_MS. Keeping it at a fifth of the threshold -// catches every stall of 1.2 s or more, at 5 wakeups per second that never enter JS. -const RESOLUTION_MS = 200; -const STALL_THRESHOLD_MS = 1000; +// undercount a stall by up to RESOLUTION_MS. With these values every stall over 3 s +// is caught, at 1 wakeup per second that never enters JS. +const RESOLUTION_MS = 1000; +const STALL_THRESHOLD_MS = 2000; const SAMPLE_INTERVAL = "30 seconds"; -/** One sample interval as Node reports it. Delay in ns, CPU times in µs. */ +/** One sample interval as Node reports it. Delay in ns, active time in ms, CPU in µs. */ export interface EventLoopReadings { readonly delayMaxNs: number; + readonly activeMs: number; readonly utilization: number; readonly usage: Pick< NodeJS.ResourceUsage, @@ -48,9 +49,11 @@ const makeNodeSampler = Effect.gen(function* () { return Effect.sync(() => { const nextElu = NodePerfHooks.performance.eventLoopUtilization(); const nextUsage = process.resourceUsage(); + const loop = NodePerfHooks.performance.eventLoopUtilization(nextElu, elu); const readings: EventLoopReadings = { delayMaxNs: histogram.max, - utilization: NodePerfHooks.performance.eventLoopUtilization(nextElu, elu).utilization, + activeMs: loop.active, + utilization: loop.utilization, usage: { userCPUTime: nextUsage.userCPUTime - usage.userCPUTime, systemCPUTime: nextUsage.systemCPUTime - usage.systemCPUTime, @@ -68,9 +71,21 @@ const makeNodeSampler = Effect.gen(function* () { }); }); +/** + * Returns the stall to report for one sample in ms, or undefined when there was none. + */ +export const stallMs = ({ delayMaxNs, activeMs }: EventLoopReadings) => { + const delayMs = Math.round(delayMaxNs / 1e6) - RESOLUTION_MS; + // A stall is time the loop spent running code, so it counts as active time. libuv's + // clock keeps running while the system sleeps on macOS and Windows, so a sleep also + // reads as delay, but the loop spent it idle in poll. + if (delayMs <= STALL_THRESHOLD_MS || activeMs < delayMs) return undefined; + return delayMs; +}; + /** * Samples event loop health every 30 s and records a `server.eventLoop.stall` span - * with a warning when the loop stalled for more than a second, so stalls land in + * with a warning when the loop stalled for more than 2 s, so stalls land in * the local trace file and Settings > Diagnostics without OTLP. Takes the sampler * so tests can inject readings. */ @@ -81,9 +96,10 @@ export const layerWith = ( Effect.gen(function* () { const sample = yield* makeSampler; const tick = Effect.gen(function* () { - const { delayMaxNs, utilization, usage, rssBytes } = yield* sample; - const delayMaxMs = Math.round(delayMaxNs / 1e6) - RESOLUTION_MS; - if (delayMaxMs <= STALL_THRESHOLD_MS) return; + const readings = yield* sample; + const delayMaxMs = stallMs(readings); + if (delayMaxMs === undefined) return; + const { utilization, usage, rssBytes } = readings; // Root, as the stall has no caller to attach to. Warn level keeps it when // T3CODE_TRACE_MIN_LEVEL is raised to cut trace noise. yield* Effect.logWarning(`event loop stalled for ${delayMaxMs} ms`).pipe( @@ -103,10 +119,14 @@ export const layerWith = ( }), ); }); - // Layers build outside any span, so this fiber retains no parent span. - yield* Effect.sleep(SAMPLE_INTERVAL).pipe( - Effect.andThen(tick), - Effect.forever, + const wait = Effect.sleep(SAMPLE_INTERVAL); + // The layer builds before the rest of the server, so the first sample covers + // startup work such as migrations and projection bootstrap. That can block the + // loop for seconds on a large database, so skip it rather than warn at every + // launch. Layers build outside any span, so this fiber retains no parent span. + yield* wait.pipe( + Effect.andThen(sample), + Effect.andThen(wait.pipe(Effect.andThen(tick), Effect.forever)), Effect.forkScoped, ); }), diff --git a/docs/operations/observability.md b/docs/operations/observability.md index ef65039282bd..2409f9a32ad5 100644 --- a/docs/operations/observability.md +++ b/docs/operations/observability.md @@ -90,16 +90,24 @@ If OTLP is not configured, metrics still exist in-process, but you will not have ### Event Loop Stalls `apps/server/src/observability/EventLoopMonitor.ts` samples the server's event loop every 30 s. When -the loop stalled for more than 1 s since the previous sample, it records a root +the loop stalled for more than 2 s since the previous sample, it records a root `server.eventLoop.stall` span with a warning. The span has trace level `Warn`, so it stays when `T3CODE_TRACE_MIN_LEVEL` is `Warn`. The warning shows in Settings > Diagnostics unless OTLP logs are on. The span time is when the sample ran, not when the stall happened. -`delayMaxMs` is the longest stall, and can undercount it by up to 200 ms. CPU times and page faults -cover the whole process over the whole window since the previous sample. The window is nominally -30 s, but a long stall delays the sample and makes the window longer. Other work in the window can -hide a wait, so only CPU time far below `delayMaxMs` proves the thread was waiting. Read CPU together -with page faults: +Some delay is not recorded: + +- `delayMaxMs` is the longest stall, and can undercount it by up to 1 s. The 2 s threshold applies to + this value, so every stall over 3 s is recorded, and a shorter one can be missed. +- Time the computer spends asleep reads as delay on macOS and Windows. So a sample only counts when + the loop was busy, not waiting for events, for at least `delayMaxMs`. +- The first sample after launch is skipped. Startup work such as migrations and projection bootstrap + can block the loop for seconds on a large database. + +CPU times and page faults cover the whole process over the whole window since the previous sample. +The window is nominally 30 s, but a long stall delays the sample and makes the window longer. Other +work in the window can hide a wait, so only CPU time far below `delayMaxMs` proves the thread was +waiting. Read CPU together with page faults: - High `cpuSystemMs` with many page faults means memory pressure. Major faults are reads from disk or swap. On macOS, reads from compressed memory are minor faults plus system CPU. @@ -108,9 +116,6 @@ with page faults: file writes. - Many `involuntaryContextSwitches` mean other processes were competing for the CPU. -The first sample after launch includes startup, such as migrations and projection bootstrap. With a -large database, this can record a real stall at each launch. - ### Related Artifacts Provider event NDJSON files still exist for provider runtime streams. Those are separate from the main server trace file. From 6cde623b8a4f7c278f246308e03de7049b3e2c15 Mon Sep 17 00:00:00 2001 From: Theo Browne Date: Fri, 25 Sep 2026 18:35:48 -0700 Subject: [PATCH 5/5] docs(observability): note the stall monitor's known misses and false positives Co-Authored-By: Claude Opus 5.5 (1M context) --- docs/operations/observability.md | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/docs/operations/observability.md b/docs/operations/observability.md index 2409f9a32ad5..c6537f6eac71 100644 --- a/docs/operations/observability.md +++ b/docs/operations/observability.md @@ -98,9 +98,12 @@ on. The span time is when the sample ran, not when the stall happened. Some delay is not recorded: - `delayMaxMs` is the longest stall, and can undercount it by up to 1 s. The 2 s threshold applies to - this value, so every stall over 3 s is recorded, and a shorter one can be missed. + this value, so a stall over 3 s is normally recorded, and a shorter one can be missed. A stall + that ends just as a sample runs can be missed too. - Time the computer spends asleep reads as delay on macOS and Windows. So a sample only counts when - the loop was busy, not waiting for events, for at least `delayMaxMs`. + the loop was busy, not waiting for events, for at least `delayMaxMs`. Busy time covers the whole + window, so a short sleep in an otherwise busy window can still record a false stall. The span then + shows CPU time far below `delayMaxMs`. - The first sample after launch is skipped. Startup work such as migrations and projection bootstrap can block the loop for seconds on a large database.