Files
PaperClipAI/server/src/services/native-runtime/native-run-trace.ts
T
DottaandClaude Opus 5.5 6fd46c0025 perf(budgets): judge Paperclip's share of restart recovery; report the provider's session load (#20183)
## Thinking Path

- Speed budgets protect the time to first visible agent activity, and
restart recovery is one of the judged metrics
(`native-speed-budgets.ts`, wave grader).
- In the B1 concurrency-6 chaos wave (`w-20261109T045320-s9807`), Codex
`restart_recovery` was p50 8.6 s and p95 11.2 s, against a budget of 6.5
s and 8.0 s. At concurrency 4 (K13) it was 3.8 s and 5.0 s.
- The preparation spans on a copy of the kept database break it down:
- Paperclip's share (ready → claim → prepare → runtime stage → runner
launch) is a steady 1.2–2.0 s.
- `provider.session.load`, the Codex app-server boot plus
`thread/resume` of long saved sessions, takes 3.0–6.3 s, 65–75% of each
recovery.
- Resumes run concurrently, and the worktree lock and the startup
reconciler are not on the path.
- Judging the full latency therefore mixes our code with provider and
session-size effects. Budget the part we control, so a regression in our
code shows up regardless of session size or concurrency, and report the
rest.

## Linked Issues or Issue Description

**What happened?**
`restart_recovery` breached its budget whenever many long provider
sessions resumed at once, although Paperclip's own recovery work stayed
within about 2 s. The breach did not point at anything Paperclip could
fix, and a real regression in our code could hide inside the
provider-load variance.

**Steps to reproduce**
1. Run a local chaos wave at concurrency 6 with long-running Codex tasks
and K1/K2/K4 faults (for example B1, seed 9807).
2. Compare `restart_recovery` in `speed.json` with
`provider.session.load` in the recovered runs' run logs.

**Expected behavior**
The budget judges Paperclip's share of a recovery. The provider's
session load and the full latency are reported but not judged.

## What Changed

- `server/src/services/native-runtime/native-speed-budgets.ts`:
- New budgeted metric `restart_recovery_control_plane`: from `ready` to
the start of `provider.session.load`, or to the next provider event when
nothing reloads (for example a reattached runner).
- Its budget is 2.5 s / 4.0 s for claude, codex and opencode. Measured:
1.2–2.0 s per run at concurrency 6.
  - The full `restart_recovery` stays in the table for reporting.
  - Breach payloads carry `restartTotalMs` and `providerLoadMs`.
- `server/src/services/native-runtime/native-run-trace.ts`:
- The per-run check records when `provider.session.load` starts, keeps
the recovery measurement, and judges it when the run finishes.
- It judges after the deferred diagnostics drain, so a provider span
committed after the provider event still counts.
  - It emits `restart_recovery_control_plane` breaches only.
- `tests/restart-chaos/ttft-baseline-stats.ts`: each recovery sample
gains `controlPlaneMs` and `providerLoadMs`. The provider-load start is
the span event's write time minus its duration.
- `tests/restart-chaos/wave-speed.ts`:
- Three restart rows per adapter: `restart_recovery` (report-only),
`restart_recovery_control_plane` (budgeted) and `restart_provider_load`
(report-only).
  - All three have outage time removed.
- `tests/restart-chaos/ttft-baseline.ts`: the recovery table adds a
"Paperclip share" column.
- Docs: `doc/run-log-events.md` (metric and payload) and the
speed-budget table in
`doc/plans/2026-11-07-durable-ownership-and-reconciliation.md`.

## Verification

- `server`: `npx vitest run
src/services/native-runtime/native-speed-budgets.test.ts`, 18 passed.
Two new tests:
  - a recovery dominated by provider load does not breach;
- a slow Paperclip share breaches with `restartTotalMs` and
`providerLoadMs`, even when the provider span is committed after the
provider event.

The existing recovery tests moved to the new metric. All six were red
before the trace change.
- `tests/restart-chaos`: `npx vitest run --config
tests/restart-chaos/vitest.config.ts wave-speed.test.ts
ttft-baseline-stats.test.ts`, 29 passed. New tests cover the sample
split and the grader rows (a judged share, a report-only provider load,
zero breaches).
- Server typecheck: no errors in the touched files.

## Risks

