perf(dispatch): time the orphan reap inside the agent start lock (BLO-35878)

server/src/__tests__/agent-start-lock-liveness.test.ts

@@ -3,6 +3,7 @@ import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
 import {
   _resetAgentStartLocksForTesting,
   describeHeldAgentStartLocks,
+  LOCK_HELD_WARN_MS,
   withAgentStartLock,
 } from "../services/agent-start-lock.js";
 import {
@@ -301,3 +302,74 @@ describe("agent start lock metrics publication (PEN-3305)", () => {
     expect(afterRelease.size).toBe(0);
   });
 });
+
+/**
+ * BLO-35878. `LOCK_HELD_WARN_MS` was module-private until this change and is
+ * now exported, so that a *phase* inside the critical section can be judged
+ * against the same budget the lock itself enforces rather than against a
+ * second threshold invented beside it. `heartbeat.ts` imports it to decide
+ * when one `reapOrphanedRuns` sweep has, on its own, consumed the whole
+ * budget — which is the discriminator the hold gauge cannot provide, because
+ * it reports a section's total duration with no breakdown. That is how a
+ * 245–1586 s regression came to be attributed to hindsight recall, a
+ * subsystem that never runs on this path.
+ *
+ * An exported constant is only worth importing if it is still the number the
+ * lock actually acts on. Nothing else pins that: the suite above stubs `warn`
+ * globally and every one of its tests advances well past the threshold, so a
+ * divergence between the exported value and the interval that consumes it
+ * would leave all of them green while every caller's comparison silently
+ * shifted. This asserts the coupling at the edge, where it is observable.
+ */
+describe("exported lock budget is the threshold the lock acts on (BLO-35878)", () => {
+  let warn!: ReturnType<typeof vi.spyOn<typeof logger, "warn">>;
+
+  beforeEach(() => {
+    warn = vi.spyOn(logger, "warn").mockImplementation(() => logger);
+    vi.spyOn(logger, "error").mockImplementation(() => logger);
+  });
+
+  afterEach(() => {
+    vi.useRealTimers();
+    vi.restoreAllMocks();
+    _resetAgentStartLocksForTesting();
+  });
+
+  it("first warns at exactly LOCK_HELD_WARN_MS, reporting that same value as its budget", async () => {
+    vi.useFakeTimers();
+    const agentId = randomUUID();
+    const gate = deferred<string>();
+    const held = withAgentStartLock(agentId, () => gate.promise, coalesced);
+
+    const warnsForAgent = () =>
+      warn.mock.calls.filter(
+        ([fields]) => (fields as { agentId?: string } | undefined)?.agentId === agentId,
+      );
+
+    // One millisecond short of the exported budget: nothing has overrun yet.
+    // If the export were larger than the interval that consumes it, the lock
+    // would already have warned here and this would fail.
+    await vi.advanceTimersByTimeAsync(LOCK_HELD_WARN_MS - 1);
+    expect(warnsForAgent()).toHaveLength(0);
+
+    // Crossing it produces exactly one line. If the export were smaller than
+    // the interval, no line would have landed yet and this would fail. So the
+    // two assertions bracket the value from both sides rather than asserting
+    // "some warn eventually happens".
+    await vi.advanceTimersByTimeAsync(1);
+    expect(warnsForAgent()).toHaveLength(1);
+
+    // `heldMs` is the lock's own measurement and `warnAfterMs` is the budget
+    // it judged against. Both must equal the exported constant, or a caller
+    // comparing its phase duration to that constant is comparing against a
+    // number the lock does not use.
+    expect(warnsForAgent()[0]?.[0]).toMatchObject({
+      agentId,
+      heldMs: LOCK_HELD_WARN_MS,
+      warnAfterMs: LOCK_HELD_WARN_MS,
+    });
+
+    gate.resolve("done");
+    await held;
+  });
+});

server/src/services/agent-start-lock.ts

@@ -74,8 +74,17 @@ import { logger } from "../middleware/logger.js";
  * still happens exactly once.
  */
 
