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

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<Tracer.NativeSpan> = [];
+      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);
+  });
+});

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<Effect.Effect<EventLoopReadings>, 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);

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),
 );
 

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