Files
PaperClipAI/server/src/services/native-runtime/native-reconciliation-timing.ts
T
Devin FoleyandPaperclip cda77edc60 perf(server): stop readiness waiting on startup housekeeping (#16329)
## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work
> - On restart, `/api/health` reports `starting` until startup recovery
finishes, and deploy tooling waits for `ok`
> - After heartbeat recovery, readiness also waits for housekeeping that
every scheduler tick repeats and that serving requests does not need
> - #16330 added OpenTelemetry spans for the main startup phases; native
recovery and orphan reaping are the slow ones, and both run the native
finalization reconciliation pass, which has no inner breakdown
> - This pull request stops readiness waiting on that housekeeping, and
records the phases of slow reconciliation passes as spans
> - The benefit is faster readiness on every restart, and traces that
show where a slow reconciliation pass spends its time

## Linked Issues or Issue Description

Builds on #16330, which records `controller.startup.<phase>` spans.
Related to #16328.

**What existing behavior does this improve?**
Server readiness time after a restart, and diagnosis of slow native
recovery.

**Current behavior**
- After heartbeat recovery, readiness waits for the custom-image setup
cleanup, tool connection health (remote MCP checks), decision expiry,
the adapter and setup-token login reapers, environment lease cleanup
(provider calls) and the retention sweep. Each also runs on every
scheduler tick. On one instance they added 11–28 s to every measured
restart. A throw in any of them fails startup.
- On the same instance, native recovery took from 33 s to 11.5 min and
orphan reaping from 30 s to 4 min across restarts in one hour. Both run
the native finalization reconciliation pass. The #16330 spans time each
step as a whole, but not the phases inside that pass.

**Proposed behavior**
- The housekeeping steps run after readiness. The scheduler interval
still starts after them.
- With an OTLP endpoint, a reconciliation pass of at least one second
records a span with one child span per phase.

**Reason and benefit**
Readiness depends only on what serving requests and run recovery need.
Slow reconciliation passes become attributable to a phase in the
existing traces, without adding trace volume for the periodic pass.

**Breaking changes**
None. A failed housekeeping step no longer fails startup; it is logged
and the next step runs.

## What Changed

- `server/src/index.ts`: moves the housekeeping steps into
`runStartupHousekeeping`, which runs after readiness under
`trackHeartbeatSchedulerWork` (idle sleep and shutdown wait for it).
Each step catches and logs its own failure (`startup housekeeping step
failed`). The heartbeat scheduler interval starts when housekeeping
finishes, unless the scheduler was stopped, so the reapers still finish
before the first timer tick.
- New
`server/src/services/native-runtime/native-reconciliation-timing.ts`:
records the phase boundaries of one pass. When the pass took at least
one second and an OTLP endpoint is configured, it emits a
`controller.native_reconciliation` root span
(`paperclip.native-reconciliation`) with child spans
`legacy_workspace_exports`, `obsolete_policy_reviews`,
`automatic_completion_reviews`, `candidate_scan` and `candidates`, using
the recorded start and end times. It records `scoped` and the candidate
count only. A failed pass marks the pass span and the running phase.
Tracing failures are swallowed.
- `native-finalization-reconciler.ts`: the exported function wraps the
pass in that timing and finishes it in `finally`, so failed passes are
recorded; the original error is rethrown.
- `doc/execution-semantics.md`: what readiness waits for, and the
housekeeping order. `doc/observability.md`: the reconciliation spans.

## Verification

- `pnpm exec vitest run
src/__tests__/server-startup-feedback-export.test.ts
src/services/native-runtime/native-reconciliation-timing.test.ts
src/services/native-runtime/native-finalization-reconciler-timing.test.ts
src/startup-recovery-timing.test.ts` (in `server/`): 52 passed. New
tests:
- Readiness is `ready` while a housekeeping step hangs, and the
heartbeat interval starts only after the step settles.
- A failed housekeeping step is logged, and the scheduler still starts
after the remaining steps.
- Span timing: nothing for a fast pass or without an endpoint; a slow
pass emits the pass span and one child per phase with the recorded
times; a failed pass marks the running phase and the pass; a failing
tracer does not throw.
- The reconciler records its phases and a failed outcome when a pass
throws, and rethrows.
- Three existing startup tests settle housekeeping before they read the
scheduler interval or the setup cleanup.
- `pnpm exec vitest run src/services/native-runtime`: 4,399 passed.
- `pnpm typecheck` in `server/`: passed.

## Risks

- Housekeeping now runs concurrently with the first requests and with
`waitForExternalAdapters`. None of these steps is needed to serve
requests, and each one also runs on every scheduler tick.
- Readiness is reported earlier; the heartbeat timer starts at the same
point relative to housekeeping as before.
- The new spans exist only with an OTLP endpoint and only for passes of
at least one second.

## Model Used

- Claude Opus 5.5 (`claude-opus-5-5`), 1M context, through Claude Code
with tool use (shell, file edits, test runs).

## Checklist

- [x] I have included a thinking path that traces from project context
to this change
- [x] I have specified the model used (with version and capability
details)
- [x] I have checked ROADMAP.md and confirmed this PR does not duplicate
planned core work
- [x] I have searched GitHub for duplicate or related PRs and linked
them above
- [x] I have either (a) linked existing issues with `Fixes: #` / `Closes
#` / `Refs #` OR (b) described the issue in-PR following the relevant
issue template
- [x] I have not referenced internal/instance-local Paperclip issues or
links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip`
URLs)
- [x] My branch name describes the change (e.g. `docs/...`, `fix/...`)
and contains no internal Paperclip ticket id or instance-derived details
- [x] I have run tests locally and they pass
- [x] I have added or updated tests where applicable
- [x] I have updated relevant documentation to reflect my changes
- [x] I have considered and documented any risks above
- [ ] All Paperclip CI gates are green
- [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups
- [ ] I will address all Greptile and reviewer comments before
requesting merge

Co-authored-by: Paperclip <noreply@paperclip.ing>
2026-10-14 15:55:13 -07:00

72 lines
3.0 KiB
TypeScript

import { performance } from "node:perf_hooks";
import { ROOT_CONTEXT, SpanStatusCode, trace } from "@opentelemetry/api";
export type NativeReconciliationPhase = "legacy_workspace_exports" | "obsolete_policy_reviews"
| "automatic_completion_reviews" | "candidate_scan" | "candidates";
// A pass at least this slow records its phases. Startup recovery runs the pass
// twice and readiness waits for both; the periodic pass runs on every
// scheduler tick, so fast passes record nothing.
export const NATIVE_RECONCILIATION_SLOW_PASS_MS = 1_000;
type RecordedPhase = { phase: NativeReconciliationPhase; startedAt: number; endedAt: number };
// Records phase boundaries of one native finalization reconciliation pass.
// When the pass is slow and an OTLP endpoint is configured, `finish` emits a
// `controller.native_reconciliation` span with one child span per phase, using
// the recorded start and end times. It records counts and outcome only.
export function createNativeReconciliationPassTiming(options: { now?: () => number } = {}) {
const now = options.now ?? (() => performance.timeOrigin + performance.now());
const passStartedAt = now();
const phases: RecordedPhase[] = [];
let current: { phase: NativeReconciliationPhase; startedAt: number } | null = null;
let candidates: number | null = null;
const closeCurrent = () => {
if (!current) return;
phases.push({ ...current, endedAt: now() });
current = null;
};
return {
phase(phase: NativeReconciliationPhase) {
closeCurrent();
current = { phase, startedAt: now() };
},
candidates(count: number) {
candidates = count;
},
finish(details: { outcome: "ok" | "failed"; scoped: boolean }) {
const failedPhase = details.outcome === "failed" ? current?.phase ?? null : null;
closeCurrent();
const passEndedAt = now();
if (passEndedAt - passStartedAt < NATIVE_RECONCILIATION_SLOW_PASS_MS) return;
if (!process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim()) return;
try {
const tracer = trace.getTracer("paperclip.native-reconciliation");
const pass = tracer.startSpan("controller.native_reconciliation", {
startTime: passStartedAt,
attributes: {
"paperclip.native_reconciliation.scoped": details.scoped,
...(candidates === null ? {} : { "paperclip.native_reconciliation.candidates": candidates }),
},
}, ROOT_CONTEXT);
const passContext = trace.setSpan(ROOT_CONTEXT, pass);
for (const recorded of phases) {
const span = tracer.startSpan(
`controller.native_reconciliation.${recorded.phase}`,
{ startTime: recorded.startedAt },
passContext,
);
if (recorded.phase === failedPhase) span.setStatus({ code: SpanStatusCode.ERROR });
span.end(recorded.endedAt);
}
if (details.outcome === "failed") pass.setStatus({ code: SpanStatusCode.ERROR });
pass.end(passEndedAt);
} catch {
// Tracing must never change reconciliation.
}
},
};
}