1// @effect-diagnostics nodeBuiltinImport:off - only node:perf_hooks exposes the event loop delay histogram.
2import * as NodePerfHooks from "node:perf_hooks";
3
4import { RotatingFileSink } from "@t3tools/shared/logging";
5import * as DateTime from "effect/DateTime";
6import * as Effect from "effect/Effect";
7import * as Layer from "effect/Layer";
8import * as Path from "effect/Path";
9import * as Schema from "effect/Schema";
10import type * as Scope from "effect/Scope";
11
12import * as ServerConfig from "../config.ts";
13
14// Node's delay histogram wakes a native timer every RESOLUTION_MS and records the
15// gap between wakeups, so an idle loop reads about RESOLUTION_MS and a stall of S
16// reads between S and S + RESOLUTION_MS. We subtract the resolution, so a delay can
17// undercount a stall by up to RESOLUTION_MS. With these values every stall over 3 s
18// is caught, at 1 wakeup per second that never enters JS.
19const RESOLUTION_MS = 1000;
20const STALL_THRESHOLD_MS = 2000;
21const SAMPLE_INTERVAL = "30 seconds";
22// A stall line is about 250 bytes, so the file and its one backup keep the last
23// 1000 to 2000 stalls.
24const STALL_LOG_MAX_BYTES = 256 * 1024;
25
26/** One sample interval as Node reports it. Delay in ns, active time in ms, CPU in µs. */
27export interface EventLoopReadings {
28 readonly delayMaxNs: number;
29 readonly activeMs: number;
30 readonly utilization: number;
31 readonly usage: Pick<
32 NodeJS.ResourceUsage,
33 | "userCPUTime"
34 | "systemCPUTime"
35 | "majorPageFault"
36 | "minorPageFault"
37 | "involuntaryContextSwitches"
38 >;
39 readonly rssBytes: number;
40}
41
42// Enables the delay histogram for the layer's lifetime. Each read returns the
43// readings since the previous read and resets the histogram. Node skips the first
44// gap after a reset, so a stall right at a sample boundary can be missed.
45const makeNodeSampler = Effect.gen(function* () {
46 const histogram = yield* Effect.acquireRelease(
47 Effect.sync(() => {
48 const histogram = NodePerfHooks.monitorEventLoopDelay({ resolution: RESOLUTION_MS });
49 histogram.enable();
50 return histogram;
51 }),
52 (histogram) => Effect.sync(() => histogram.disable()),
53 );
54 let elu = NodePerfHooks.performance.eventLoopUtilization();
55 let usage = process.resourceUsage();
56
57 // @effect-diagnostics-next-line returnEffectInGen:off - the read effect is the result.
58 return Effect.sync(() => {
59 const nextElu = NodePerfHooks.performance.eventLoopUtilization();
60 const nextUsage = process.resourceUsage();
61 const loop = NodePerfHooks.performance.eventLoopUtilization(nextElu, elu);
62 const readings: EventLoopReadings = {
63 delayMaxNs: histogram.max,
64 activeMs: loop.active,
65 utilization: loop.utilization,
66 usage: {
67 userCPUTime: nextUsage.userCPUTime - usage.userCPUTime,
68 systemCPUTime: nextUsage.systemCPUTime - usage.systemCPUTime,
69 majorPageFault: nextUsage.majorPageFault - usage.majorPageFault,
70 minorPageFault: nextUsage.minorPageFault - usage.minorPageFault,
71 involuntaryContextSwitches:
72 nextUsage.involuntaryContextSwitches - usage.involuntaryContextSwitches,
73 },
74 rssBytes: process.memoryUsage.rss(),
75 };
76 histogram.reset();
77 elu = nextElu;
78 usage = nextUsage;
79 return readings;
80 });
81});
82
83/**
84 * Returns the stall to report for one sample in ms, or undefined when there was none.
85 */
86export const stallMs = ({ delayMaxNs, activeMs }: EventLoopReadings) => {
87 const delayMs = Math.round(delayMaxNs / 1e6) - RESOLUTION_MS;
88 // A stall is time the loop spent running code, so it counts as active time. libuv's
89 // clock keeps running while the system sleeps on macOS and Windows, so a sleep also
90 // reads as delay, but the loop spent it idle in poll.
91 if (delayMs <= STALL_THRESHOLD_MS || activeMs < delayMs) return undefined;
92 return delayMs;
93};
94
95const encodeStallLine = Schema.encodeUnknownEffect(Schema.fromJsonString(Schema.Unknown));
96
97export interface StallLogOptions {
98 readonly filePath: string;
99 readonly maxBytes: number;
100}
101
102/**
103 * Samples event loop health every 30 s and records a `server.eventLoop.stall` span
104 * with a warning when the loop stalled for more than 2 s, so stalls land in
105 * the local trace file and Settings > Diagnostics without OTLP. Each stall is
106 * also appended as one NDJSON line to a small stall log, which keeps stall
107 * history long after the trace file has rotated. Takes the sampler and log
108 * options so tests can inject readings and a small cap.
109 */
110export const layerWith = (
111 makeSampler: Effect.Effect<Effect.Effect<EventLoopReadings>, never, Scope.Scope>,
112 stallLog: StallLogOptions,
113) =>
114 Layer.effectDiscard(
115 Effect.gen(function* () {
116 const sample = yield* makeSampler;
117 // A log that cannot open must not stop the monitor; the span still records stalls.
118 const stallSink = yield* Effect.try(
119 () =>
120 new RotatingFileSink({
121 filePath: stallLog.filePath,
122 maxBytes: stallLog.maxBytes,
123 maxFiles: 1,
124 throwOnError: true,
125 }),
126 ).pipe(
127 Effect.catch(() =>
128 Effect.logWarning("event loop stall log unavailable", {
129 filePath: stallLog.filePath,
130 }).pipe(Effect.as(undefined)),
131 ),
132 );
133 const tick = Effect.gen(function* () {
134 const readings = yield* sample;
135 const delayMaxMs = stallMs(readings);
136 if (delayMaxMs === undefined) return;
137 const { utilization, usage, rssBytes } = readings;
138 const attributes = {
139 delayMaxMs,
140 utilization: Math.round(utilization * 100) / 100,
141 cpuUserMs: Math.round(usage.userCPUTime / 1000),
142 cpuSystemMs: Math.round(usage.systemCPUTime / 1000),
143 majorPageFaults: usage.majorPageFault,
144 minorPageFaults: usage.minorPageFault,
145 involuntaryContextSwitches: usage.involuntaryContextSwitches,
146 rssMb: Math.round(rssBytes / 1024 / 1024),
147 };
148 // Root, as the stall has no caller to attach to. Warn level keeps it when
149 // T3CODE_TRACE_MIN_LEVEL is raised to cut trace noise.
150 yield* Effect.logWarning(`event loop stalled for ${delayMaxMs} ms`).pipe(
151 Effect.withSpan("server.eventLoop.stall", { root: true, level: "Warn", attributes }),
152 );
153 if (stallSink !== undefined) {
154 const time = DateTime.formatIso(yield* DateTime.now);
155 yield* encodeStallLine({ time, ...attributes }).pipe(
156 Effect.flatMap((line) => Effect.try(() => stallSink.write(`${line}\n`))),
157 Effect.catch(() =>
158 Effect.logWarning("event loop stall log write failed", {
159 filePath: stallLog.filePath,
160 }),
161 ),
162 );
163 }
164 });
165 const wait = Effect.sleep(SAMPLE_INTERVAL);
166 // The layer builds before the rest of the server, so the first sample covers
167 // startup work such as migrations and projection bootstrap. That can block the
168 // loop for seconds on a large database, so skip it rather than warn at every
169 // launch. Layers build outside any span, so this fiber retains no parent span.
170 yield* wait.pipe(
171 Effect.andThen(sample),
172 Effect.andThen(wait.pipe(Effect.andThen(tick), Effect.forever)),
173 Effect.forkScoped,
174 );
175 }),
176 );
177
178/** Writes the stall log next to the server trace file, as `event-loop-stalls.ndjson`. */
179export const layer = Layer.unwrap(
180 Effect.gen(function* () {
181 const { serverTracePath } = yield* ServerConfig.ServerConfig;
182 const path = yield* Path.Path;
183 return layerWith(makeNodeSampler, {
184 filePath: path.join(path.dirname(serverTracePath), "event-loop-stalls.ndjson"),
185 maxBytes: STALL_LOG_MAX_BYTES,
186 });
187 }),
188);