- **Lower sensitivity to provider-side slowdowns.** A provider
regression in session load no longer breaches. It stays visible in the
report-only rows and in breach payloads.
- **Runs with no `provider.session.load` span** (reattach, or an adapter
that doesn't emit it) are judged on the full latency against the
control-plane budget. That's conservative.
- **Run-log consumers that filter on `metric: "restart_recovery"`** see
`restart_recovery_control_plane` from now on. The doc notes the change
date.

## Model Used

Claude Opus 5.5 (`claude-opus-5-5`, Anthropic), 1M context window, tool
use and code execution, via Claude Code.

## 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
- [x] I will address all Greptile and reviewer comments before
requesting merge

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
2026-11-09 01:22:28 -06:00

817 lines
30 KiB
TypeScript

import { getRunExecutionTraceContext } from "../execution-preparation-timing.js";
import { AsyncLocalStorage } from "node:async_hooks";
import { createHash } from "node:crypto";
import { isSpanContextValid, ROOT_CONTEXT, trace } from "@opentelemetry/api";
import { runWithRuntimeParent } from "@paperclipai/adapter-utils/acpx-engine/startup-timing";
import type { AdapterRuntimeEvent } from "../../adapters/index.js";
import {
getStartupTraceContext,
type StartupTraceContextHandle,
} from "../../instrumentation.js";
import {
evaluateSpeedBudget,
SPEED_BUDGET_EXCEEDED_EVENT_TYPE,
type SpeedBudgetAdapter,
type SpeedBudgetBreach,
type SpeedBudgetStart,
} from "./native-speed-budgets.js";
export const NATIVE_RUN_SPAN_EVENT_TYPE = "run.performance.span";
export const NATIVE_RUN_TRACE_SCHEMA_VERSION = 3;
export type NativeRunSpanOutcome = "ok" | "failed";
export interface NativeRunHistoricalSpan {
name: string;
parentName?: string;
startedAtMs: number;
endedAtMs: number;
outcome?: NativeRunSpanOutcome;
attributes?: Record<string, string | number | boolean>;
}
export function isNativeRunRootHistoricalSpan(name: string): boolean {
return (
name === "heartbeat.queue" ||
name === "comment.to_run_created" ||
name === "question_response.to_run_created"
);
}
/** Current causal ingress, not the older source comment kept for provenance. */
export function buildNativeWakeIngressSpan(input: {
runCreatedAtMs: number;
wakeComments: readonly unknown[];
/** Attempt-local output of committed server authorization, never a wake marker. */
attestedQuestionResponseAtMs: number | null;
}): NativeRunHistoricalSpan | null {
const answeredAt = input.attestedQuestionResponseAtMs;
if (answeredAt !== null && Number.isFinite(answeredAt) && answeredAt >= 0) {
return {
name: "question_response.to_run_created",
parentName: "task.provider_session",
startedAtMs: answeredAt,
endedAtMs: Math.max(answeredAt, input.runCreatedAtMs),
};
}
const createdAt = input.wakeComments
.map((comment) => {
const value =
comment && typeof comment === "object" && !Array.isArray(comment)
? (comment as Record<string, unknown>).createdAt
: null;
return typeof value === "string" ? Date.parse(value) : Number.NaN;
})
.filter(Number.isFinite)
.sort((a, b) => a - b)[0];
return createdAt === undefined
? null
: {
name: "comment.to_run_created",
parentName: "task.provider_session",
startedAtMs: createdAt,
endedAtMs: Math.max(createdAt, input.runCreatedAtMs),
};
}
export function buildNativeHeartbeatPreparationSpans(input: {
runCreatedAtMs: number;
runStartedAtMs: number;
attemptStartedAtMs: number;
environmentAcquireStartedAtMs: number;
environmentRealizeEndedAtMs: number;
nativeDispatchAtMs: number;
}): NativeRunHistoricalSpan[] {
return [
{
name: "heartbeat.queue",
parentName: "task.provider_session",
startedAtMs: input.runCreatedAtMs,
endedAtMs: Math.max(input.runCreatedAtMs, input.runStartedAtMs),
},
{
name: "heartbeat.prepare_before_environment",
parentName: "task.provider_session",
// A same-run resume retains startedAt for wall-time accounting; it is
// not the beginning of this dispatch attempt's preparation.
startedAtMs: input.attemptStartedAtMs,
endedAtMs: Math.max(
input.attemptStartedAtMs,
input.environmentAcquireStartedAtMs,
),
},
{
name: "heartbeat.prepare_after_environment",
parentName: "task.provider_session",
startedAtMs: Math.min(
input.nativeDispatchAtMs,
input.environmentRealizeEndedAtMs,
),
endedAtMs: input.nativeDispatchAtMs,
},
];
}
/** Which accepted input `task.time_to_first_token` is measured from. */
export type NativeTimeToFirstTokenAnchor =
| "question_response"
| "comment"
| "wake_request"
| "run_created";
/**
* Resolve the start of `task.time_to_first_token`: the earliest accepted input
* that caused this run. A question answer or a wake comment is already a root
* historical span. Otherwise the run row's creation time is the fallback. A
* durable wake request accepted earlier (deferred, coalesced or retried wakes)
* moves the start back to that request, so queueing before the run row exists
* is part of the measured latency.
*
* Run-log only. The wake request time is read after the first deliverable
* text, never before `turn.start`.
*/
export function resolveNativeTimeToFirstTokenStart(input: {
traceStartedAtMs: number;
preparationSpans: readonly NativeRunHistoricalSpan[];
wakeRequestedAtMs: number | null;
}): { startedAtMs: number; anchor: NativeTimeToFirstTokenAnchor } {
const ingress = input.preparationSpans.find(
(span) =>
span.name === "question_response.to_run_created" ||
span.name === "comment.to_run_created",
);
// The trace starts at the earliest preparation span. A comment coalesced
// into an already-queued run starts after run creation, so it names the
// start only when it is that earliest span.
const ingressIsStart = ingress !== undefined && ingress.startedAtMs <= input.traceStartedAtMs;
let anchor: NativeTimeToFirstTokenAnchor =
!ingressIsStart
? "run_created"
: ingress.name === "question_response.to_run_created"
? "question_response"
: "comment";
let startedAtMs = input.traceStartedAtMs;
const wakeAt = input.wakeRequestedAtMs;
if (
wakeAt !== null &&
Number.isFinite(wakeAt) &&
wakeAt >= 0 &&
wakeAt < startedAtMs
) {
startedAtMs = wakeAt;
anchor = "wake_request";
}
return { startedAtMs, anchor };
}
export function nativeRunPreparationStarts(
spans: NativeRunHistoricalSpan[],
nowMs: number,
): { runStartedAtMs: number; preparationStartedAtMs: number } {
const runStartedAtMs = spans.reduce(
(earliest, span) => Math.min(earliest, span.startedAtMs),
nowMs,
);
// Queue and accepted-comment latency remain run-level history. Including
// them in task.prepare would charge previous attempts and recovery delays
// to every resumed attempt, even if its actual startup took milliseconds.
const preparationStartedAtMs = spans
.filter((span) => !isNativeRunRootHistoricalSpan(span.name))
.reduce((earliest, span) => Math.min(earliest, span.startedAtMs), nowMs);
return { runStartedAtMs, preparationStartedAtMs };
}
export interface NativeRunSpanScope {
readonly name: string;
readonly parentName: string;
readonly startedAtMs: number;
}
type NativeRunTraceSink = (event: AdapterRuntimeEvent) => Promise<void>;
type SpanHandle = ReturnType<StartupTraceContextHandle["tracer"]["startSpan"]>;
interface NativeRunSpanScopeState extends NativeRunSpanScope {
span: SpanHandle;
context: unknown;
attributes: Record<string, string | number | boolean>;
ended: boolean;
persistRunLog: boolean;
}
const NOOP_SPAN: SpanHandle = {
setAttribute() {},
setStatus() {},
end() {},
};
const SAFE_NATIVE_RUN_SPAN_ATTRIBUTE_KEYS = new Set([
"adapter",
"anchor",
"bytesTransferred",
"inputBytes", "toolSchemaBytes", "toolCount", "contextReused", "tokenDataAvailable",
"connectionOwner",
"driver",
"duration_ms",
"eventKind",
"harness",
"identityPresent",
"lifecycleMode",
"mode",
"outcome",
"operation",
"provider",
"reason",
"runtime",
"stateSource",
"strategy",
"target",
]);
function finiteMs(value: number): number {
return Number.isFinite(value) ? Math.max(0, value) : 0;
}
function hashedId(value: string): string {
return createHash("sha256").update(value).digest("hex").slice(0, 12);
}
function safeAttributes(
attributes: Record<string, string | number | boolean> | undefined,
): Record<string, string | number | boolean> {
if (!attributes) return {};
return Object.fromEntries(
Object.entries(attributes)
.filter(
([key, value]) =>
SAFE_NATIVE_RUN_SPAN_ATTRIBUTE_KEYS.has(key) &&
(typeof value === "boolean" ||
(typeof value === "number" && Number.isFinite(value)) ||
(typeof value === "string" && value.length <= 120)),
)
.slice(0, 16),
);
}
/**
* Run-scoped tracing for the native Paperclip runner path.
*
* A scope owns a real OpenTelemetry parent context. While work runs inside a
* scope, nested native measurements and the existing sandbox/provider tracing
* seams inherit that context. The persisted run-event copy retains the same
* semantic parent name for developer installs without an OTLP collector.
*/
/** The runner span for the provider loading its saved session on resume. */
const PROVIDER_SESSION_LOAD_SPAN = "provider.session.load";
export function createNativeRunTrace(input: {
runId: string;
startedAtMs?: number;
onEvent?: NativeRunTraceSink;
traceContext?: StartupTraceContextHandle;
/** Called once when the trace finishes. */
onFinish?: () => void;
/** Speed-budget subject (invariant 8). Absent or remote means no check. */
budget?: {
adapter: SpeedBudgetAdapter | null;
environment: "local" | "remote";
/** A restart-recovery dispatch: its TTFT and boot span the outage, so only
* `restart_recovery` is judged. */
restartRecovery?: boolean;
};
}) {
const tracing =
input.traceContext ?? getStartupTraceContext("paperclip.native-runner");
const traceStartedAtMs = finiteMs(input.startedAtMs ?? Date.now());
/** Start times of the provider's saved-session loads (restart recovery split). */
const providerLoadStartsMs: number[] = [];
const runIdHash = hashedId(input.runId);
let rootSpan: SpanHandle;
try {
const owned = getRunExecutionTraceContext(input.runId);
const trigger = process.env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim()
? (owned ? trace.getSpan(owned) : trace.getActiveSpan())?.spanContext()
: undefined;
rootSpan = tracing.tracer.startSpan("task.provider_session", {
startTime: traceStartedAtMs,
attributes: {
"paperclip.task.run.run_id": runIdHash,
"paperclip.task.run.runtime": "paperclip_runner",
"paperclip.task.run.trace_schema_version":
NATIVE_RUN_TRACE_SCHEMA_VERSION,
},
...(trigger && isSpanContextValid(trigger) ? { links: [{ context: trigger }] } : {}),
}, ROOT_CONTEXT);
} catch {
rootSpan = NOOP_SPAN;
}
let rootContext: unknown;
try {
rootContext = tracing.contextWithSpan(rootSpan);
} catch {
rootContext = undefined;
}
const scopeStorage = new AsyncLocalStorage<
NativeRunSpanScopeState | undefined
>();
const scopes = new WeakSet<NativeRunSpanScope>();
const openScopes = new Set<NativeRunSpanScopeState>();
const namedScopes = new Map<string, NativeRunSpanScopeState>();
let runtimeParentScope: NativeRunSpanScopeState | undefined;
let ended = false;
const scopeState = (scope: NativeRunSpanScope): NativeRunSpanScopeState => {
if (!scopes.has(scope)) throw new Error("native_run_trace_scope_invalid");
return scope as NativeRunSpanScopeState;
};
const currentParent = (): { name: string; context: unknown } => {
const active = scopeStorage.getStore();
return active && !active.ended
? { name: active.name, context: active.context }
: runtimeParentScope && !runtimeParentScope.ended
? { name: runtimeParentScope.name, context: runtimeParentScope.context }
: { name: "task.provider_session", context: rootContext };
};
const parentFor = (
parentName?: string,
): { name: string; context: unknown } => {
if (parentName && parentName !== "task.provider_session") {
const named = namedScopes.get(parentName);
if (named) return { name: named.name, context: named.context };
return currentParent();
}
if (parentName === "task.provider_session")
return { name: "task.provider_session", context: rootContext };
return currentParent();
};
const setOtelAttributes = (
span: SpanHandle,
attributes: Record<string, string | number | boolean>,
): void => {
for (const [key, value] of Object.entries(attributes)) {
try {
span.setAttribute(`paperclip.native.span.${key}`, value);
} catch {
// Tracing is diagnostic-only and must never change runner control flow.
}
}
};
// Speed budgets (invariant 8). Breaches are written detached, after the
// measurement, so the check never adds a wait to the turn path.
let budgetStart: SpeedBudgetStart | null = null;
let queueEndedAtMs: number | null = null;
// When the run row was created (start of heartbeat.queue, end of the
// ingress span). Input accepted before it waited for a run to exist, for
// example a comment posted while the previous turn was still running.
let runCreatedAtMs: number | null = null;
let attemptStartedAtMs: number | null = null;
let bootChecked = false;
const reportBudgetBreach = (breach: SpeedBudgetBreach | null): void => {
if (!breach || !input.onEvent) return;
defer(async () => {
await input.onEvent?.({
eventType: SPEED_BUDGET_EXCEEDED_EVENT_TYPE,
stream: "system",
level: "warn",
message: `speed budget exceeded: ${breach.metric} ${breach.measuredMs}ms > p95 ${breach.budgetP95Ms}ms (${breach.adapter}, ${breach.startKind})`,
payload: breach,
});
});
};
const checkSpanBudget = (name: string, startedAtMs: number, endedAtMs: number): void => {
if (!input.budget || input.budget.restartRecovery) return;
const subject = { adapter: input.budget.adapter, environment: input.budget.environment };
if (name === "heartbeat.queue") { queueEndedAtMs = endedAtMs; runCreatedAtMs ??= startedAtMs; }
if (name === "comment.to_run_created" || name === "question_response.to_run_created") runCreatedAtMs ??= endedAtMs;
// A resumed attempt keeps the run's original queue span; its own claim is
// the start of this attempt's preparation.
if (name === "heartbeat.prepare_before_environment") attemptStartedAtMs = startedAtMs;
if (name === "task.time_to_first_agent_activity") {
// The span keeps the full user-visible latency. The budget (baseline:
// idle follow-ups) judges it from run creation: time the input spent
// waiting for a run to exist (behind a live turn) is reported, not judged.
// Time to first text (task.time_to_first_token) is reported, not budgeted.
const inputWaitMs = runCreatedAtMs !== null && runCreatedAtMs > startedAtMs ? runCreatedAtMs - startedAtMs : 0;
reportBudgetBreach(evaluateSpeedBudget({ ...subject, metric: "time_to_first_activity", start: budgetStart,
measuredMs: endedAtMs - startedAtMs - inputWaitMs, ...(inputWaitMs > 0 ? { inputWaitMs } : {}) }));
}
// Agent boot: run claimed (end of heartbeat.queue) to the provider session
// accepting turn.start (end of runner.turn.submit or runner.session.resume).
if ((name === "runner.turn.submit" || name === "runner.session.resume") && !bootChecked && queueEndedAtMs !== null) {
bootChecked = true;
const claimedAtMs = Math.max(queueEndedAtMs, attemptStartedAtMs ?? queueEndedAtMs);
reportBudgetBreach(evaluateSpeedBudget({ ...subject, metric: "agent_boot", start: budgetStart,
measuredMs: endedAtMs - claimedAtMs }));
}
};
const emitCompletedSpanEvent = async (
span: NativeRunHistoricalSpan,
): Promise<void> => {
const startedAtMs = finiteMs(span.startedAtMs);
const endedAtMs = Math.max(startedAtMs, finiteMs(span.endedAtMs));
const durationMs = endedAtMs - startedAtMs;
const outcome = span.outcome ?? "ok";
const attributes = safeAttributes(span.attributes);
try {
await input.onEvent?.({
eventType: NATIVE_RUN_SPAN_EVENT_TYPE,
stream: "system",
level: outcome === "failed" ? "warn" : "info",
message: `runner span: ${span.name} (${durationMs.toFixed(1)}ms)`,
payload: {
// Keep the persisted schema identifier stable; traceSchemaVersion
// describes the OTel hierarchy independently of the run-log shape.
schema: "paperclip.run-performance-span.v1",
traceSchemaVersion: NATIVE_RUN_TRACE_SCHEMA_VERSION,
span: span.name,
parentSpan: span.parentName ?? "task.provider_session",
startOffsetMs: startedAtMs - traceStartedAtMs,
durationMs,
outcome,
...attributes,
// The span's own start time. The row can be written late (deferred
// diagnostics), so readers must not infer the start from its write time.
wallStartedAtMs: startedAtMs,
},
});
} catch {
// A diagnostic sink failure must not fail the task.
}
};
const start = (
name: string,
options: {
parentName?: string;
startedAtMs?: number;
attributes?: Record<string, string | number | boolean>;
/** False only when an existing durable diagnostic batch already contains the measurements. */
persistRunLog?: boolean;
} = {},
): NativeRunSpanScope => {
const startedAtMs = finiteMs(options.startedAtMs ?? Date.now());
if (name === PROVIDER_SESSION_LOAD_SPAN) {
providerLoadStartsMs.push(startedAtMs);
// The measurement can arrive before its provider span is recorded; judge now.
if (pendingRecovery) judgeRestartRecovery();
}
const attributes = safeAttributes(options.attributes);
const parent = parentFor(options.parentName);
let span: SpanHandle;
try {
span = tracing.tracer.startSpan(
name,
{
startTime: startedAtMs,
attributes: {
"paperclip.native.span.trace_schema_version":
NATIVE_RUN_TRACE_SCHEMA_VERSION,
...Object.fromEntries(
Object.entries(attributes).map(([key, value]) => [
`paperclip.native.span.${key}`,
value,
]),
),
},
},
parent.context ?? ROOT_CONTEXT,
);
} catch {
span = NOOP_SPAN;
}
let context: unknown;
try {
context = tracing.contextWithSpan(span);
} catch {
context = undefined;
}
const state: NativeRunSpanScopeState = {
name,
parentName: parent.name,
startedAtMs,
span,
context,
attributes,
ended: false,
persistRunLog: options.persistRunLog !== false,
};
scopes.add(state);
openScopes.add(state);
namedScopes.set(name, state);
return state;
};
const annotate = (
scope: NativeRunSpanScope,
attributes: Record<string, string | number | boolean>,
): void => {
const state = scopeState(scope);
const incoming = safeAttributes(attributes);
const retained = Object.fromEntries(
Object.entries(state.attributes).slice(
0,
Math.max(0, 16 - Object.keys(incoming).length),
),
);
const safe = { ...retained, ...incoming };
state.attributes = safe;
setOtelAttributes(state.span, safe);
};
const end = async (
scope: NativeRunSpanScope,
options: {
endedAtMs?: number;
outcome?: NativeRunSpanOutcome;
attributes?: Record<string, string | number | boolean>;
} = {},
): Promise<void> => {
const state = scopeState(scope);
if (state.ended) return;
state.ended = true;
openScopes.delete(state);
const endedAtMs = Math.max(
state.startedAtMs,
finiteMs(options.endedAtMs ?? Date.now()),
);
const outcome = options.outcome ?? "ok";
const durationMs = endedAtMs - state.startedAtMs;
annotate(state, {
...options.attributes,
duration_ms: durationMs,
outcome,
});
if (outcome === "failed") { try { state.span.setStatus({ code: 2 }); } catch {} }
try { state.span.end(endedAtMs); } catch {}
if (state.persistRunLog) await emitCompletedSpanEvent({
name: state.name,
parentName: state.parentName,
startedAtMs: state.startedAtMs,
endedAtMs,
outcome,
attributes: state.attributes,
});
checkSpanBudget(state.name, state.startedAtMs, endedAtMs);
};
const activate = (scope: NativeRunSpanScope): void => {
const state = scopeState(scope);
if (state.ended) return;
runtimeParentScope = state;
};
const run = <T>(scope: NativeRunSpanScope, fn: () => T): T => {
const state = scopeState(scope);
const dynamicContext = new Proxy<Record<PropertyKey, unknown>>(
{},
{
get(_target, property) {
const active = scopeStorage.getStore();
const target =
active && !active.ended
? active.context
: runtimeParentScope && !runtimeParentScope.ended
? runtimeParentScope.context
: state.context;
if (
(typeof target !== "object" || target === null) &&
typeof target !== "function"
) {
return undefined;
}
const value = Reflect.get(target, property);
return typeof value === "function" ? value.bind(target) : value;
},
},
);
return scopeStorage.run(state, () =>
runWithRuntimeParent(dynamicContext, fn),
);
};
const record = async (span: NativeRunHistoricalSpan, options: { persistRunLog?: boolean } = {}): Promise<void> => {
const scope = start(span.name, {
parentName: span.parentName,
startedAtMs: span.startedAtMs,
attributes: span.attributes,
persistRunLog: options.persistRunLog,
});
await end(scope, {
endedAtMs: span.endedAtMs,
outcome: span.outcome,
});
};
const measure = async <T>(
name: string,
fn: () => Promise<T>,
options: {
parentName?: string;
attributes?: Record<string, string | number | boolean>;
} = {},
): Promise<T> => {
const scope = start(name, options);
let outcome: NativeRunSpanOutcome = "ok";
try {
return await run(scope, fn);
} catch (error) {
outcome = "failed";
throw error;
} finally {
await end(scope, { outcome });
}
};
/**
* Diagnostic work that must not block the caller (for example a read that
* anchors a span). It runs detached; `finish` settles it before the root
* span closes. The work must bound its own waits.
*/
const pendingDiagnostics = new Set<Promise<void>>();
const defer = (work: () => Promise<void>): void => {
if (ended) return;
const pending: Promise<void> = Promise.resolve()
.then(work)
.catch(() => {
// Diagnostics cannot change runner control flow.
})
.finally(() => {
pendingDiagnostics.delete(pending);
});
pendingDiagnostics.add(pending);
};
const finish = async (outcome: NativeRunSpanOutcome): Promise<void> => {
if (ended) return;
try { input.onFinish?.(); } catch { /* Diagnostics cannot change runner control flow. */ }
// Settled diagnostics can defer more (a budget breach after a deferred
// measurement), so drain until none remain. Judge restart recovery after
// the first drain, so a deferred provider span is counted, then drain its
// breach report.
while (pendingDiagnostics.size > 0) await Promise.all([...pendingDiagnostics]);
judgeRestartRecovery();
while (pendingDiagnostics.size > 0) await Promise.all([...pendingDiagnostics]);
if (ended) return;
ended = true;
const endedAtMs = Date.now();
for (const scope of [...openScopes].reverse()) {
await end(scope, { endedAtMs, outcome });
}
try { rootSpan.setAttribute("paperclip.task.run.wall_ms", endedAtMs - traceStartedAtMs); } catch {}
try { rootSpan.setAttribute("paperclip.task.run.outcome", outcome); } catch {}
if (outcome === "failed") { try { rootSpan.setStatus({ code: 2 }); } catch {} }
try { rootSpan.end(endedAtMs); } catch {}
// Preserve the historical run-log record without emitting a duplicate
// full-width child span into the OpenTelemetry waterfall.
await emitCompletedSpanEvent({
name: "task.provider_session.measured",
parentName: "task.provider_session",
startedAtMs: traceStartedAtMs,
endedAtMs,
outcome,
attributes: { runtime: "paperclip_runner" },
});
};
/** Labels the run cold (fresh provider session) or warm (reused). */
const setBudgetStart = (kind: SpeedBudgetStart): void => {
budgetStart ??= kind;
};
/** Restart recovery latency: control plane ready to the recovered run's
* next provider event, checked once per run. Only Paperclip's share is
* judged: ready to the start of the provider's session load (or to the
* event when nothing reloads). It is judged as soon as both are known: at
* the check when the load span is already recorded or nothing reloads (a
* reattached runner, whose dispositions launch nothing), when the load span is recorded, and otherwise when
* the run finishes. A run that detaches for another restart therefore keeps
* its warning unless the detach lands between the event and a deferred span. */
let recoveryChecked = false;
let pendingRecovery: RestartRecoveryMeasurement | null = null;
const judgeRestartRecovery = (): void => {
const measurement = pendingRecovery;
pendingRecovery = null;
if (!input.budget || !measurement || measurement.readyAtMs === null) return;
const readyAtMs = measurement.readyAtMs;
const loads = providerLoadStartsMs.filter(at => at >= readyAtMs && at <= measurement.committedAtMs);
const loadStartedAtMs = loads.length ? Math.min(...loads) : null;
const totalMs = measurement.committedAtMs - readyAtMs;
reportBudgetBreach(evaluateSpeedBudget({ adapter: input.budget.adapter, environment: input.budget.environment,
metric: "restart_recovery_control_plane", start: null, measuredMs: (loadStartedAtMs ?? measurement.committedAtMs) - readyAtMs,
disposition: measurement.disposition, restartTotalMs: totalMs,
providerLoadMs: loadStartedAtMs === null ? 0 : measurement.committedAtMs - loadStartedAtMs }));
};
const checkRestartRecovery = (measurement: RestartRecoveryMeasurement): void => {
if (!input.budget || recoveryChecked || measurement.readyAtMs === null) return;
// An event emitted before ready (buffered by a surviving runner and
// committed late) is not the recovered run's next event; it must not use
// the one check.
if (measurement.emittedAtMs !== null && measurement.emittedAtMs < measurement.readyAtMs) return;
if (measurement.committedAtMs < measurement.readyAtMs) return;
recoveryChecked = true;
pendingRecovery = measurement;
const readyAtMs = measurement.readyAtMs;
// Only a launched runner reloads a provider session (native-restart-recovery).
if (!["resume_dead_runner", "bootstrap_incomplete"].includes(measurement.disposition)
|| providerLoadStartsMs.some(at => at >= readyAtMs && at <= measurement.committedAtMs)) judgeRestartRecovery();
};
return {
traceStartedAtMs,
setBudgetStart,
checkRestartRecovery,
/** Judge a pending restart-recovery check now (the controller is detaching
* this run for another restart and will not finish the trace). */
flushRestartRecovery: () => judgeRestartRecovery(),
start,
annotate,
activate,
end,
run,
record,
measure,
defer,
finish,
};
}
export type NativeRunTrace = ReturnType<typeof createNativeRunTrace>;
/** Restart recovery latency: control plane ready to the recovered run's
* next provider event. The event is filtered on when it was emitted and
* measured to when it was committed (the baseline's run-log `created_at`). */
export type RestartRecoveryMeasurement = {
readyAtMs: number | null;
emittedAtMs: number | null;
committedAtMs: number;
disposition: string;
};
/** Group already-normalized provider measurements without exporting provider attributes. */
export async function recordNativeProviderPerformanceSpans(trace: NativeRunTrace, spans: NativeRunHistoricalSpan[]): Promise<void> {
if (!spans.length) return;
try {
const scope = trace.start("provider.runtime", { parentName: "native.session.execute",
startedAtMs: Math.min(...spans.map(span => span.startedAtMs)), persistRunLog: false });
try {
for (const span of spans) await trace.record({ name: span.name, parentName: "provider.runtime",
startedAtMs: span.startedAtMs, endedAtMs: span.endedAtMs, outcome: span.outcome }, { persistRunLog: false });
} finally {
await trace.end(scope, { endedAtMs: Math.max(...spans.map(span => span.endedAtMs)),
outcome: spans.some(span => span.outcome === "failed") ? "failed" : "ok" });
}
} catch { /* Diagnostics cannot replace the work's result. */ }
}
/** One local runner startup sub-step measured by the runner transport. */
export interface NativeRunnerStartupStep {
name: "runner.runtime.stage" | "runner.process.launch" | "provider.session.load";
mode: "bootstrap" | "resume";
startedAtMs: number;
endedAtMs: number;
outcome: NativeRunSpanOutcome;
}
/**
* Record a local runner startup sub-step under `runner.session.startup`.
* Run log (and Observability when an operator endpoint is set) only, never
* Telemetry. Detached: the run-log write never delays `turn.start`; the
* trace settles it at finish.
*/
export function recordNativeRunnerStartupStep(trace: NativeRunTrace | undefined, step: NativeRunnerStartupStep): void {
trace?.defer(() => trace.record({
name: step.name,
parentName: "runner.session.startup",
startedAtMs: step.startedAtMs,
endedAtMs: step.endedAtMs,
outcome: step.outcome,
attributes: { mode: step.mode, target: "local" },
}));
}
/** Emit preparation failure even when execution aborts before a native session exists. */
export async function recordFailedSkillPreparation(input: {
runId: string;
startedAtMs: number;
onEvent?: NativeRunTraceSink;
traceContext?: StartupTraceContextHandle;
}): Promise<void> {
try {
const trace = createNativeRunTrace(input);
const preparation = trace.start("task.prepare", { parentName: "task.provider_session", startedAtMs: input.startedAtMs });
const endedAtMs = Date.now();
await trace.record({ name: "skills.prepare", parentName: "task.prepare", startedAtMs: input.startedAtMs, endedAtMs, outcome: "failed" });
await trace.end(preparation, { endedAtMs, outcome: "failed" });
await trace.finish("failed");
} catch {
// Diagnostics must not replace the original preparation error.
}
}