fix(health): discount total event-loop stall time from db liveness latency

The stall watcher kept only the longest gap, so a saturated loop with many sub-second stalls still failed database-liveness. It now sums blocked time across the probe (ignoring timer jitter) and reports total and longest.
This commit is contained in:
Daniel Salazar committed 2026-10-09 18:10:03 -07:00
1 parent 43094a84a0
commit 09d79eb2d1
2 files changed
+117 -20

No files matched your search

@@ -198,7 +198,7 @@ describe('ServerHealthService.addCheck', () => {
expect.stringContaining('"hangs" failed'),
expect.objectContaining({
message:
'Health check timed out (event loop blocked up to 0ms)',
'Health check timed out (event loop blocked 0ms total, longest 0ms)',
}),
);
service.onServerShutdown();
@@ -221,7 +221,7 @@ describe('ServerHealthService.addCheck', () => {
expect.stringContaining('"stalls" failed'),
expect.objectContaining({
message:
'Health check timed out (event loop blocked up to 3000ms)',
'Health check timed out (event loop blocked 3000ms total, longest 3000ms)',
}),
);
service.onServerShutdown();
@@ -292,7 +292,9 @@ describe('ServerHealthService — default checks', () => {
expect(await uncachedStatus(service)).toEqual({ ok: true });
expect(warnSpy).toHaveBeenCalledWith(
expect.stringContaining('event loop was blocked for 40ms'),
expect.stringContaining(
'event loop blocked 40ms total, longest 40ms',
),
);
service.onServerShutdown();
});
@@ -319,13 +321,87 @@ describe('ServerHealthService — default checks', () => {
expect.stringContaining('database-liveness'),
expect.objectContaining({
message: expect.stringContaining(
'event loop blocked up to 20ms',
'event loop blocked 20ms total, longest 20ms',
),
}),
);
service.onServerShutdown();
});
it('passes a slow probe when many short stalls add up to the difference', async () => {
const { service, dbRead } = makeService();
// A saturated loop: six 500ms stalls, the loop turning for 100ms after
// each. No single stall covers the 2100ms over the 1500ms threshold.
dbRead.mockImplementation(async () => {
for (let i = 0; i < 6; i++) {
vi.setSystemTime(Date.now() + 500);
await new Promise((resolve) => setTimeout(resolve, 100));
}
return [{ ok: 1 }];
});
service.onServerStart();
await runCycle();
await vi.advanceTimersByTimeAsync(1000);
expect(await uncachedStatus(service)).toEqual({ ok: true });
expect(warnSpy).toHaveBeenCalledWith(
'[server-health] database-liveness took 3600ms but passed (event loop blocked 3000ms total, longest 500ms)',
);
service.onServerShutdown();
});
it('fails a database that is slow on its own while the loop is idle', async () => {
const { service, dbRead } = makeService();
dbRead.mockImplementation(
() =>
new Promise((resolve) =>
setTimeout(() => resolve([{ ok: 1 }]), 3600),
),
);
service.onServerStart();
await runCycle();
await vi.advanceTimersByTimeAsync(3700);
expect(await uncachedStatus(service)).toEqual({
ok: false,
failed: ['database-liveness'],
});
expect(errorSpy).toHaveBeenCalledWith(
expect.stringContaining('database-liveness'),
expect.objectContaining({
message:
'database liveness latency 3600ms > threshold 1500ms (event loop blocked 0ms total, longest 0ms)',
}),
);
service.onServerShutdown();
});
it('does not count timer jitter as a stall', async () => {
const { service, dbRead } = makeService({
server_health: { db_liveness_latency_fail_ms: 10 },
});
// Every tick lands 5ms late: under twice the watch interval.
dbRead.mockImplementation(async () => {
for (let i = 0; i < 3; i++) {
vi.setSystemTime(Date.now() + 5);
await new Promise((resolve) => setTimeout(resolve, 10));
}
return [{ ok: 1 }];
});
service.onServerStart();
await runCycle();
await vi.advanceTimersByTimeAsync(100);
expect(errorSpy).toHaveBeenCalledWith(
expect.stringContaining('database-liveness'),
expect.objectContaining({
message:
'database liveness latency 45ms > threshold 10ms (event loop blocked 0ms total, longest 0ms)',
}),
);
service.onServerShutdown();
});
it('fails when socket.io was never attached', async () => {
const { service, hasIO } = makeService();
hasIO.mockReturnValue(false);
@@ -96,31 +96,52 @@ const DYNAMO_PROBE_KEY = {
key: 'liveness-probe',
};
interface LoopStalls {
/** Time blocked beyond the timer's interval, summed over every stall. */
totalMs: number;
longestMs: number;
}
/**
* Times the longest gap between ticks of a short timer, for as long as a probe
* runs. The gap still open when `stop` is called counts too, so a stall that
* ends just before the reply is read isn't missed. Returns ms blocked beyond
* the timer's own interval.
* Measures event-loop stalls from the gaps between ticks of a short timer, for
* as long as a probe runs. The gap still open when `stop` is called counts too,
* so a stall that ends just before the reply is read isn't missed.
*/
const watchLoopStalls = (): (() => number) => {
const watchLoopStalls = (): (() => LoopStalls) => {
const startedAt = Date.now();
let lastTick = startedAt;
let longest = 0;
let totalMs = 0;
let longestMs = 0;
let expired = false;
// Gaps under twice the interval are timer jitter, not a stall.
const blockedIn = (gap: number) =>
gap < LOOP_WATCH_INTERVAL_MS * 2 ? 0 : gap - LOOP_WATCH_INTERVAL_MS;
const timer = setInterval(() => {
const now = Date.now();
longest = Math.max(longest, now - lastTick);
const blocked = blockedIn(now - lastTick);
totalMs += blocked;
longestMs = Math.max(longestMs, blocked);
lastTick = now;
// A probe that never settles must not leave this running.
if (now - startedAt > CHECK_TIMEOUT_MS) clearInterval(timer);
if (now - startedAt > CHECK_TIMEOUT_MS) {
clearInterval(timer);
expired = true;
}
}, LOOP_WATCH_INTERVAL_MS);
timer.unref?.();
return () => {
clearInterval(timer);
const gap = Math.max(longest, Date.now() - lastTick);
return Math.max(0, gap - LOOP_WATCH_INTERVAL_MS);
const open = expired ? 0 : blockedIn(Date.now() - lastTick);
return {
totalMs: totalMs + open,
longestMs: Math.max(longestMs, open),
};
};
};
const describeStalls = ({ totalMs, longestMs }: LoopStalls): string =>
`event loop blocked ${totalMs}ms total, longest ${longestMs}ms`;
type CheckFn = () => Promise<unknown> | unknown;
type FailHandler = (err: unknown) => Promise<void> | void;
@@ -343,11 +364,11 @@ export class ServerHealthService extends PuterService {
const stopWatch = watchLoopStalls();
const startedAt = Date.now();
let rows: unknown[];
let blockedMs: number;
let stalls: LoopStalls;
try {
rows = (await db.read('SELECT 1 AS ok')) as unknown[];
} finally {
blockedMs = stopWatch();
stalls = stopWatch();
}
const durationMs = Date.now() - startedAt;
this.#stats.database_liveness_latency_ms = durationMs;
@@ -356,14 +377,14 @@ export class ServerHealthService extends PuterService {
throw new Error('database liveness query returned no rows');
}
if (durationMs <= latencyFailMs) return;
if (durationMs - blockedMs <= latencyFailMs) {
if (durationMs - stalls.totalMs <= latencyFailMs) {
console.warn(
`[server-health] database-liveness took ${durationMs}ms, but the event loop was blocked for ${blockedMs}ms of it`,
`[server-health] database-liveness took ${durationMs}ms but passed (${describeStalls(stalls)})`,
);
return;
}
throw new Error(
`database liveness latency ${durationMs}ms > threshold ${latencyFailMs}ms (event loop blocked up to ${blockedMs}ms)`,
`database liveness latency ${durationMs}ms > threshold ${latencyFailMs}ms (${describeStalls(stalls)})`,
);
});
}
@@ -583,7 +604,7 @@ export class ServerHealthService extends PuterService {
() =>
reject(
new Error(
`Health check timed out (event loop blocked up to ${stopWatch()}ms)`,
`Health check timed out (${describeStalls(stopWatch())})`,
),
),
CHECK_TIMEOUT_MS,