1import * as NodeServices from "@effect/platform-node/NodeServices";
2import { assert, describe, it } from "@effect/vitest";
3import * as Effect from "effect/Effect";
4import * as FileSystem from "effect/FileSystem";
5import * as Layer from "effect/Layer";
6import * as Logger from "effect/Logger";
7import * as Tracer from "effect/Tracer";
8import * as TestClock from "effect/testing/TestClock";
9
10import * as EventLoopMonitor from "./EventLoopMonitor.ts";
11
12const ms = (value: number) => value * 1e6;
13
14// Node reports a stall of S as a gap of up to S + 1 s, the histogram resolution.
15const stalled: EventLoopMonitor.EventLoopReadings = {
16 delayMaxNs: ms(5_950),
17 activeMs: 6_200,
18 utilization: 0.176,
19 usage: {
20 userCPUTime: 310_400,
21 systemCPUTime: 95_600,
22 majorPageFault: 8_412,
23 minorPageFault: 20_031,
24 involuntaryContextSwitches: 57,
25 },
26 rssBytes: 1536 * 1024 * 1024,
27};
28// Over the threshold as read, but not once the resolution is subtracted.
29const quiet: EventLoopMonitor.EventLoopReadings = { ...stalled, delayMaxNs: ms(2_950) };
30
31// The first sample covers startup, so the monitor discards it.
32const monitor = (
33 samples: Array<EventLoopMonitor.EventLoopReadings>,
34 stallLog: EventLoopMonitor.StallLogOptions = { filePath: "\0", maxBytes: 1 },
35) =>
36 Layer.build(
37 EventLoopMonitor.layerWith(
38 Effect.succeed(Effect.sync(() => samples.shift() ?? quiet)),
39 stallLog,
40 ),
41 );
42
43describe("EventLoopMonitor", () => {
44 it.effect("records a warning span only for samples that saw a stall", () =>
45 Effect.gen(function* () {
46 const spans: Array<Tracer.NativeSpan> = [];
47 const tracer = Tracer.make({
48 span: (options) => {
49 const span = new Tracer.NativeSpan(options);
50 spans.push(span);
51 return span;
52 },
53 });
54 yield* Effect.gen(function* () {
55 // The default stall log path cannot open, and the span must still be recorded.
56 yield* monitor([stalled, quiet, stalled]);
57 yield* TestClock.adjust("60 seconds");
58 assert.lengthOf(spans, 0);
59 yield* TestClock.adjust("30 seconds");
60 }).pipe(Effect.scoped, Effect.withTracer(tracer));
61
62 assert.deepStrictEqual(
63 spans.map((span) => span.name),
64 ["server.eventLoop.stall"],
65 );
66 const [span] = spans;
67 assert.deepStrictEqual(Object.fromEntries(span!.attributes), {
68 delayMaxMs: 4_950,
69 utilization: 0.18,
70 cpuUserMs: 310,
71 cpuSystemMs: 96,
72 majorPageFaults: 8_412,
73 minorPageFaults: 20_031,
74 involuntaryContextSwitches: 57,
75 rssMb: 1536,
76 });
77 assert.deepStrictEqual(
78 span!.events.map(([name, , attributes]) => [name, attributes["effect.logLevel"]]),
79 [["event loop stalled for 4950 ms", "WARN"]],
80 );
81 }),
82 );
83
84 it.effect("keeps each stall as one line in a capped stall log", () =>
85 Effect.gen(function* () {
86 const fs = yield* FileSystem.FileSystem;
87 const directory = yield* fs.makeTempDirectoryScoped({ prefix: "t3-event-loop-" });
88 const filePath = `${directory}/event-loop-stalls.ndjson`;
89 // Room for one line, so each new stall rotates the last one into the backup.
90 yield* monitor([stalled, stalled, stalled, { ...stalled, delayMaxNs: ms(7_000) }], {
91 filePath,
92 maxBytes: 300,
93 });
94 yield* TestClock.adjust("120 seconds");
95
96 const lines = (yield* fs.readFileString(filePath)).trim().split("\n");
97 assert.deepStrictEqual(
98 lines.map((line) => JSON.parse(line)),
99 [
100 {
101 time: "1970-01-01T00:02:00.000Z",
102 delayMaxMs: 6_000,
103 utilization: 0.18,
104 cpuUserMs: 310,
105 cpuSystemMs: 96,
106 majorPageFaults: 8_412,
107 minorPageFaults: 20_031,
108 involuntaryContextSwitches: 57,
109 rssMb: 1536,
110 },
111 ],
112 );
113 assert.lengthOf((yield* fs.readFileString(`${filePath}.1`)).trim().split("\n"), 1);
114 assert.isFalse(yield* fs.exists(`${filePath}.2`));
115 }).pipe(Effect.scoped, Effect.provide(NodeServices.layer)),
116 );
117
118 it.effect("warns when a stall cannot be written to the stall log", () => {
119 const warnings: Array<unknown> = [];
120 const logger = Logger.make(({ message }) => {
121 warnings.push(Array.isArray(message) ? message[0] : message);
122 });
123 return Effect.gen(function* () {
124 const fs = yield* FileSystem.FileSystem;
125 // A directory at the log path opens, but every append to it fails. The cap
126 // is large so the sink never rotates the directory out of the way.
127 const filePath = yield* fs.makeTempDirectoryScoped({ prefix: "t3-event-loop-" });
128 yield* monitor([stalled, stalled], { filePath, maxBytes: 1024 * 1024 });
129 yield* TestClock.adjust("60 seconds");
130 assert.deepStrictEqual(warnings, [
131 "event loop stalled for 4950 ms",
132 "event loop stall log write failed",
133 ]);
134 }).pipe(
135 Effect.scoped,
136 Effect.provide(
137 Layer.merge(NodeServices.layer, Logger.layer([logger], { mergeWithExisting: false })),
138 ),
139 );
140 });
141
142 it("ignores delay the loop spent idle, such as a system sleep", () => {
143 // Waking from sleep reads as a long gap, but the loop was idle in poll for it.
144 const asleep: EventLoopMonitor.EventLoopReadings = {
145 ...stalled,
146 delayMaxNs: ms(600_000),
147 activeMs: 900,
148 };
149 assert.isUndefined(EventLoopMonitor.stallMs(asleep));
150 assert.strictEqual(EventLoopMonitor.stallMs({ ...asleep, activeMs: 600_000 }), 599_000);
151 });
152});