diff --git a/apps/server/src/server.ts b/apps/server/src/server.ts index 6fc8196108..cb982d6b97 100644 --- a/apps/server/src/server.ts +++ b/apps/server/src/server.ts @@ -44,6 +44,7 @@ import { captureTrustedRemoteAddress, resolveRequestAppSurface, } from "./request-context.js"; +import { runEventLoopWork } from "./services/system/event-loop-work.js"; import { runWithTelemetryAppSurface } from "./services/system/telemetry.js"; import { onClientSocketClose, @@ -283,6 +284,13 @@ export function createApp( ); return runWithTelemetryAppSurface(appSurface, next); }); + app.use("*", async (context, next) => { + const path = context.req.path; + if (!path.startsWith("/api/v1/") && !path.startsWith("/internal/")) { + return next(); + } + return runEventLoopWork(`${context.req.method} ${path}`, next); + }); app.use( "*", cors({ diff --git a/apps/server/src/services/plugins/plugin-runtime.ts b/apps/server/src/services/plugins/plugin-runtime.ts index 85706419c7..dafe89f7dc 100644 --- a/apps/server/src/services/plugins/plugin-runtime.ts +++ b/apps/server/src/services/plugins/plugin-runtime.ts @@ -44,6 +44,7 @@ import type { PluginWireLookup, ServiceRuntime, } from "./plugin-service-internal.js"; +import { runEventLoopWork } from "../system/event-loop-work.js"; /** * Plugin server bundles keep `@bb/plugin-sdk` external (see @bb/plugin-build), @@ -587,7 +588,10 @@ export function createPluginRuntime(context: PluginRuntimeContext) { } pending.add(marker); try { - return { ok: true, value: await run() }; + return { + ok: true, + value: await runEventLoopWork(`plugin:${id} ${label}`, run), + }; } catch (error) { const message = error instanceof Error ? error.message : String(error); stats.errorCount += 1; diff --git a/apps/server/src/services/system/event-loop-stall-monitor.ts b/apps/server/src/services/system/event-loop-stall-monitor.ts index c38964313d..8a604a77d8 100644 --- a/apps/server/src/services/system/event-loop-stall-monitor.ts +++ b/apps/server/src/services/system/event-loop-stall-monitor.ts @@ -1,6 +1,7 @@ import { monitorEventLoopDelay } from "node:perf_hooks"; import { roundDurationMs } from "../lib/duration.js"; import type { ServerLogger } from "../../types.js"; +import { takeEventLoopWorkWindowSnapshot } from "./event-loop-work.js"; export interface EventLoopStallMonitorOptions { logger: Pick; @@ -29,6 +30,7 @@ export function startEventLoopStallMonitor( const interval = setInterval(() => { const maxDelayMs = nanosecondsToMilliseconds(histogram.max); + const work = takeEventLoopWorkWindowSnapshot(); if (maxDelayMs >= DEFAULT_EVENT_LOOP_STALL_LOG_THRESHOLD_MS) { // `info`, not `debug`: the packaged app runs at `info`, so a `debug` line // here is unreachable in production — which is exactly where a stalled @@ -37,6 +39,9 @@ export function startEventLoopStallMonitor( // dynamic tool call and interactive request, so it delays real agent // work, not just UI refreshes. Threshold-gated, so a healthy server // stays silent. + // currentWork is still in flight. lastWork is the latest finish. + // slowestWork is the longest unit in this histogram window, so a later + // heartbeat cannot hide the block that produced histogram.max. options.logger.info( { intervalMs: DEFAULT_EVENT_LOOP_STALL_MONITOR_INTERVAL_MS, @@ -49,6 +54,7 @@ export function startEventLoopStallMonitor( ), resolutionMs: DEFAULT_EVENT_LOOP_STALL_MONITOR_RESOLUTION_MS, thresholdMs: DEFAULT_EVENT_LOOP_STALL_LOG_THRESHOLD_MS, + ...work, }, "Event loop stalled", ); diff --git a/apps/server/src/services/system/event-loop-work.ts b/apps/server/src/services/system/event-loop-work.ts new file mode 100644 index 0000000000..ad774a1549 --- /dev/null +++ b/apps/server/src/services/system/event-loop-work.ts @@ -0,0 +1,152 @@ +import { AsyncLocalStorage } from "node:async_hooks"; +import { performance } from "node:perf_hooks"; +import { roundDurationMs } from "../lib/duration.js"; + +interface EventLoopWorkFrame { + id: number; + label: string; + parentId: number | null; + startedAt: number; +} + +interface CompletedEventLoopWork { + durationMs: number; + label: string; +} + +export interface EventLoopWorkSnapshot { + currentWork: string | null; + lastWork: string | null; + lastWorkMs: number | null; + slowestWork: string | null; + slowestWorkMs: number | null; +} + +const activeFrames = new Map(); +const currentFrameId = new AsyncLocalStorage(); +const completedInWindow: CompletedEventLoopWork[] = []; +let nextFrameId = 1; +let lastCompleted: CompletedEventLoopWork | null = null; + +function enterEventLoopWork(label: string): number { + const id = nextFrameId; + nextFrameId += 1; + activeFrames.set(id, { + id, + label, + parentId: currentFrameId.getStore() ?? null, + startedAt: performance.now(), + }); + return id; +} + +function leaveEventLoopWork(id: number): void { + const frame = activeFrames.get(id); + activeFrames.delete(id); + if (frame === undefined) { + return; + } + const completed: CompletedEventLoopWork = { + durationMs: performance.now() - frame.startedAt, + label: frame.label, + }; + lastCompleted = completed; + completedInWindow.push(completed); +} + +function formatLineage(root: EventLoopWorkFrame): string { + const labels: string[] = [root.label]; + let parentId = root.id; + for (;;) { + const children: EventLoopWorkFrame[] = [...activeFrames.values()] + .filter((frame) => frame.parentId === parentId) + .sort((left, right) => left.id - right.id); + const child = children[0]; + if (child === undefined) { + break; + } + labels.push(child.label); + parentId = child.id; + } + return labels.join(" > "); +} + +function formatActiveWork(): string | null { + if (activeFrames.size === 0) { + return null; + } + const roots = [...activeFrames.values()] + .filter( + (frame) => frame.parentId === null || !activeFrames.has(frame.parentId), + ) + .sort((left, right) => left.id - right.id); + return roots.map((root) => formatLineage(root)).join(" | "); +} + +function selectSlowestWork(): CompletedEventLoopWork | null { + let slowest: CompletedEventLoopWork | null = null; + for (const completed of completedInWindow) { + if (slowest === null || completed.durationMs > slowest.durationMs) { + slowest = completed; + } + } + const now = performance.now(); + for (const frame of activeFrames.values()) { + const durationMs = now - frame.startedAt; + if (slowest === null || durationMs > slowest.durationMs) { + slowest = { durationMs, label: frame.label }; + } + } + return slowest; +} + +export function getEventLoopWorkSnapshot(): EventLoopWorkSnapshot { + const slowest = selectSlowestWork(); + return { + currentWork: formatActiveWork(), + lastWork: lastCompleted?.label ?? null, + lastWorkMs: + lastCompleted === null ? null : roundDurationMs(lastCompleted.durationMs), + slowestWork: slowest?.label ?? null, + slowestWorkMs: + slowest === null ? null : roundDurationMs(slowest.durationMs), + }; +} + +export function takeEventLoopWorkWindowSnapshot(): EventLoopWorkSnapshot { + const snapshot = getEventLoopWorkSnapshot(); + completedInWindow.length = 0; + return snapshot; +} + +export function runEventLoopWorkSync(label: string, work: () => T): T { + const id = enterEventLoopWork(label); + return currentFrameId.run(id, () => { + try { + return work(); + } finally { + leaveEventLoopWork(id); + } + }); +} + +export async function runEventLoopWork( + label: string, + work: () => Promise | T, +): Promise { + const id = enterEventLoopWork(label); + return currentFrameId.run(id, async () => { + try { + return await work(); + } finally { + leaveEventLoopWork(id); + } + }); +} + +export function resetEventLoopWorkForTests(): void { + activeFrames.clear(); + completedInWindow.length = 0; + lastCompleted = null; + nextFrameId = 1; +} diff --git a/apps/server/src/services/system/periodic-sweeps.ts b/apps/server/src/services/system/periodic-sweeps.ts index 4dadcbf137..cedd16fca7 100644 --- a/apps/server/src/services/system/periodic-sweeps.ts +++ b/apps/server/src/services/system/periodic-sweeps.ts @@ -48,6 +48,7 @@ import { hasLiveThreadStartInFlight } from "../threads/thread-lifecycle.js"; import { advanceThreadProvisioning } from "../threads/thread-provisioning.js"; import { runQueuedMessageAutoSendSweep } from "../threads/queued-messages.js"; import { LIVE_DAEMON_COMMAND_TIMEOUT_MS } from "../hosts/live-command.js"; +import { runEventLoopWork } from "./event-loop-work.js"; export type DatabaseMaintenanceSweepDeps = Pick; @@ -150,7 +151,7 @@ async function runPeriodicSweepJob( state.lastStartedAt = now; state.running = true; try { - await job.run(deps, now); + await runEventLoopWork(`sweep:${job.name}`, () => job.run(deps, now)); } catch (error) { deps.logger.error( { diff --git a/apps/server/src/services/threads/timeline.ts b/apps/server/src/services/threads/timeline.ts index 6a85e8d649..b5817d1146 100644 --- a/apps/server/src/services/threads/timeline.ts +++ b/apps/server/src/services/threads/timeline.ts @@ -56,6 +56,7 @@ import type { } from "@bb/db"; import { ApiError } from "../../errors.js"; import { roundDurationMs } from "../lib/duration.js"; +import { runEventLoopWorkSync } from "../system/event-loop-work.js"; import { parseStoredEvent } from "./thread-data.js"; import { paginateTimelineRows, @@ -1787,11 +1788,15 @@ export function buildThreadTimeline( thread: Thread, options: BuildThreadTimelineOptions, ): ThreadTimelineResponse { - return buildThreadTimelineInternal(db, thread, { - ...options, - includeProfile: false, - measureResponseBytes: false, - }).response; + return runEventLoopWorkSync( + `timeline-build ${thread.id}`, + () => + buildThreadTimelineInternal(db, thread, { + ...options, + includeProfile: false, + measureResponseBytes: false, + }).response, + ); } /** @@ -1804,15 +1809,17 @@ export function buildThreadTimelineWithProfile( thread: Thread, options: BuildThreadTimelineOptions, ): { profile: ThreadTimelineBuildProfile; response: ThreadTimelineResponse } { - const result = buildThreadTimelineInternal(db, thread, { - ...options, - includeProfile: true, - measureResponseBytes: false, + return runEventLoopWorkSync(`timeline-build ${thread.id}`, () => { + const result = buildThreadTimelineInternal(db, thread, { + ...options, + includeProfile: true, + measureResponseBytes: false, + }); + if (result.profile === null) { + throw new Error("Profiled timeline build returned no profile"); + } + return { profile: result.profile, response: result.response }; }); - if (result.profile === null) { - throw new Error("Profiled timeline build returned no profile"); - } - return { profile: result.profile, response: result.response }; } export interface BuildThreadConversationOutlineOptions { @@ -1860,57 +1867,59 @@ export function buildThreadConversationOutline( thread: Thread, options: BuildThreadConversationOutlineOptions, ): ThreadConversationOutlineResponse { - const rawEventRows = listStoredConversationOutlineEventRows(db, { - threadId: thread.id, - }); - const decodedRawEvents = rawEventRows.map((row) => - toThreadEventWithMeta(row), - ); - const decodedEvents = compactThreadTimelineSummaryEvents(decodedRawEvents); - const clientRequestContextRows = selectClientRequestContextRows(db, { - rows: rawEventRows, - threadId: thread.id, - }); - const acceptedClientRequestContext: AcceptedClientRequestContext = { - acceptedClientRequestEvents: clientRequestContextRows.acceptedRows.map( - (row) => toThreadEventWithMeta(row), - ), - rejectedClientRequestEvents: clientRequestContextRows.rejectedRows.map( - (row) => toThreadEventWithMeta(row), - ), - }; - const timeline = buildThreadTimelineFromEvents({ - acceptedClientRequestContext, - contextWindowEvents: [], - events: decodedEvents, - options: { - includeDebugRawEvents: false, - includeNestedRows: false, - includeProviderUnhandledOperations: false, - isLatestPage: true, - providerDisplayName: options.providerDisplayName, - providerId: thread.providerId, - threadName: thread.title ?? thread.titleFallback ?? "", - threadStatus: thread.status, - turnMessageDetail: "summary", - workspaceRoot: resolveThreadWorkspaceRoot(db, thread), - }, - }); - const items: ThreadConversationOutlineItem[] = []; - for (const row of timeline.rows) { - if (row.kind !== "conversation") { - continue; - } - items.push({ - id: row.id, - role: row.role, - preview: toConversationOutlinePreview(row.text), - attachmentSummary: toConversationOutlineAttachmentSummary( - row.attachments, + return runEventLoopWorkSync(`conversation-outline ${thread.id}`, () => { + const rawEventRows = listStoredConversationOutlineEventRows(db, { + threadId: thread.id, + }); + const decodedRawEvents = rawEventRows.map((row) => + toThreadEventWithMeta(row), + ); + const decodedEvents = compactThreadTimelineSummaryEvents(decodedRawEvents); + const clientRequestContextRows = selectClientRequestContextRows(db, { + rows: rawEventRows, + threadId: thread.id, + }); + const acceptedClientRequestContext: AcceptedClientRequestContext = { + acceptedClientRequestEvents: clientRequestContextRows.acceptedRows.map( + (row) => toThreadEventWithMeta(row), + ), + rejectedClientRequestEvents: clientRequestContextRows.rejectedRows.map( + (row) => toThreadEventWithMeta(row), ), + }; + const timeline = buildThreadTimelineFromEvents({ + acceptedClientRequestContext, + contextWindowEvents: [], + events: decodedEvents, + options: { + includeDebugRawEvents: false, + includeNestedRows: false, + includeProviderUnhandledOperations: false, + isLatestPage: true, + providerDisplayName: options.providerDisplayName, + providerId: thread.providerId, + threadName: thread.title ?? thread.titleFallback ?? "", + threadStatus: thread.status, + turnMessageDetail: "summary", + workspaceRoot: resolveThreadWorkspaceRoot(db, thread), + }, }); - } - return { items, maxSeq: options.maxSeq }; + const items: ThreadConversationOutlineItem[] = []; + for (const row of timeline.rows) { + if (row.kind !== "conversation") { + continue; + } + items.push({ + id: row.id, + role: row.role, + preview: toConversationOutlinePreview(row.text), + attachmentSummary: toConversationOutlineAttachmentSummary( + row.attachments, + ), + }); + } + return { items, maxSeq: options.maxSeq }; + }); } export function buildTimelineTurnSummaryDetails( diff --git a/apps/server/src/ws/daemon-protocol.ts b/apps/server/src/ws/daemon-protocol.ts index ec6af16341..4500e7e004 100644 --- a/apps/server/src/ws/daemon-protocol.ts +++ b/apps/server/src/ws/daemon-protocol.ts @@ -17,6 +17,7 @@ import { notifyDaemonEnvironmentChange, recordDaemonEnvironmentMetadataChange, } from "../internal/environment-changes.js"; +import { runEventLoopWorkSync } from "../services/system/event-loop-work.js"; import { decodeSocketPayload } from "./decode-payload.js"; interface DaemonSocket { @@ -120,69 +121,77 @@ export function onDaemonSocketMessage( } try { - const session = requireAuthorizedOpenSession(deps.db, { - hostId: args.hostId, - sessionId: args.sessionId, - }); - heartbeatSession( - deps.db, - session.id, - Math.max(Date.now() + session.leaseTimeoutMs, session.leaseExpiresAt + 1), - ); - if (result.data.type === "environment-change") { - notifyDaemonEnvironmentChange(deps, { + runEventLoopWorkSync(`ws:daemon ${result.data.type}`, () => { + const session = requireAuthorizedOpenSession(deps.db, { hostId: args.hostId, - environmentId: result.data.environmentId, - change: result.data.change, - }); - return; - } - if (result.data.type === "environment-metadata-change") { - recordDaemonEnvironmentMetadataChange(deps, { - hostId: args.hostId, - environmentId: result.data.environmentId, - workspace: result.data.workspace, - }); - return; - } - if (result.data.type === "host-rpc.response") { - const disposition = deps.hub.recordHostOnlineRpcResponse({ - message: result.data, sessionId: args.sessionId, }); - if (!disposition.handled && disposition.reason === "session_mismatch") { - deps.logger.warn( - { - commandType: result.data.commandType, - expectedSessionId: disposition.expectedSessionId, - requestId: result.data.requestId, - sessionId: args.sessionId, - }, - "Ignoring host RPC response from mismatched daemon session", - ); - } else if (!disposition.handled) { - deps.logger.debug( - { - commandType: result.data.commandType, - requestId: result.data.requestId, - sessionId: args.sessionId, - }, - "Ignoring stale host RPC response", + heartbeatSession( + deps.db, + session.id, + Math.max( + Date.now() + session.leaseTimeoutMs, + session.leaseExpiresAt + 1, + ), + ); + if (result.data.type === "environment-change") { + notifyDaemonEnvironmentChange(deps, { + hostId: args.hostId, + environmentId: result.data.environmentId, + change: result.data.change, + }); + return; + } + if (result.data.type === "environment-metadata-change") { + recordDaemonEnvironmentMetadataChange(deps, { + hostId: args.hostId, + environmentId: result.data.environmentId, + workspace: result.data.workspace, + }); + return; + } + if (result.data.type === "host-rpc.response") { + const disposition = deps.hub.recordHostOnlineRpcResponse({ + message: result.data, + sessionId: args.sessionId, + }); + if (!disposition.handled && disposition.reason === "session_mismatch") { + deps.logger.warn( + { + commandType: result.data.commandType, + expectedSessionId: disposition.expectedSessionId, + requestId: result.data.requestId, + sessionId: args.sessionId, + }, + "Ignoring host RPC response from mismatched daemon session", + ); + } else if (!disposition.handled) { + deps.logger.debug( + { + commandType: result.data.commandType, + requestId: result.data.requestId, + sessionId: args.sessionId, + }, + "Ignoring stale host RPC response", + ); + } + return; + } + if (result.data.type === "connect-tunnel.identity") { + deps.sharedPorts.recordTunnelIdentity( + args.hostId, + result.data.identity, ); + return; } - return; - } - if (result.data.type === "connect-tunnel.identity") { - deps.sharedPorts.recordTunnelIdentity(args.hostId, result.data.identity); - return; - } - if (result.data.type !== "heartbeat") { - deps.terminalSessions.handleDaemonTerminalMessage({ - hostId: args.hostId, - message: result.data, - sessionId: args.sessionId, - }); - } + if (result.data.type !== "heartbeat") { + deps.terminalSessions.handleDaemonTerminalMessage({ + hostId: args.hostId, + message: result.data, + sessionId: args.sessionId, + }); + } + }); } catch (error) { if (error instanceof ApiError && error.body.code === "inactive_session") { deps.logger.info( diff --git a/apps/server/test/services/database-maintenance-sweep.test.ts b/apps/server/test/services/database-maintenance-sweep.test.ts index 1dd2e2aede..95e4992a32 100644 --- a/apps/server/test/services/database-maintenance-sweep.test.ts +++ b/apps/server/test/services/database-maintenance-sweep.test.ts @@ -51,7 +51,7 @@ interface TempDatabasePath { class CapturingSlowQueryLogger implements SlowDbQueryLogger { debugLogs: SlowDbQueryLogFields[] = []; - debug(fields: SlowDbQueryLogFields): void { + info(fields: SlowDbQueryLogFields): void { this.debugLogs.push(fields); } diff --git a/apps/server/test/services/threads/conversation-outline-performance.test.ts b/apps/server/test/services/threads/conversation-outline-performance.test.ts index b878e71834..6f01f2c2b5 100644 --- a/apps/server/test/services/threads/conversation-outline-performance.test.ts +++ b/apps/server/test/services/threads/conversation-outline-performance.test.ts @@ -17,7 +17,7 @@ function setup() { const db = createConnection(":memory:", { slowQueryThresholdMs: 0, slowQueryLogger: { - debug(fields) { + info(fields) { queries.push(fields); }, }, diff --git a/apps/server/test/system/event-loop-stall-monitor.test.ts b/apps/server/test/system/event-loop-stall-monitor.test.ts index 4a48ce5756..ff33bf347b 100644 --- a/apps/server/test/system/event-loop-stall-monitor.test.ts +++ b/apps/server/test/system/event-loop-stall-monitor.test.ts @@ -25,11 +25,22 @@ const perfHooksMock = vi.hoisted(() => { }; }); -vi.mock("node:perf_hooks", () => ({ - monitorEventLoopDelay: perfHooksMock.monitorEventLoopDelay, -})); +vi.mock("node:perf_hooks", async () => { + const actual = + await vi.importActual("node:perf_hooks"); + return { + ...actual, + monitorEventLoopDelay: perfHooksMock.monitorEventLoopDelay, + }; +}); +import { performance as nodePerformance } from "node:perf_hooks"; import { startEventLoopStallMonitor } from "../../src/services/system/event-loop-stall-monitor.js"; +import { + resetEventLoopWorkForTests, + runEventLoopWork, + runEventLoopWorkSync, +} from "../../src/services/system/event-loop-work.js"; const EVENT_LOOP_STALL_MONITOR_INTERVAL_MS = 5_000; const NANOSECONDS_PER_MILLISECOND = 1_000_000; @@ -59,11 +70,20 @@ function installHistogram( return histogram; } +const EMPTY_WORK_SNAPSHOT = { + currentWork: null, + lastWork: null, + lastWorkMs: null, + slowestWork: null, + slowestWorkMs: null, +}; + describe("event loop stall monitor", () => { beforeEach(() => { vi.useFakeTimers(); perfHooksMock.monitorEventLoopDelay.mockClear(); perfHooksMock.state.histogram = null; + resetEventLoopWorkForTests(); }); afterEach(() => { @@ -96,6 +116,7 @@ describe("event loop stall monitor", () => { p99DelayMs: 450, resolutionMs: 20, thresholdMs: 500, + ...EMPTY_WORK_SNAPSHOT, }, "Event loop stalled", ); @@ -136,4 +157,175 @@ describe("event loop stall monitor", () => { expect(histogram.reset).not.toHaveBeenCalled(); expect(logger.info).not.toHaveBeenCalled(); }); + + it("includes the in-flight unit of work on the stall report", async () => { + installHistogram({ + maxDelayMs: 500, + meanDelayMs: 25, + p99DelayMs: 450, + }); + const logger = { info: vi.fn() }; + const monitor = startEventLoopStallMonitor({ logger }); + let release!: () => void; + const held = runEventLoopWork( + "GET /api/v1/threads/thr_example/timeline", + () => + new Promise((resolve) => { + release = resolve; + }), + ); + + vi.advanceTimersByTime(EVENT_LOOP_STALL_MONITOR_INTERVAL_MS); + + expect(logger.info).toHaveBeenCalledWith( + expect.objectContaining({ + currentWork: "GET /api/v1/threads/thr_example/timeline", + lastWork: null, + lastWorkMs: null, + slowestWork: "GET /api/v1/threads/thr_example/timeline", + }), + "Event loop stalled", + ); + + release(); + await held; + monitor.stop(); + }); + + it("includes the last finished unit of work on the stall report", () => { + installHistogram({ + maxDelayMs: 500, + meanDelayMs: 25, + p99DelayMs: 450, + }); + const logger = { info: vi.fn() }; + const monitor = startEventLoopStallMonitor({ logger }); + + runEventLoopWorkSync("sweep:database-maintenance", () => undefined); + vi.advanceTimersByTime(EVENT_LOOP_STALL_MONITOR_INTERVAL_MS); + + expect(logger.info).toHaveBeenCalledWith( + expect.objectContaining({ + currentWork: null, + lastWork: "sweep:database-maintenance", + }), + "Event loop stalled", + ); + const fields = logger.info.mock.calls[0]?.[0] as { + lastWorkMs: number | null; + }; + expect(fields.lastWorkMs).toEqual(expect.any(Number)); + + monitor.stop(); + }); + + it("nests the current work label when units overlap", async () => { + installHistogram({ + maxDelayMs: 500, + meanDelayMs: 25, + p99DelayMs: 450, + }); + const logger = { info: vi.fn() }; + const monitor = startEventLoopStallMonitor({ logger }); + let release!: () => void; + const held = runEventLoopWork( + "GET /api/v1/threads/thr_example/timeline", + () => + runEventLoopWork( + "timeline-build thr_example", + () => + new Promise((resolve) => { + release = resolve; + }), + ), + ); + + vi.advanceTimersByTime(EVENT_LOOP_STALL_MONITOR_INTERVAL_MS); + + expect(logger.info).toHaveBeenCalledWith( + expect.objectContaining({ + currentWork: + "GET /api/v1/threads/thr_example/timeline > timeline-build thr_example", + }), + "Event loop stalled", + ); + + release(); + await held; + monitor.stop(); + }); + + it("keeps sibling frames when one request finishes first", async () => { + installHistogram({ + maxDelayMs: 500, + meanDelayMs: 25, + p99DelayMs: 450, + }); + const logger = { info: vi.fn() }; + const monitor = startEventLoopStallMonitor({ logger }); + let releaseFirst!: () => void; + let releaseSecond!: () => void; + const first = runEventLoopWork( + "GET /api/v1/first", + () => + new Promise((resolve) => { + releaseFirst = resolve; + }), + ); + const second = runEventLoopWork( + "GET /api/v1/second", + () => + new Promise((resolve) => { + releaseSecond = resolve; + }), + ); + + releaseFirst(); + await first; + vi.advanceTimersByTime(EVENT_LOOP_STALL_MONITOR_INTERVAL_MS); + + expect(logger.info).toHaveBeenCalledWith( + expect.objectContaining({ + currentWork: "GET /api/v1/second", + lastWork: "GET /api/v1/first", + }), + "Event loop stalled", + ); + + releaseSecond(); + await second; + monitor.stop(); + }); + + it("keeps the slowest work from the stall window after later short work", () => { + installHistogram({ + maxDelayMs: 500, + meanDelayMs: 25, + p99DelayMs: 450, + }); + const logger = { info: vi.fn() }; + const nowSpy = vi.spyOn(nodePerformance, "now"); + nowSpy.mockReturnValueOnce(0); + nowSpy.mockReturnValueOnce(650); + runEventLoopWorkSync("sweep:database-maintenance", () => undefined); + nowSpy.mockReturnValueOnce(650); + nowSpy.mockReturnValueOnce(651); + runEventLoopWorkSync("ws:daemon heartbeat", () => undefined); + nowSpy.mockRestore(); + + const monitor = startEventLoopStallMonitor({ logger }); + vi.advanceTimersByTime(EVENT_LOOP_STALL_MONITOR_INTERVAL_MS); + + expect(logger.info).toHaveBeenCalledWith( + expect.objectContaining({ + lastWork: "ws:daemon heartbeat", + lastWorkMs: 1, + slowestWork: "sweep:database-maintenance", + slowestWorkMs: 650, + }), + "Event loop stalled", + ); + + monitor.stop(); + }); }); diff --git a/packages/db/src/connection.ts b/packages/db/src/connection.ts index c77de85e84..15a3c04c0c 100644 --- a/packages/db/src/connection.ts +++ b/packages/db/src/connection.ts @@ -12,7 +12,7 @@ export interface SlowDbQueryLogFields { } export interface SlowDbQueryLogger { - debug(fields: SlowDbQueryLogFields, message: string): void; + info(fields: SlowDbQueryLogFields, message: string): void; } export interface CreateConnectionOptions { @@ -74,7 +74,9 @@ function runTimedStatementOperation( } finally { const durationMs = performance.now() - startedAt; if (durationMs >= args.config.thresholdMs) { - args.config.logger.debug( + // `info`, not `debug`: the packaged app runs at `info`, so a debug + // line never appears next to the stall reports it is meant to explain. + args.config.logger.info( { bindingArgumentCount: args.bindingArgumentCount, durationMs: roundDurationMs(durationMs), diff --git a/packages/db/test/connection.test.ts b/packages/db/test/connection.test.ts index 1a253cc519..b70564a1fa 100644 --- a/packages/db/test/connection.test.ts +++ b/packages/db/test/connection.test.ts @@ -8,30 +8,30 @@ import { import { migrate } from "../src/migrate.js"; import { hosts } from "../src/schema.js"; -interface LoggedDebug { +interface LoggedInfo { fields: SlowDbQueryLogFields; message: string; } class CapturingSlowQueryLogger implements SlowDbQueryLogger { - readonly debugLogs: LoggedDebug[] = []; + readonly infoLogs: LoggedInfo[] = []; - debug(fields: SlowDbQueryLogFields, message: string): void { - this.debugLogs.push({ fields, message }); + info(fields: SlowDbQueryLogFields, message: string): void { + this.infoLogs.push({ fields, message }); } clear(): void { - this.debugLogs.length = 0; + this.infoLogs.length = 0; } } -function getOnlyDebugLog(logger: CapturingSlowQueryLogger): LoggedDebug { - expect(logger.debugLogs).toHaveLength(1); - const debugLog = logger.debugLogs[0]; - if (!debugLog) { - throw new Error("Expected slow query debug log"); +function getOnlyInfoLog(logger: CapturingSlowQueryLogger): LoggedInfo { + expect(logger.infoLogs).toHaveLength(1); + const infoLog = logger.infoLogs[0]; + if (!infoLog) { + throw new Error("Expected slow query info log"); } - return debugLog; + return infoLog; } describe("createConnection", () => { @@ -44,12 +44,12 @@ describe("createConnection", () => { db.$client.prepare("SELECT ? AS value").get("sensitive-value"); - const debugLog = getOnlyDebugLog(logger); - expect(debugLog.message).toBe("Slow DB query"); - expect(debugLog.fields.operation).toBe("get"); - expect(debugLog.fields.bindingArgumentCount).toBe(1); - expect(debugLog.fields.sql).toBe("SELECT ? AS value"); - expect(debugLog.fields.sql).not.toContain("sensitive-value"); + const infoLog = getOnlyInfoLog(logger); + expect(infoLog.message).toBe("Slow DB query"); + expect(infoLog.fields.operation).toBe("get"); + expect(infoLog.fields.bindingArgumentCount).toBe(1); + expect(infoLog.fields.sql).toBe("SELECT ? AS value"); + expect(infoLog.fields.sql).not.toContain("sensitive-value"); db.$client.close(); }); @@ -63,9 +63,9 @@ describe("createConnection", () => { db.$client.prepare("SELECT 'sensitive-literal' AS value").get(); - const debugLog = getOnlyDebugLog(logger); - expect(debugLog.fields.sql).toBe("SELECT '?' AS value"); - expect(debugLog.fields.sql).not.toContain("sensitive-literal"); + const infoLog = getOnlyInfoLog(logger); + expect(infoLog.fields.sql).toBe("SELECT '?' AS value"); + expect(infoLog.fields.sql).not.toContain("sensitive-literal"); db.$client.close(); }); @@ -95,13 +95,13 @@ describe("createConnection", () => { .get(); expect(row?.name).toBe("Drizzle Host"); - const debugLog = getOnlyDebugLog(logger); - expect(debugLog.message).toBe("Slow DB query"); - expect(debugLog.fields.operation).toBe("get"); - expect(debugLog.fields.bindingArgumentCount).toBe(1); - expect(debugLog.fields.sql).toContain("from"); - expect(debugLog.fields.sql).toContain("hosts"); - expect(debugLog.fields.sql).not.toContain("host-drizzle"); + const infoLog = getOnlyInfoLog(logger); + expect(infoLog.message).toBe("Slow DB query"); + expect(infoLog.fields.operation).toBe("get"); + expect(infoLog.fields.bindingArgumentCount).toBe(1); + expect(infoLog.fields.sql).toContain("from"); + expect(infoLog.fields.sql).toContain("hosts"); + expect(infoLog.fields.sql).not.toContain("host-drizzle"); db.$client.close(); }); @@ -118,9 +118,9 @@ describe("createConnection", () => { db.$client.prepare(longSql).get(); - const debugLog = getOnlyDebugLog(logger); - expect(debugLog.fields.sql).toHaveLength(1_000); - expect(debugLog.fields.sql.endsWith("...")).toBe(true); + const infoLog = getOnlyInfoLog(logger); + expect(infoLog.fields.sql).toHaveLength(1_000); + expect(infoLog.fields.sql.endsWith("...")).toBe(true); db.$client.close(); }); diff --git a/packages/db/test/query-plans.test.ts b/packages/db/test/query-plans.test.ts index 34fadf3042..3e4b7d5165 100644 --- a/packages/db/test/query-plans.test.ts +++ b/packages/db/test/query-plans.test.ts @@ -93,7 +93,7 @@ interface AssertEmittedQueryPlanUsesIndexArgs { class CapturingSlowQueryLogger implements SlowDbQueryLogger { readonly debugLogs: LoggedDebug[] = []; - debug: SlowDbQueryLogger["debug"] = (fields, message) => { + info: SlowDbQueryLogger["info"] = (fields, message) => { this.debugLogs.push({ fields, message }); };