diff --git a/apps/server/src/observability/EventLoopMonitor.test.ts b/apps/server/src/observability/EventLoopMonitor.test.ts new file mode 100644 index 000000000000..fbe30157aec2 --- /dev/null +++ b/apps/server/src/observability/EventLoopMonitor.test.ts @@ -0,0 +1,77 @@ +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, stallMs } from "./EventLoopMonitor.ts"; + +const ms = (value: number) => value * 1e6; + +// Node reports a stall of S as a gap of up to S + 1 s, the histogram resolution. +const stalled: EventLoopReadings = { + delayMaxNs: ms(5_950), + activeMs: 6_200, + utilization: 0.176, + usage: { + userCPUTime: 310_400, + systemCPUTime: 95_600, + majorPageFault: 8_412, + minorPageFault: 20_031, + involuntaryContextSwitches: 57, + }, + rssBytes: 1536 * 1024 * 1024, +}; +// Over the threshold as read, but not once the resolution is subtracted. +const quiet: EventLoopReadings = { ...stalled, delayMaxNs: ms(2_950) }; + +describe("EventLoopMonitor", () => { + it.effect("records a warning span only for samples that saw a stall", () => + Effect.gen(function* () { + const spans: Array = []; + const tracer = Tracer.make({ + span: (options) => { + const span = new Tracer.NativeSpan(options); + spans.push(span); + return span; + }, + }); + // 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("60 seconds"); + assert.lengthOf(spans, 0); + yield* TestClock.adjust("30 seconds"); + }).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), { + delayMaxMs: 4_950, + utilization: 0.18, + 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"]], + ); + }), + ); + + 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 new file mode 100644 index 000000000000..13b7b48c4cf7 --- /dev/null +++ b/apps/server/src/observability/EventLoopMonitor.ts @@ -0,0 +1,135 @@ +// @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"; +import * as Layer from "effect/Layer"; +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. 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, active time in ms, CPU in µs. */ +export interface EventLoopReadings { + readonly delayMaxNs: number; + readonly activeMs: number; + readonly utilization: number; + readonly usage: Pick< + NodeJS.ResourceUsage, + | "userCPUTime" + | "systemCPUTime" + | "majorPageFault" + | "minorPageFault" + | "involuntaryContextSwitches" + >; + readonly rssBytes: number; +} + +// 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 loop = NodePerfHooks.performance.eventLoopUtilization(nextElu, elu); + const readings: EventLoopReadings = { + delayMaxNs: histogram.max, + activeMs: loop.active, + utilization: loop.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; + }); +}); + +/** + * 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 2 s, 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; + 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( + 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), + }, + }), + ); + }); + 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, + ); + }), + ); + +export const layer = layerWith(makeNodeSampler); 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..c6537f6eac71 100644 --- a/docs/operations/observability.md +++ b/docs/operations/observability.md @@ -87,6 +87,38 @@ 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 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. + +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 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`. 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. + +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 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. + ### Related Artifacts Provider 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: - git command execution and git hook events - terminal session lifecycle - sqlite query execution +- event loop stalls (`server.eventLoop.stall`) ### Current Constraints