From 67c45ffd7d01aaa85aeab9daf6832470ec86b190 Mon Sep 17 00:00:00 2001 From: PlatformSREEngineer Date: Thu, 24 Sep 2026 10:36:48 +0000 Subject: [PATCH 1/3] perf(dispatch): time the orphan reap inside the agent start lock (BLO-35878) `paperclip_agent_start_lock_held_seconds` reports a section's total hold with no breakdown, so a 245-1586 s regression on 2026-09-23 was attributed to hindsight recall latency. Recall is not on this path: plugin events are delivered out-of-process off `plugin_event_outbox` (the log line's own `service` field is `plugin-worker`), and nothing the critical section awaits is plugin-related. What the section does await is `reapOrphanedRuns`, which has exactly one call site -- inside this lock, with no timer anywhere -- and is NOT agent-scoped: it selects every `running` run in the instance, then issues per-run k8s reads and writes plus `listManagedAgentJobs` / `listAgentJobRunStatuses` / `cleanupOrphanedManagedPods`. Every external-lifecycle agent's dispatch pass therefore pays a full cluster-wide sweep, and every agent in this instance is external-lifecycle, so there is no control group to compare against. This does not fix that. It makes the next reading able to name it: a reap that alone exceeds the lock's own warn budget now logs `reapMs` next to the hold it caused, under the same threshold rather than a second one invented beside it. `LOCK_HELD_WARN_MS` is exported for that reason. No test: this is a log branch on a timing comparison, not a guard over an invariant. A test asserting we log when a fake clock advances would pass with the branch reverted in every way that matters, which is documentation, not a check. The production signal is the check -- the line either appears next to the long holds or it does not, and that is the measurement the issue needs. Refs: https://paperclip.blockcast.net/BLO/issues/BLO-35878 Co-Authored-By: Paperclip --- server/src/services/agent-start-lock.ts | 13 +++++++++++-- server/src/services/heartbeat.ts | 24 +++++++++++++++++++++++- 2 files changed, 34 insertions(+), 3 deletions(-) diff --git a/server/src/services/agent-start-lock.ts b/server/src/services/agent-start-lock.ts index 1799038bd03d..cb5e479054d1 100644 --- a/server/src/services/agent-start-lock.ts +++ b/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). diff --git a/server/src/services/heartbeat.ts b/server/src/services/heartbeat.ts index e1c22c9889c5..31e85c4143f7 100644 --- a/server/src/services/heartbeat.ts +++ b/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,29 @@ export function heartbeatService(db: Db, options: HeartbeatServiceOptions = {}) } const policy = parseHeartbeatPolicy(agent); if (hasExternalLifecycle(agent.adapterType)) { + // BLO-35878: time this. `reapOrphanedRuns` has exactly one call site — + // here, inside the agent start lock — and it 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. + // + // 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. + const reapStartedAtMs = Date.now(); await reapOrphanedRuns({ suppressDispatchAfterReap: true }); + 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 From cc301f1181793c6b6fe2511471da9103e02c806e Mon Sep 17 00:00:00 2001 From: PlatformSREEngineer Date: Thu, 24 Sep 2026 19:22:15 +0000 Subject: [PATCH 2/3] test(dispatch): pin the exported lock budget against the threshold the lock acts on (BLO-35878) The parent commit argued "no test", on the grounds that a fake-clock test of a log branch would pass with the branch reverted. That reasoning is still correct about the log branch, and it was wrong about this PR: exporting `LOCK_HELD_WARN_MS` creates a contract nothing pinned. The export is only safe while it remains the number the lock actually acts on, and nothing failed if those two drifted apart. Adds to the existing `agent-start-lock-liveness.test.ts` harness (fake timers, `logger` spy, no database): no warn at `LOCK_HELD_WARN_MS - 1`, exactly one at `LOCK_HELD_WARN_MS`, carrying `heldMs`/`warnAfterMs` equal to the exported value. Brackets the threshold from both sides rather than asserting that some warn eventually happens. Scope of the mutation, stated rather than overclaimed: it fails on divergence -- hardcoding `30_000` at the `setInterval` and then moving the constant. It does not fail on a consistent revaluation, which is the constant doing its job. Refs: https://paperclip.blockcast.net/BLO/issues/BLO-35878 Co-Authored-By: Paperclip --- .../agent-start-lock-liveness.test.ts | 72 +++++++++++++++++++ 1 file changed, 72 insertions(+) diff --git a/server/src/__tests__/agent-start-lock-liveness.test.ts b/server/src/__tests__/agent-start-lock-liveness.test.ts index 338cd9ed2e82..5f5c53092c4b 100644 --- a/server/src/__tests__/agent-start-lock-liveness.test.ts +++ b/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>; + + 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(); + 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; + }); +}); From dbcab17681ee796553920837cf82a72342c00d9e Mon Sep 17 00:00:00 2001 From: Omar Ramadan Date: Thu, 24 Sep 2026 23:55:58 +0000 Subject: [PATCH 3/3] fix(dispatch): time the in-lock orphan reap on throw too, and scope its call-site claim (BLO-35878) Addresses Ally's review of cc301f11: - Important: the comment claimed reapOrphanedRuns has exactly one call site. It has three: the startup reap and the periodic scheduler tick in index.ts run outside the lock. Restate it as the only call site inside the lock, and note the tick sweep is not timed and can run concurrently (no in-flight latch), so a large reapMs may be contention with it. - Important: the reap timing ran only on the success path, so a sweep that stalls and then throws (the first running select sits outside its per-stage catches) logged nothing. Move the elapsed check into finally. Co-Authored-By: Claude Opus 5.5 (1M context) --- server/src/services/heartbeat.ts | 32 +++++++++++++++++++++++--------- 1 file changed, 23 insertions(+), 9 deletions(-) diff --git a/server/src/services/heartbeat.ts b/server/src/services/heartbeat.ts index 31e85c4143f7..e2138a77fcbd 100644 --- a/server/src/services/heartbeat.ts +++ b/server/src/services/heartbeat.ts @@ -27291,13 +27291,20 @@ export function heartbeatService(db: Db, options: HeartbeatServiceOptions = {}) } const policy = parseHeartbeatPolicy(agent); if (hasExternalLifecycle(agent.adapterType)) { - // BLO-35878: time this. `reapOrphanedRuns` has exactly one call site — - // here, inside the agent start lock — and it is NOT agent-scoped: it + // 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 @@ -27305,14 +27312,21 @@ export function heartbeatService(db: Db, options: HeartbeatServiceOptions = {}) // 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(); - await reapOrphanedRuns({ suppressDispatchAfterReap: true }); - 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", - ); + 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