From f35eb1e5efc3f01264adb7de7a59be1d6114a725 Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Sat, 7 Nov 2026 20:27:41 -0600 Subject: [PATCH] fix(observability): judge the TTFT budget from run creation; report the wait behind a live turn (#19941) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work. > - Invariant 8 of the durable-ownership plan says turns must start fast. #19863 added per-run speed budgets that write `run.performance.budget_exceeded` to the run log. > - The Phase 2 chaos data (#19927) showed follow-up TTFT about 3x over the claude budget. > - The cause is measurement scope. A follow-up comment posted during a live turn waits for that turn to end, and TTFT is anchored at the comment. The budgets came from idle follow-ups. > - This pull request judges the TTFT budget from run creation and reports the wait separately. > - The benefit is that budget breaches point at real start-up slowness, not at time spent behind a turn the user is already watching. ## Linked Issues or Issue Description Refs #19863 (speed budgets), #19927 (Phase 2 data), #19852 (startup sub-spans), #19888 (warm default). **What happened?** In two local storm waves, C1 follow-up runs breached the claude warm TTFT budget (p50 27.6–29.9 s against 9.5 s). Their spans show `comment.to_run_created` at 6–62 s (waiting for the live turn), then session resume at 1.4–3.8 s and submit-to-first-event at 2–5 s. Codex without the wait was about 4.8 s, the same as the warm-follow-up baseline. **What did you expect?** The budget should judge start-up latency, which is what its baseline measured. The wait behind a live turn should be visible but not judged. **Steps to reproduce** 1. Run a local chaos storm with C1 tasks. 2. Read `run.performance.budget_exceeded` rows with metric `ttft` for `issue_commented` runs, and compare them with each run's `comment.to_run_created` span. ## What Changed - `native-run-trace.ts`: the TTFT budget check measures from run creation (start of `heartbeat.queue`, or end of the ingress span). The TTFT span itself does not change. - `native-speed-budgets.ts`: breaches can carry `inputWaitMs` (TTFT only). - `tests/restart-chaos/ttft-baseline-stats.ts` and `ttft-baseline.ts`: the wait behind a live turn is its own measured step (`inputWait`), next to the full TTFT and the TTFT from run creation. The TTFT table gains a "Wait behind live turn" column. The full comment-to-first-token time stays the user-visible metric. - `doc/run-log-events.md` and the plan's speed-budget section describe the rule. ## Verification - `cd server && npx vitest run src/services/native-runtime/native-speed-budgets.test.ts src/services/native-runtime/native-run-trace.test.ts`: 43 pass, 2 new. `pnpm exec vitest run --config tests/restart-chaos/vitest.config.ts tests/restart-chaos/ttft-baseline-stats.test.ts`: 12 pass, 1 new. They cover a follow-up under budget after a 60 s wait (no breach), a follow-up over budget (breach with `inputWaitMs`), and queueing after run creation still judged. - Server typecheck passes. ## Risks - Low. This is a run-log-only change (AGENTS.md §5.7): no Telemetry and no span attributes change. - A slow wait before run creation is no longer a TTFT budget breach. The TTFT span still records it, and the breach payload names it. Admission holds after run creation are still judged. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, in Claude Code with tool use (shell, file edits). ## 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 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 --- ...07-durable-ownership-and-reconciliation.md | 2 +- doc/run-log-events.md | 3 ++ .../native-runtime/native-run-trace.ts | 13 ++++++-- .../native-speed-budgets.test.ts | 33 +++++++++++++++++++ .../native-runtime/native-speed-budgets.ts | 5 +++ .../restart-chaos/ttft-baseline-stats.test.ts | 15 +++++++++ tests/restart-chaos/ttft-baseline-stats.ts | 24 ++++++++++++-- tests/restart-chaos/ttft-baseline.ts | 4 +-- 8 files changed, 91 insertions(+), 8 deletions(-) diff --git a/doc/plans/2026-11-07-durable-ownership-and-reconciliation.md b/doc/plans/2026-11-07-durable-ownership-and-reconciliation.md index 8032c06acfc..6ae500192d3 100644 --- a/doc/plans/2026-11-07-durable-ownership-and-reconciliation.md +++ b/doc/plans/2026-11-07-durable-ownership-and-reconciliation.md @@ -73,7 +73,7 @@ Each metric is reported by adapter (Codex, Claude/ACPX, OpenCode) and environmen Phase 1 sets these budgets from the local baseline in `2026-11-07-ttft-baseline.md`. Each budget is the baseline value times 1.2, rounded up to 0.5 s. The 20% headroom covers the small samples and the shared host of the baseline. Daytona and other remote environments get budgets after their own baseline. -A single run is checked against its p95 budget. When a run exceeds it, the run log gets one `run.performance.budget_exceeded` row (`doc/run-log-events.md`). The p50 budgets apply to aggregates: chaos waves, the baseline driver, and staging. Every later phase's exit criteria include "no regression against these budgets". The table lives in code at `server/src/services/native-runtime/native-speed-budgets.ts`. +A single run is checked against its p95 budget. When a run exceeds it, the run log gets one `run.performance.budget_exceeded` row (`doc/run-log-events.md`). The TTFT span keeps the full user-visible latency, but the TTFT budget judges it from run creation: time an input waited for its run to exist (for example a comment posted while the previous turn was still running) is not judged, because the baseline measured idle follow-ups. That wait is real user-visible latency, so it is its own measured step: the `comment.to_run_created` span in the run log, `inputWaitMs` in a breach, and its own column ("Wait behind live turn") in the TTFT tables of the baseline driver and chaos reports, next to the full comment-to-first-token TTFT. The p50 budgets apply to aggregates: chaos waves, the baseline driver, and staging. Every later phase's exit criteria include "no regression against these budgets". The table lives in code at `server/src/services/native-runtime/native-speed-budgets.ts`. Time to first token (s, p50 / p95): diff --git a/doc/run-log-events.md b/doc/run-log-events.md index 8ae2618d9cf..1119e5b8064 100644 --- a/doc/run-log-events.md +++ b/doc/run-log-events.md @@ -100,6 +100,9 @@ provider event). The payload names `adapter` (`codex`, `claude` or `opencode`), `environment` (`local`), `startKind` (`cold`, `warm` or `unknown`; an unknown start uses the looser budget), `measuredMs`, `budgetP50Ms`, `budgetP95Ms`, `percentile` (`p95`), `baseline`, and, for restart recovery, `disposition`. +For `ttft`, `measuredMs` counts from run creation: when the input waited for its +run to exist (for example a comment posted while the previous turn was still +running), that wait is excluded from the judgment and reported as `inputWaitMs`. Each metric is checked at most once per dispatch. A restart-recovery dispatch is judged only on `restart_recovery`, because its TTFT and boot span the outage. Remote runs and other adapters have no budget yet. The event is written in detached diagnostic work after the diff --git a/server/src/services/native-runtime/native-run-trace.ts b/server/src/services/native-runtime/native-run-trace.ts index 0685506fcec..7615ce13364 100644 --- a/server/src/services/native-runtime/native-run-trace.ts +++ b/server/src/services/native-runtime/native-run-trace.ts @@ -359,6 +359,10 @@ export function createNativeRunTrace(input: { // 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 => { @@ -376,13 +380,18 @@ export function createNativeRunTrace(input: { 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; + 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_token") { + // 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. + const inputWaitMs = runCreatedAtMs !== null && runCreatedAtMs > startedAtMs ? runCreatedAtMs - startedAtMs : 0; reportBudgetBreach(evaluateSpeedBudget({ ...subject, metric: "ttft", start: budgetStart, - measuredMs: endedAtMs - startedAtMs })); + 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). diff --git a/server/src/services/native-runtime/native-speed-budgets.test.ts b/server/src/services/native-runtime/native-speed-budgets.test.ts index 02a6a6b4116..72741b7c20b 100644 --- a/server/src/services/native-runtime/native-speed-budgets.test.ts +++ b/server/src/services/native-runtime/native-speed-budgets.test.ts @@ -87,6 +87,39 @@ describe("speed budget checks in the native run trace", () => { expect(breaches()).toEqual([expect.objectContaining({ metric: "ttft", adapter: "claude", startKind: "warm", measuredMs: ttft })]); }); + it("judges a follow-up's TTFT from run creation and reports the wait behind the live turn", async () => { + // A comment posted while the previous turn runs waits for a run to exist; + // the budget (idle follow-up baseline) judges the time after that. + const budget = LOCAL_SPEED_BUDGETS.claude.ttft.warm.p95Ms; + const wait = 60_000; + const quiet = traced({ adapter: "claude", environment: "local" }); + quiet.trace.setBudgetStart("warm"); + await quiet.trace.record({ name: "comment.to_run_created", startedAtMs: 0, endedAtMs: wait }); + await quiet.trace.record({ name: "heartbeat.queue", startedAtMs: wait, endedAtMs: wait + 100 }); + await quiet.trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: wait + budget - 1 }); + await quiet.trace.finish("ok"); + expect(quiet.breaches()).toEqual([]); + + const slow = traced({ adapter: "claude", environment: "local" }); + slow.trace.setBudgetStart("warm"); + await slow.trace.record({ name: "comment.to_run_created", startedAtMs: 0, endedAtMs: wait }); + await slow.trace.record({ name: "heartbeat.queue", startedAtMs: wait, endedAtMs: wait + 100 }); + await slow.trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: wait + budget + 1 }); + await slow.trace.finish("ok"); + expect(slow.breaches()).toEqual([expect.objectContaining({ metric: "ttft", measuredMs: budget + 1, inputWaitMs: wait })]); + }); + + it("still judges queueing after run creation (admission, dispatch) inside the TTFT budget", async () => { + const { trace, breaches } = traced({ adapter: "codex", environment: "local" }); + trace.setBudgetStart("cold"); + const budget = LOCAL_SPEED_BUDGETS.codex.ttft.cold.p95Ms; + await trace.record({ name: "heartbeat.queue", startedAtMs: 0, endedAtMs: budget }); + await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: budget + 1 }); + await trace.finish("ok"); + expect(breaches()).toEqual([expect.objectContaining({ metric: "ttft", measuredMs: budget + 1 })]); + expect(breaches()[0]).not.toHaveProperty("inputWaitMs"); + }); + it("checks restart recovery latency once, from ready to the first provider event", async () => { const { trace, breaches } = traced({ adapter: "opencode", environment: "local" }); const late = LOCAL_SPEED_BUDGETS.opencode.restart_recovery.p95Ms + 1_000; diff --git a/server/src/services/native-runtime/native-speed-budgets.ts b/server/src/services/native-runtime/native-speed-budgets.ts index 1d746946dd8..3b49837caf2 100644 --- a/server/src/services/native-runtime/native-speed-budgets.ts +++ b/server/src/services/native-runtime/native-speed-budgets.ts @@ -87,6 +87,9 @@ export type SpeedBudgetBreach = { percentile: "p95"; baseline: string; disposition?: string; + /** TTFT only: time the input waited for its run to exist (for example a + * comment posted while the previous turn was running). Not judged. */ + inputWaitMs?: number; }; /** A breach when one measured run exceeds its p95 budget, else null. */ @@ -97,6 +100,7 @@ export function evaluateSpeedBudget(input: { start: SpeedBudgetStart | null; measuredMs: number; disposition?: string; + inputWaitMs?: number; }): SpeedBudgetBreach | null { if (!input.adapter || input.environment !== "local" || !Number.isFinite(input.measuredMs) || input.measuredMs < 0) return null; const budget = speedBudgetFor(input.adapter, input.metric, input.start); @@ -106,6 +110,7 @@ export function evaluateSpeedBudget(input: { startKind: input.start ?? "unknown", measuredMs: Math.round(input.measuredMs), budgetP50Ms: budget.p50Ms, budgetP95Ms: budget.p95Ms, percentile: "p95", baseline: SPEED_BUDGET_BASELINE, ...(input.disposition ? { disposition: input.disposition } : {}), + ...(input.inputWaitMs ? { inputWaitMs: Math.round(input.inputWaitMs) } : {}), }; } diff --git a/tests/restart-chaos/ttft-baseline-stats.test.ts b/tests/restart-chaos/ttft-baseline-stats.test.ts index 246870d97b1..2a1b7173b96 100644 --- a/tests/restart-chaos/ttft-baseline-stats.test.ts +++ b/tests/restart-chaos/ttft-baseline-stats.test.ts @@ -43,6 +43,21 @@ describe("ttft baseline statistics", () => { ]); }); + it("reports the wait behind a live turn as its own step and the TTFT the budget judges", () => { + // A follow-up comment posted during the previous turn waits 40 s for its run. + const followUp = run("f", "warm", [ + reuse("reused"), + span("comment.to_run_created", 0, 40_000), + span("heartbeat.queue", 40_000, 100), + span("runner.session.resume", 40_100, 2_000), + span("task.time_to_first_token", 0, 45_000, { anchor: "comment" }), + ]); + expect(runMetrics(followUp)).toMatchObject({ ttftMs: 45_000, inputWaitMs: 40_000, ttftAfterRunCreatedMs: 5_000 }); + expect(runMetrics(coldRun("c"))).toMatchObject({ inputWaitMs: null, ttftAfterRunCreatedMs: 6_000 }); + const [row] = baselineRows([followUp]); + expect(row).toMatchObject({ ttft: { p50: 45_000 }, inputWait: { n: 1, p50: 40_000 }, ttftAfterRunCreated: { p50: 5_000 } }); + }); + it("uses runner.session.resume as the turn boundary for a resumed session", () => { const resumed = run("r", "warm", [reuse("reused"), span("heartbeat.queue", 0, 50), span("runner.session.resume", 60, 940)]); expect(runWarmth(resumed)).toBe("warm"); diff --git a/tests/restart-chaos/ttft-baseline-stats.ts b/tests/restart-chaos/ttft-baseline-stats.ts index 4fc3b563d06..2034038e4a1 100644 --- a/tests/restart-chaos/ttft-baseline-stats.ts +++ b/tests/restart-chaos/ttft-baseline-stats.ts @@ -70,10 +70,16 @@ export interface RunMetrics { bootMs: number | null; /** Durations of every span that starts before the first turn submission. */ preTurnSteps: Record; + /** Input accepted to run created (`comment.to_run_created` or + * `question_response.to_run_created`): the wait behind a live turn. Part of + * the user-visible TTFT; reported as its own step, not judged by the budget. */ + inputWaitMs: number | null; + /** TTFT from run creation: what the speed budget judges. */ + ttftAfterRunCreatedMs: number | null; } /** Spans that wrap others (or the whole run); ranking them would double count. */ -const CUMULATIVE_SPANS = new Set(["task.time_to_first_token", "task.provider_session.measured", "task.prepare", +const CUMULATIVE_SPANS = new Set(["task.time_to_first_token", "comment.to_run_created", "question_response.to_run_created", "task.provider_session.measured", "task.prepare", "native.session.execute", "runner.session.startup", "agent.turn", "environment.startup"]); const FIRST_SPAN = (spans: RunSpan[], name: string) => spans.find(span => span.name === name) ?? null; @@ -95,7 +101,12 @@ export function runMetrics(run: BaselineRun): RunMetrics { if (span.startOffsetMs < turnStartAt && !(span.name in preTurnSteps)) preTurnSteps[span.name] = span.durationMs; } } + const ingress = FIRST_SPAN(spans, "comment.to_run_created") ?? FIRST_SPAN(spans, "question_response.to_run_created"); + // Only an ingress that starts the TTFT span waited for its run to exist. + const inputWaitMs = ingress && ttft && ingress.startOffsetMs <= ttft.startOffsetMs ? ingress.durationMs : null; return { + inputWaitMs, + ttftAfterRunCreatedMs: ttft ? Math.max(0, ttft.durationMs - (inputWaitMs ?? 0)) : null, ttftMs: ttft ? ttft.durationMs : null, ttftAnchor: ttft && typeof ttft.attributes.anchor === "string" ? ttft.attributes.anchor : null, bootMs: claimedAt !== null && turnStartAt !== null ? Math.max(0, turnStartAt - claimedAt) : null, @@ -128,7 +139,12 @@ export function recoverySamples(runs: readonly BaselineRun[], faults: readonly B return samples; } -export interface BaselineRow { adapter: string; environment: string; warmth: "cold" | "warm"; ttft: Distribution; boot: Distribution; anchors: Record } +export interface BaselineRow { adapter: string; environment: string; warmth: "cold" | "warm"; ttft: Distribution; boot: Distribution; + /** The wait behind a live turn (input accepted to run created), its own measured step. */ + inputWait: Distribution; + /** TTFT from run creation: the value the speed budget judges. */ + ttftAfterRunCreated: Distribution; + anchors: Record } export function baselineRows(runs: readonly BaselineRun[]): BaselineRow[] { const groups = new Map(); @@ -145,7 +161,9 @@ export function baselineRows(runs: readonly BaselineRun[]): BaselineRow[] { for (const metric of group.metrics) if (metric.ttftAnchor) anchors[metric.ttftAnchor] = (anchors[metric.ttftAnchor] ?? 0) + 1; return { adapter: group.adapter, environment: group.environment, warmth: group.warmth, anchors, ttft: distribution(group.metrics.flatMap(metric => metric.ttftMs === null ? [] : [metric.ttftMs])), - boot: distribution(group.metrics.flatMap(metric => metric.bootMs === null ? [] : [metric.bootMs])) }; + boot: distribution(group.metrics.flatMap(metric => metric.bootMs === null ? [] : [metric.bootMs])), + inputWait: distribution(group.metrics.flatMap(metric => metric.inputWaitMs === null ? [] : [metric.inputWaitMs])), + ttftAfterRunCreated: distribution(group.metrics.flatMap(metric => metric.ttftAfterRunCreatedMs === null ? [] : [metric.ttftAfterRunCreatedMs])) }; }); } diff --git a/tests/restart-chaos/ttft-baseline.ts b/tests/restart-chaos/ttft-baseline.ts index 7ddb0c1978b..d527afda5b9 100644 --- a/tests/restart-chaos/ttft-baseline.ts +++ b/tests/restart-chaos/ttft-baseline.ts @@ -152,9 +152,9 @@ async function readyAdapters(api: ChaosApi, lab: ChaosLab, adapters: AdapterId[] function report(runs: BaselineRun[], faults: BaselineFault[]): string { const ms = (value: number | null) => value === null ? "—" : `${(value / 1000).toFixed(2)} s`; - const lines = ["| Adapter | Env | Start | n | TTFT p50 | TTFT p95 | Boot p50 | Boot p95 | TTFT anchors |", "|---|---|---|---|---|---|---|---|---|"]; + const lines = ["| Adapter | Env | Start | n | TTFT p50 | TTFT p95 | Wait behind live turn p50 / p95 (n) | TTFT from run created p50 / p95 | Boot p50 | Boot p95 | TTFT anchors |", "|---|---|---|---|---|---|---|---|---|---|---|"]; for (const row of baselineRows(runs)) { - lines.push(`| ${row.adapter} | ${row.environment} | ${row.warmth} | ${row.ttft.n}/${row.boot.n} | ${ms(row.ttft.p50)} | ${ms(row.ttft.p95)} | ${ms(row.boot.p50)} | ${ms(row.boot.p95)} | ${Object.entries(row.anchors).map(([k, v]) => `${k}×${v}`).join(", ") || "—"} |`); + lines.push(`| ${row.adapter} | ${row.environment} | ${row.warmth} | ${row.ttft.n}/${row.boot.n} | ${ms(row.ttft.p50)} | ${ms(row.ttft.p95)} | ${ms(row.inputWait.p50)} / ${ms(row.inputWait.p95)} (${row.inputWait.n}) | ${ms(row.ttftAfterRunCreated.p50)} / ${ms(row.ttftAfterRunCreated.p95)} | ${ms(row.boot.p50)} | ${ms(row.boot.p95)} | ${Object.entries(row.anchors).map(([k, v]) => `${k}×${v}`).join(", ") || "—"} |`); } lines.push("", "| Pre-turn step | n | p50 | p95 | Adapters |", "|---|---|---|---|---|"); for (const step of rankPreTurnSteps(runs).slice(0, 25)) lines.push(`| \`${step.step}\` | ${step.n} | ${ms(step.p50)} | ${ms(step.p95)} | ${step.adapters.join(", ")} |`);