diff --git a/src/backend/services/health/ServerHealthService.test.ts b/src/backend/services/health/ServerHealthService.test.ts index 3e507fec0..c6ff5e746 100644 --- a/src/backend/services/health/ServerHealthService.test.ts +++ b/src/backend/services/health/ServerHealthService.test.ts @@ -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); diff --git a/src/backend/services/health/ServerHealthService.ts b/src/backend/services/health/ServerHealthService.ts index 3d549ae44..026a1fdc3 100644 --- a/src/backend/services/health/ServerHealthService.ts +++ b/src/backend/services/health/ServerHealthService.ts @@ -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; type FailHandler = (err: unknown) => Promise | 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,