-/** Warn (do not bypass) when one critical section runs longer than this. */
-const LOCK_HELD_WARN_MS = 30_000;
+/**
+ * Warn (do not bypass) when one critical section runs longer than this.
+ *
+ * Exported (BLO-35878) so the section's own phases can be judged against the
+ * same budget they consume. The hold gauge says an agent's lock was held for N
+ * seconds; it cannot say by what, which is why a 1586 s hold was attributed to
+ * a plugin that never runs on this path. A phase that on its own exceeds the
+ * lock's warn budget is by definition the hold, so it logs under the same
+ * threshold rather than a second one invented next to it.
+ */
+export const LOCK_HELD_WARN_MS = 30_000;
 
 /**
  * Escalate the overrun log from `warn` to `error` past this (PEN-3305).

server/src/services/heartbeat.ts

@@ -504,7 +504,7 @@ import { PROVIDER_CAPACITY_MAX_HORIZON_MS } from "./provider-capacity-horizon-bo
 import { productivityReviewService } from "./productivity-review.js";
 import { resolveRequiredSuccessfulRunHandoffOnValidPath } from "./successful-run-handoff-state.js";
 import { taskWatchdogService } from "./task-watchdogs.js";
-import { runDetachedFromAgentStartLock, withAgentStartLock } from "./agent-start-lock.js";
+import { LOCK_HELD_WARN_MS, runDetachedFromAgentStartLock, withAgentStartLock } from "./agent-start-lock.js";
 import {
   evaluateAgentInvokability,
   evaluateAgentInvokabilityFromDb,
@@ -27291,7 +27291,43 @@ export function heartbeatService(db: Db, options: HeartbeatServiceOptions = {})
       }
       const policy = parseHeartbeatPolicy(agent);
       if (hasExternalLifecycle(agent.adapterType)) {
-        await reapOrphanedRuns({ suppressDispatchAfterReap: true });
+        // BLO-35878: time this. This is the only `reapOrphanedRuns` call site
+        // inside the agent start lock, and the sweep is NOT agent-scoped: it
+        // sweeps every `running` run in the instance, issuing per-run k8s reads
+        // and writes. So every external-lifecycle agent's dispatch pass pays a
+        // full cluster-wide sweep, and N concurrently-dispatching agents run N
+        // redundant copies of it against one API server and one DB pool.
+        //
+        // Not covered here: the startup reap and the periodic scheduler tick's
+        // reap (both in `index.ts`) run outside the lock and are not timed.
+        // `reapOrphanedRuns` has no in-flight latch, so the tick's sweep can run
+        // concurrently with this one, and a large `reapMs` below can mean this
+        // sweep was contending with it for the same k8s API and DB pool rather
+        // than being slow on its own. This line cannot separate those two.
+        //
+        // The hold gauge (`paperclip_agent_start_lock_held_seconds`) reports the
+        // section's total duration with no breakdown, which is why a 245–1586 s
+        // regression was attributed to hindsight recall — recall runs in the
+        // out-of-process plugin worker off the `plugin_event_outbox`, and
+        // nothing on this path awaits it. This line is the discriminator: a reap
+        // that alone exceeds the lock's warn budget names itself in the log next
+        // to the hold it caused.
+        //
+        // Timed in `finally` so a sweep that stalls and then throws (its first
+        // `running` select sits outside its per-stage catches, so a slow pool
+        // acquire that rejects propagates) still logs its duration.
+        const reapStartedAtMs = Date.now();
+        try {
+          await reapOrphanedRuns({ suppressDispatchAfterReap: true });
+        } finally {
+          const reapMs = Date.now() - reapStartedAtMs;
+          if (reapMs >= LOCK_HELD_WARN_MS) {
+            logger.warn(
+              { agentId, reapMs, warnAfterMs: LOCK_HELD_WARN_MS },
+              "orphan reap alone exceeded the agent start lock budget; it is holding dispatch for this agent",
+            );
+          }
+        }
       }
       // BLO-12990 Fix #1 / BLO-20775: stale/silent running runs must not block new
       // high-priority work. Fetch full run rows so `isRunOccupyingSlot` can partition