Attribute event-loop stalls to the work that blocked them

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({

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;

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<ServerLogger, "info">;
@@ -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",
       );

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<number, EventLoopWorkFrame>();
+const currentFrameId = new AsyncLocalStorage<number>();
+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<T>(label: string, work: () => T): T {
+  const id = enterEventLoopWork(label);
+  return currentFrameId.run(id, () => {
+    try {
+      return work();
+    } finally {
+      leaveEventLoopWork(id);
+    }
+  });
+}
+
+export async function runEventLoopWork<T>(
+  label: string,
+  work: () => Promise<T> | T,
+): Promise<T> {
+  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;
+}

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<AppDeps, "db" | "logger">;
 
@@ -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(
       {