mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-10 12:37:55 +01:00
perf(budgets): judge time to first visible agent activity; keep time to first text as a reported metric (#20077)
## Thinking Path - The native speed budgets (plan invariant 8) judge how fast an agent responds. They judged `task.time_to_first_token`: time to the first deliverable **text**. - In the clean local restart storm (w-20261108T153612-s9401), Claude breached its TTFT budget (cold p50/p95 17.4/34.7 s against 16.5/30). The per-run spans showed this was not a control-plane wait: in all 49 cold runs (and 76% of warm), Claude started a tool call before writing any text. Its first visible activity came at 7.4 s p50 from run creation; first text came at 19.6 s. Codex never calls a tool first. - So first text charges model tool work as latency for tool-first adapters. What the user experiences as "the agent responded" is the first visible activity: a text delta, a tool-call start, or a thinking indicator. - The coordinator decided: budgets judge time to first visible agent activity from run creation, with the budget numbers unchanged; first text stays a reported metric with no budget for tool-first adapters. ## Linked Issues or Issue Description **What happened?** Local storm s9401: the Claude TTFT budget breached on every aggregate, while the control-plane steps (queue 0.05 s, prepare 0.3 s, runner startup ~4 s, first provider event 1.3–1.8 s) were well within budget. The rest of the first-text wait was Claude streaming tool input (about 5.5 s per call) and running tools before it wrote text. **Steps to reproduce** 1. Run a Claude task whose first action is a tool call (most real tasks). 2. Read the run log: `provider.time_to_first_agent_event` ends at the tool call; `task.time_to_first_token` ends many seconds later at the first text. 3. The speed budget judges the later one and reports a breach. **Expected behavior** The budget judges the first visible agent activity from run creation (`task.time_to_first_agent_activity`). Time to first text is still recorded and reported. ## What Changed - `server/src/services/native-runtime/native-session-executor.ts`: when the first meaningful agent event commits (the existing `firstMeaningfulAgentEventKind`: text delta, tool-call start, or reasoning), record `task.time_to_first_agent_activity`. It uses the same detached anchor resolution as TTFT (accepted comment, answered question, durable wake request, or run creation), so it adds nothing to the turn path. - `server/src/services/native-runtime/native-speed-budgets.ts`: the metric is now named `time_to_first_activity` (was `ttft`), with identical budget numbers. The type comment documents the definition and why first text is unbudgeted. - `server/src/services/native-runtime/native-run-trace.ts`: the budget check judges `task.time_to_first_agent_activity` from run creation, keeping the existing input-wait handling. `task.time_to_first_token` is no longer budgeted. - `tests/restart-chaos/ttft-baseline-stats.ts` and `ttft-baseline.ts`: report first activity from run creation (the budgeted value) next to TTFT. - Docs: `doc/observability.md` (new span) and `doc/plans/2026-11-07-ttft-baseline.md` (metric table). - Tests: - A tool-first turn records first activity at the tool call (5 s) while TTFT records first text (16 s). - A tool-first trace with slow first text but fast first activity is within budget. - The existing budget tests now judge the activity span. Observability path (AGENTS.md section 5.7): the new run-log span uses only the existing `eventKind` and `anchor` attributes. Its name survives run-log redaction intact; checked with `redactEventPayload`. The operator OTLP gate is unchanged. It is not Telemetry. ## Verification - `cd server && npx vitest run src/services/native-runtime/native-speed-budgets.test.ts src/services/native-runtime/native-run-trace.test.ts`: 44/44 pass. - `cd server && npx vitest run src/services/native-runtime/native-session-executor.test.ts -t "first visible activity|first assistant text once|first-token timing"`: 7/7 pass. - `npx vitest run --root tests/restart-chaos`: 159/159 pass; `tsc` on `tests/restart-chaos` is clean. ## Risks - **A metric rename.** Consumers of `run.performance.budget_exceeded` see `metric: "time_to_first_activity"` instead of `"ttft"`. In-repo there are none besides the tests; Phase 3's chaos speed grade switches to the new span. - **A looser budget for slow first text.** Intentional: first text is reported, not judged. A regression in control-plane latency still shows up in first activity. ## 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>
This commit is contained in:
1 parent
015d3d0a7c
commit
b32ef9f111
12 files changed
+179
-44
No files matched your search
@@ -772,6 +772,18 @@ queueing, preparation and execution; do not add its duration to those phases.
|
||||
No text or provider event identifiers are exported. The existing duration attribute
|
||||
is `paperclip.native.span.duration_ms`.
|
||||
|
||||
`task.time_to_first_agent_activity` uses the same start and `anchor` as
|
||||
`task.time_to_first_token`, and ends when Core commits the first event that
|
||||
`provider.time_to_first_agent_event` counts: a text delta, a tool-call start, or
|
||||
a reasoning item, whichever comes first. That is when the user sees the agent
|
||||
respond, so the native speed budgets judge this span (metric
|
||||
`time_to_first_activity`, measured from run creation). Its `eventKind` is
|
||||
`agentMessage`, `reasoning`, `toolCall` or `dynamicToolCall`. Time to first text
|
||||
stays a reported metric without a budget: tool-first adapters (for example
|
||||
Claude) often call tools before they write any text, so first text includes
|
||||
model tool work rather than control-plane latency. Like TTFT, it is a cumulative
|
||||
child of `task.provider_session`; do not add it to the phases it overlaps.
|
||||
|
||||
`tool.request.input_stream` measures the observed request-input window: from
|
||||
an ACP tool announcement to its last input update before the provider reports
|
||||
the tool complete. It can include provider buffering and transport. It is not
|
||||
|
||||
@@ -37,7 +37,7 @@ These become reconciler checks and crash-suite assertions. They should also be a
|
||||
5. **Work-based budgets:** a restart consumes run budget only when the resumed attempt started provider work and made no progress.
|
||||
6. **Generation fencing:** every runner and provider event carries its generation and turn. Events from an earlier generation are recorded as history and never fail the current turn.
|
||||
7. **Visible next action:** every non-terminal task has a next action, either automatic or a working control. "Waiting" with no owner is a violation.
|
||||
8. **Fast turns:** TTFT and agent boot stay within their measured budgets. Restart safety work never adds waiting or file transfer before `turn.start` (see "Performance constraint" below).
|
||||
8. **Fast turns:** time to first visible agent activity and agent boot stay within their measured budgets (TTFT, time to first text, is reported; since 2026-11-08 the budget judges first activity, because tool-first adapters call tools before writing text). Restart safety work never adds waiting or file transfer before `turn.start` (see "Performance constraint" below).
|
||||
|
||||
## Performance constraint: a turn must start as fast as possible
|
||||
|
||||
|
||||
@@ -45,6 +45,7 @@ Plan: [`2026-11-07-durable-ownership-and-reconciliation.md`](2026-11-07-durable-
|
||||
| Metric | Definition (run-log spans) |
|
||||
|---|---|
|
||||
| **TTFT** | `task.time_to_first_token`. It runs from the accepted input to the first deliverable text committed by Core. The accepted input is the wake comment, the answered question, or the durable wake request when that is earlier (#19838). Otherwise it is run creation. `anchor` names which one. |
|
||||
| **First visible activity** | `task.time_to_first_agent_activity`: the same start as TTFT, to the first text delta, tool-call start or reasoning item committed by Core. Added 2026-11-08: the speed budgets judge this metric (from run creation) with the TTFT numbers below, and TTFT is reported without a budget, because tool-first adapters such as Claude call tools before they write text. |
|
||||
| **Agent boot** | Run claimed (end of `heartbeat.queue`) → provider session accepted `turn.start` (end of `runner.turn.submit`, or of `runner.session.resume` for a resumed session) |
|
||||
| **Pre-turn steps** | Every span that starts before the turn boundary above, without cumulative wrappers (`task.prepare`, `runner.session.startup`, `environment.startup`) |
|
||||
| **Restart recovery latency** | Fault `readyAt` (the harness saw `/api/ready` = `ready` and a healthy `/api/liveness`) → the recovered run's next provider event, grouped by `native.recovery.transition.runnerDisposition` |
|
||||
|
||||
@@ -93,18 +93,20 @@ earlier output timing. The event contains no text or provider identifiers.
|
||||
level `warn`) records one native run that exceeded its p95 speed budget. The
|
||||
budgets come from the Phase 0 local baseline and are listed in
|
||||
`doc/plans/2026-11-07-durable-ownership-and-reconciliation.md` ("Speed budgets").
|
||||
`metric` is `ttft` (`task.time_to_first_token`), `agent_boot` (end of
|
||||
`metric` is `time_to_first_activity` (`task.time_to_first_agent_activity`:
|
||||
the first text delta, tool-call start or reasoning item; named `ttft` and
|
||||
judged on `task.time_to_first_token` before 2026-11-08), `agent_boot` (end of
|
||||
`heartbeat.queue` to the end of `runner.turn.submit` or `runner.session.resume`)
|
||||
or `restart_recovery` (startup recovery `ready` to the recovered run's first
|
||||
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
|
||||
For `time_to_first_activity`, `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
|
||||
judged only on `restart_recovery`, because its first activity and boot span the outage. Time to first text (`task.time_to_first_token`) is reported without a budget. Remote runs and other adapters have
|
||||
no budget yet. The event is written in detached diagnostic work after the
|
||||
measurement, so it adds no wait before `turn.start`. It is a run-log row only
|
||||
and never goes to Telemetry.
|
||||
|
||||
@@ -385,12 +385,13 @@ export function createNativeRunTrace(input: {
|
||||
// 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") {
|
||||
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: "ttft", start: budgetStart,
|
||||
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
|
||||
|
||||
@@ -8842,6 +8842,41 @@ describe("native resumed preparation timing", () => {
|
||||
},
|
||||
);
|
||||
|
||||
it("records first visible activity at a tool call that precedes the first text", async () => {
|
||||
const startedAtMs = Date.now() - 20_000;
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
const clock = vi.spyOn(Date, "now").mockReturnValue(startedAtMs + 3_000);
|
||||
const event = (eventType: string, payload: Record<string, unknown>) => ({
|
||||
eventType, payload, itemId: "item", emittedAt: new Date(Date.now()).toISOString(),
|
||||
}) as PrpEvent;
|
||||
state.execute.mockReset().mockImplementationOnce(async () => {
|
||||
for (const candidate of [event("turn.submitted", {}), event("turn.started", {})]) await accountingEvents.committed!(candidate);
|
||||
clock.mockReturnValue(startedAtMs + 5_000);
|
||||
// Tool-first: the agent starts a tool before it writes any text.
|
||||
await accountingEvents.committed!(event("tool.execution.started", { executionId: "tool-1" }));
|
||||
clock.mockReturnValue(startedAtMs + 16_000);
|
||||
await accountingEvents.committed!(event("item.delta", { kind: "agentMessage", text: "first text" }));
|
||||
return { result: { summary: "cancelled" }, terminal: { runTerminalState: "cancelled" },
|
||||
turnId: "turn", normalizedSessionId: "session", providerSessionId: null,
|
||||
driverKind: "test", driverVersion: "1", nativeEventCount: 1, highestContiguousSourceSeq: 1 };
|
||||
});
|
||||
try {
|
||||
await executePaperclipNativeSession({ db: leaseDb(), execution, runnerInstanceId: "runner",
|
||||
preparationSpans: [{ name: "heartbeat.queue", startedAtMs, endedAtMs: startedAtMs + 100 }],
|
||||
onEvent: async (event) => {
|
||||
events.push(event);
|
||||
// A slow run-log sink: writing the first-agent-event span takes 3 s.
|
||||
// That write must not count as time until the agent responded.
|
||||
if (event.payload?.span === "provider.time_to_first_agent_event") clock.mockReturnValue(startedAtMs + 8_000);
|
||||
} });
|
||||
} finally { clock.mockRestore(); }
|
||||
const span = (name: string) => events.filter((candidate) => candidate.payload?.span === name);
|
||||
expect(span("task.time_to_first_agent_activity")).toHaveLength(1);
|
||||
expect(span("task.time_to_first_agent_activity")[0]?.payload).toMatchObject({ parentSpan: "task.provider_session",
|
||||
startOffsetMs: 0, durationMs: 5_000, eventKind: "toolCall", anchor: "run_created" });
|
||||
expect(span("task.time_to_first_token")[0]?.payload).toMatchObject({ durationMs: 16_000, eventKind: "agentMessage" });
|
||||
});
|
||||
|
||||
it("anchors first-token timing at an earlier durable wake request without blocking later events", async () => {
|
||||
const startedAtMs = Date.now() - 5_000;
|
||||
const events: AdapterRuntimeEvent[] = [];
|
||||
|
||||
@@ -10363,6 +10363,9 @@ async function executePaperclipNativeSessionWithinScope(
|
||||
const kind = firstMeaningfulAgentEventKind(event);
|
||||
if (kind) {
|
||||
firstAgentEventRecorded = true;
|
||||
// The commit observation, read before any diagnostic write so a slow
|
||||
// run-log sink never counts as time until the agent responded.
|
||||
const activityAt = Date.now();
|
||||
await trace.record({
|
||||
name: "provider.time_to_first_agent_event",
|
||||
parentName: "agent.turn",
|
||||
@@ -10370,6 +10373,23 @@ async function executePaperclipNativeSessionWithinScope(
|
||||
endedAtMs: milestoneAtMs,
|
||||
attributes: { eventKind: kind },
|
||||
});
|
||||
// The user-visible response (the speed budget's metric): the same
|
||||
// anchor as time to first text, to this first visible agent event.
|
||||
// Detached like TTFT, so the anchor read never delays the turn.
|
||||
trace.defer(async () => {
|
||||
const activityStart = resolveNativeTimeToFirstTokenStart({
|
||||
traceStartedAtMs: trace.traceStartedAtMs,
|
||||
preparationSpans,
|
||||
wakeRequestedAtMs: await readNativeRunWakeRequestedAtMs(input.db, input.execution.binding.runId),
|
||||
});
|
||||
await trace.record({
|
||||
name: "task.time_to_first_agent_activity",
|
||||
parentName: "task.provider_session",
|
||||
startedAtMs: activityStart.startedAtMs,
|
||||
endedAtMs: activityAt,
|
||||
attributes: { eventKind: kind, anchor: activityStart.anchor },
|
||||
});
|
||||
});
|
||||
}
|
||||
}
|
||||
if (
|
||||
|
||||
@@ -14,7 +14,7 @@ import {
|
||||
describe("speed budgets", () => {
|
||||
it("defines p50 below p95 for every adapter, metric and start", () => {
|
||||
for (const budgets of Object.values(LOCAL_SPEED_BUDGETS)) {
|
||||
for (const budget of [budgets.ttft.cold, budgets.ttft.warm, budgets.agent_boot.cold, budgets.agent_boot.warm,
|
||||
for (const budget of [budgets.time_to_first_activity.cold, budgets.time_to_first_activity.warm, budgets.agent_boot.cold, budgets.agent_boot.warm,
|
||||
budgets.restart_recovery]) {
|
||||
expect(budget.p50Ms).toBeGreaterThan(0);
|
||||
expect(budget.p50Ms).toBeLessThanOrEqual(budget.p95Ms);
|
||||
@@ -31,20 +31,20 @@ describe("speed budgets", () => {
|
||||
});
|
||||
|
||||
it("judges one run against p95 and uses the looser budget when the start kind is unknown", () => {
|
||||
const codexCold = LOCAL_SPEED_BUDGETS.codex.ttft.cold.p95Ms;
|
||||
expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "ttft", start: "cold", measuredMs: codexCold }))
|
||||
const codexCold = LOCAL_SPEED_BUDGETS.codex.time_to_first_activity.cold.p95Ms;
|
||||
expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "time_to_first_activity", start: "cold", measuredMs: codexCold }))
|
||||
.toBeNull();
|
||||
expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "ttft", start: "cold", measuredMs: codexCold + 1 }))
|
||||
.toMatchObject({ metric: "ttft", adapter: "codex", startKind: "cold", budgetP95Ms: codexCold, percentile: "p95" });
|
||||
const loose = speedBudgetFor("codex", "ttft", null);
|
||||
expect(loose.p95Ms).toBe(Math.max(codexCold, LOCAL_SPEED_BUDGETS.codex.ttft.warm.p95Ms));
|
||||
expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "ttft", start: null, measuredMs: codexCold + 1 }))
|
||||
expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "time_to_first_activity", start: "cold", measuredMs: codexCold + 1 }))
|
||||
.toMatchObject({ metric: "time_to_first_activity", adapter: "codex", startKind: "cold", budgetP95Ms: codexCold, percentile: "p95" });
|
||||
const loose = speedBudgetFor("codex", "time_to_first_activity", null);
|
||||
expect(loose.p95Ms).toBe(Math.max(codexCold, LOCAL_SPEED_BUDGETS.codex.time_to_first_activity.warm.p95Ms));
|
||||
expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "time_to_first_activity", start: null, measuredMs: codexCold + 1 }))
|
||||
.toBeNull();
|
||||
});
|
||||
|
||||
it("does not judge remote runs or adapters without a baseline", () => {
|
||||
expect(evaluateSpeedBudget({ adapter: "codex", environment: "remote", metric: "ttft", start: "cold", measuredMs: 1e9 })).toBeNull();
|
||||
expect(evaluateSpeedBudget({ adapter: null, environment: "local", metric: "ttft", start: "cold", measuredMs: 1e9 })).toBeNull();
|
||||
expect(evaluateSpeedBudget({ adapter: "codex", environment: "remote", metric: "time_to_first_activity", start: "cold", measuredMs: 1e9 })).toBeNull();
|
||||
expect(evaluateSpeedBudget({ adapter: null, environment: "local", metric: "time_to_first_activity", start: "cold", measuredMs: 1e9 })).toBeNull();
|
||||
});
|
||||
});
|
||||
|
||||
@@ -66,7 +66,7 @@ describe("speed budget checks in the native run trace", () => {
|
||||
await trace.record({ name: "runner.turn.submit", startedAtMs: 100, endedAtMs: 100 + boot });
|
||||
// A second submit in the same run is not a second boot.
|
||||
await trace.record({ name: "runner.turn.submit", startedAtMs: 100, endedAtMs: 100 + boot * 2 });
|
||||
await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: 1_000 });
|
||||
await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: 1_000 });
|
||||
await trace.finish("ok");
|
||||
|
||||
expect(breaches()).toEqual([expect.objectContaining({
|
||||
@@ -78,25 +78,25 @@ describe("speed budget checks in the native run trace", () => {
|
||||
it("writes a breach for a slow TTFT recorded by deferred diagnostics before the trace closes", async () => {
|
||||
const { trace, breaches } = traced({ adapter: "claude", environment: "local" });
|
||||
trace.setBudgetStart("warm");
|
||||
const ttft = LOCAL_SPEED_BUDGETS.claude.ttft.warm.p95Ms + 1;
|
||||
const ttft = LOCAL_SPEED_BUDGETS.claude.time_to_first_activity.warm.p95Ms + 1;
|
||||
trace.defer(async () => {
|
||||
await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: ttft });
|
||||
await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: ttft });
|
||||
});
|
||||
await trace.finish("ok");
|
||||
|
||||
expect(breaches()).toEqual([expect.objectContaining({ metric: "ttft", adapter: "claude", startKind: "warm", measuredMs: ttft })]);
|
||||
expect(breaches()).toEqual([expect.objectContaining({ metric: "time_to_first_activity", 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 budget = LOCAL_SPEED_BUDGETS.claude.time_to_first_activity.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.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: wait + budget - 1 });
|
||||
await quiet.trace.finish("ok");
|
||||
expect(quiet.breaches()).toEqual([]);
|
||||
|
||||
@@ -104,22 +104,34 @@ describe("speed budget checks in the native run trace", () => {
|
||||
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.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: wait + budget + 1 });
|
||||
await slow.trace.finish("ok");
|
||||
expect(slow.breaches()).toEqual([expect.objectContaining({ metric: "ttft", measuredMs: budget + 1, inputWaitMs: wait })]);
|
||||
expect(slow.breaches()).toEqual([expect.objectContaining({ metric: "time_to_first_activity", 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;
|
||||
const budget = LOCAL_SPEED_BUDGETS.codex.time_to_first_activity.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.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: budget + 1 });
|
||||
await trace.finish("ok");
|
||||
expect(breaches()).toEqual([expect.objectContaining({ metric: "ttft", measuredMs: budget + 1 })]);
|
||||
expect(breaches()).toEqual([expect.objectContaining({ metric: "time_to_first_activity", measuredMs: budget + 1 })]);
|
||||
expect(breaches()[0]).not.toHaveProperty("inputWaitMs");
|
||||
});
|
||||
|
||||
it("judges first visible activity, not first text, so a tool-first turn is within budget", async () => {
|
||||
const { trace, breaches } = traced({ adapter: "claude", environment: "local" });
|
||||
trace.setBudgetStart("cold");
|
||||
const budget = LOCAL_SPEED_BUDGETS.claude.time_to_first_activity.cold.p95Ms;
|
||||
await trace.record({ name: "heartbeat.queue", startedAtMs: 0, endedAtMs: 50 });
|
||||
// The agent calls a tool at once and writes its first text much later.
|
||||
await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: 5_000 });
|
||||
await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: budget * 2 });
|
||||
await trace.finish("ok");
|
||||
expect(breaches()).toEqual([]);
|
||||
});
|
||||
|
||||
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;
|
||||
@@ -135,7 +147,7 @@ describe("speed budget checks in the native run trace", () => {
|
||||
const { trace, breaches } = traced({ adapter: "codex", environment: "local", restartRecovery: true });
|
||||
await trace.record({ name: "heartbeat.queue", startedAtMs: 0, endedAtMs: 1 });
|
||||
await trace.record({ name: "runner.session.resume", startedAtMs: 1, endedAtMs: 120_000 });
|
||||
await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: 120_000 });
|
||||
await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: 120_000 });
|
||||
const at = LOCAL_SPEED_BUDGETS.codex.restart_recovery.p95Ms + 1;
|
||||
trace.checkRestartRecovery({ readyAtMs: 0, emittedAtMs: at, committedAtMs: at, disposition: "resume_dead_runner" });
|
||||
await trace.finish("ok");
|
||||
@@ -189,7 +201,7 @@ describe("speed budget checks in the native run trace", () => {
|
||||
const { trace, breaches } = traced(budget);
|
||||
await trace.record({ name: "heartbeat.queue", startedAtMs: 0, endedAtMs: 1 });
|
||||
await trace.record({ name: "runner.turn.submit", startedAtMs: 1, endedAtMs: 10_000_000 });
|
||||
await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: 10_000_000 });
|
||||
await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: 10_000_000 });
|
||||
await trace.finish("ok");
|
||||
expect(breaches()).toEqual([]);
|
||||
}
|
||||
|
||||
@@ -14,7 +14,15 @@
|
||||
*/
|
||||
|
||||
export type SpeedBudgetAdapter = "claude" | "codex" | "opencode";
|
||||
export type SpeedBudgetMetric = "ttft" | "agent_boot" | "restart_recovery";
|
||||
/**
|
||||
* `time_to_first_activity`: run creation to the first agent activity the UI
|
||||
* shows (a text delta, a tool-call start or a reasoning indicator, whichever
|
||||
* comes first; span `task.time_to_first_agent_activity`). That is when the user
|
||||
* sees the agent respond. Time to first text (`task.time_to_first_token`) stays
|
||||
* a reported metric without a budget: tool-first adapters such as Claude often
|
||||
* call tools before they write text. The budget numbers are the TTFT baseline's.
|
||||
*/
|
||||
export type SpeedBudgetMetric = "time_to_first_activity" | "agent_boot" | "restart_recovery";
|
||||
export type SpeedBudgetStart = "cold" | "warm";
|
||||
|
||||
export type SpeedBudget = { p50Ms: number; p95Ms: number };
|
||||
@@ -31,24 +39,24 @@ export const RESTART_RECOVERY_PROVIDER_EVENT_TYPES: ReadonlySet<string> = new Se
|
||||
|
||||
const s = (seconds: number) => Math.round(seconds * 1000);
|
||||
|
||||
/** TTFT and agent boot by adapter and start kind; restart recovery by adapter. */
|
||||
/** First activity and agent boot by adapter and start kind; restart recovery by adapter. */
|
||||
export const LOCAL_SPEED_BUDGETS: Readonly<Record<SpeedBudgetAdapter, {
|
||||
ttft: Record<SpeedBudgetStart, SpeedBudget>;
|
||||
time_to_first_activity: Record<SpeedBudgetStart, SpeedBudget>;
|
||||
agent_boot: Record<SpeedBudgetStart, SpeedBudget>;
|
||||
restart_recovery: SpeedBudget;
|
||||
}>> = {
|
||||
claude: {
|
||||
ttft: { cold: { p50Ms: s(16.5), p95Ms: s(30) }, warm: { p50Ms: s(9.5), p95Ms: s(28.5) } },
|
||||
time_to_first_activity: { cold: { p50Ms: s(16.5), p95Ms: s(30) }, warm: { p50Ms: s(9.5), p95Ms: s(28.5) } },
|
||||
agent_boot: { cold: { p50Ms: s(9), p95Ms: s(20.5) }, warm: { p50Ms: s(3.5), p95Ms: s(16.5) } },
|
||||
restart_recovery: { p50Ms: s(15), p95Ms: s(22.5) },
|
||||
},
|
||||
codex: {
|
||||
ttft: { cold: { p50Ms: s(6), p95Ms: s(17) }, warm: { p50Ms: s(10), p95Ms: s(28.5) } },
|
||||
time_to_first_activity: { cold: { p50Ms: s(6), p95Ms: s(17) }, warm: { p50Ms: s(10), p95Ms: s(28.5) } },
|
||||
agent_boot: { cold: { p50Ms: s(2.5), p95Ms: s(7) }, warm: { p50Ms: s(5), p95Ms: s(16.5) } },
|
||||
restart_recovery: { p50Ms: s(6.5), p95Ms: s(8) },
|
||||
},
|
||||
opencode: {
|
||||
ttft: { cold: { p50Ms: s(17.5), p95Ms: s(49) }, warm: { p50Ms: s(26.5), p95Ms: s(88) } },
|
||||
time_to_first_activity: { cold: { p50Ms: s(17.5), p95Ms: s(49) }, warm: { p50Ms: s(26.5), p95Ms: s(88) } },
|
||||
agent_boot: { cold: { p50Ms: s(12), p95Ms: s(37) }, warm: { p50Ms: s(22), p95Ms: s(65.5) } },
|
||||
restart_recovery: { p50Ms: s(25.5), p95Ms: s(38.5) },
|
||||
},
|
||||
@@ -87,7 +95,7 @@ export type SpeedBudgetBreach = {
|
||||
percentile: "p95";
|
||||
baseline: string;
|
||||
disposition?: string;
|
||||
/** TTFT only: time the input waited for its run to exist (for example a
|
||||
/** First activity 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;
|
||||
};
|
||||
|
||||
@@ -77,6 +77,33 @@ describe("ttft baseline statistics", () => {
|
||||
ttft: { n: 2, p50: 6_000, p95: 12_000 } });
|
||||
});
|
||||
|
||||
it("reports first visible activity from run creation next to first text", () => {
|
||||
const toolFirst = run("t", "warm", [
|
||||
reuse("reused"),
|
||||
span("comment.to_run_created", 0, 30_000),
|
||||
span("heartbeat.queue", 30_000, 100),
|
||||
span("task.time_to_first_agent_activity", 0, 35_000, { anchor: "comment" }),
|
||||
span("task.time_to_first_token", 0, 48_000, { anchor: "comment" }),
|
||||
], "claude");
|
||||
expect(runMetrics(toolFirst)).toMatchObject({ inputWaitMs: 30_000, firstActivityAfterRunCreatedMs: 5_000,
|
||||
ttftAfterRunCreatedMs: 18_000 });
|
||||
expect(baselineRows([toolFirst])[0]).toMatchObject({ firstActivityAfterRunCreated: { p50: 5_000 },
|
||||
ttftAfterRunCreated: { p50: 18_000 } });
|
||||
});
|
||||
|
||||
it("measures first activity from run creation even when it is anchored at an earlier wake request", () => {
|
||||
// A deferred wake accepted 30 s before the run existed; activity 5 s after run creation.
|
||||
const deferred = run("d", "cold", [
|
||||
reuse("fresh"),
|
||||
span("heartbeat.queue", 0, 100),
|
||||
span("task.time_to_first_agent_activity", -30_000, 35_000, { anchor: "wake_request" }),
|
||||
], "claude");
|
||||
expect(runMetrics(deferred).firstActivityAfterRunCreatedMs).toBe(5_000);
|
||||
const deferredText = run("e", "cold", [reuse("fresh"), span("heartbeat.queue", 0, 100),
|
||||
span("task.time_to_first_token", -30_000, 35_000, { anchor: "wake_request" })], "claude");
|
||||
expect(runMetrics(deferredText).ttftAfterRunCreatedMs).toBe(5_000);
|
||||
});
|
||||
|
||||
it("ranks pre-turn steps by p95 without cumulative wrappers", () => {
|
||||
const ranked = rankPreTurnSteps([coldRun("a"), coldRun("b", 2)]);
|
||||
expect(ranked[0]).toMatchObject({ step: "runner.process.launch", n: 2, p95: 3_000 });
|
||||
|
||||
@@ -74,12 +74,16 @@ export interface RunMetrics {
|
||||
* `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. */
|
||||
/** TTFT (first text) from run creation: reported, no budget for tool-first adapters. */
|
||||
ttftAfterRunCreatedMs: number | null;
|
||||
/** First visible agent activity (text delta, tool-call start or reasoning)
|
||||
* from run creation (`task.time_to_first_agent_activity`): what the speed
|
||||
* budget judges. */
|
||||
firstActivityAfterRunCreatedMs: 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", "comment.to_run_created", "question_response.to_run_created", "task.provider_session.measured", "task.prepare",
|
||||
const CUMULATIVE_SPANS = new Set(["task.time_to_first_token", "task.time_to_first_agent_activity", "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;
|
||||
@@ -87,6 +91,7 @@ const FIRST_SPAN = (spans: RunSpan[], name: string) => spans.find(span => span.n
|
||||
export function runMetrics(run: BaselineRun): RunMetrics {
|
||||
const spans = runSpans(run);
|
||||
const ttft = FIRST_SPAN(spans, "task.time_to_first_token");
|
||||
const activity = FIRST_SPAN(spans, "task.time_to_first_agent_activity");
|
||||
const queue = FIRST_SPAN(spans, "heartbeat.queue");
|
||||
// runner.turn.submit = session.started → turn.submitted; a resumed session has
|
||||
// runner.session.resume ending at turn.submitted instead.
|
||||
@@ -103,10 +108,19 @@ export function runMetrics(run: BaselineRun): RunMetrics {
|
||||
}
|
||||
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;
|
||||
const anchor = ttft ?? activity;
|
||||
// From run creation, as the runtime budget judges it: the start of
|
||||
// heartbeat.queue, else the end of the ingress span. Independent of the
|
||||
// span's own anchor (an earlier wake request or comment is not counted).
|
||||
const runCreatedAt = queue ? queue.startOffsetMs : ingress ? ingress.startOffsetMs + ingress.durationMs : null;
|
||||
const afterRunCreated = (span: RunSpan) => runCreatedAt === null
|
||||
? Math.max(0, span.durationMs - (inputWaitMs ?? 0))
|
||||
: Math.max(0, span.startOffsetMs + span.durationMs - runCreatedAt);
|
||||
const inputWaitMs = ingress && anchor && ingress.startOffsetMs <= anchor.startOffsetMs ? ingress.durationMs : null;
|
||||
return {
|
||||
inputWaitMs,
|
||||
ttftAfterRunCreatedMs: ttft ? Math.max(0, ttft.durationMs - (inputWaitMs ?? 0)) : null,
|
||||
firstActivityAfterRunCreatedMs: activity ? afterRunCreated(activity) : null,
|
||||
ttftAfterRunCreatedMs: ttft ? afterRunCreated(ttft) : 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,
|
||||
@@ -142,8 +156,10 @@ export function recoverySamples(runs: readonly BaselineRun[], faults: readonly B
|
||||
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. */
|
||||
/** TTFT (first text) from run creation: reported. */
|
||||
ttftAfterRunCreated: Distribution;
|
||||
/** First visible agent activity from run creation: the value the speed budget judges. */
|
||||
firstActivityAfterRunCreated: Distribution;
|
||||
anchors: Record<string, number> }
|
||||
|
||||
export function baselineRows(runs: readonly BaselineRun[]): BaselineRow[] {
|
||||
@@ -164,7 +180,8 @@ export function baselineRows(runs: readonly BaselineRun[]): BaselineRow[] {
|
||||
ttft: distribution(group.metrics.flatMap(metric => metric.ttftMs === null ? [] : [metric.ttftMs])),
|
||||
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])) };
|
||||
ttftAfterRunCreated: distribution(group.metrics.flatMap(metric => metric.ttftAfterRunCreatedMs === null ? [] : [metric.ttftAfterRunCreatedMs])),
|
||||
firstActivityAfterRunCreated: distribution(group.metrics.flatMap(metric => metric.firstActivityAfterRunCreatedMs === null ? [] : [metric.firstActivityAfterRunCreatedMs])) };
|
||||
});
|
||||
}
|
||||
|
||||
|
||||
@@ -190,8 +190,8 @@ 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 | Wait behind live turn p50 / p95 (n) | TTFT from run created p50 / p95 | Boot p50 | Boot p95 | TTFT anchors |", "|---|---|---|---|---|---|---|---|---|---|---|"];
|
||||
const rowLine = (row: ReturnType<typeof baselineRows>[number]) => `| ${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(", ") || "—"} |`;
|
||||
const lines = ["| Adapter | Env | Start | n | TTFT p50 | TTFT p95 | Wait behind live turn p50 / p95 (n) | First activity from run created p50 / p95 (budget) | TTFT from run created p50 / p95 | Boot p50 | Boot p95 | TTFT anchors |", "|---|---|---|---|---|---|---|---|---|---|---|---|"];
|
||||
const rowLine = (row: ReturnType<typeof baselineRows>[number]) => `| ${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.firstActivityAfterRunCreated.p50)} / ${ms(row.firstActivityAfterRunCreated.p95)} | ${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(", ") || "—"} |`;
|
||||
for (const row of baselineRows(runs)) lines.push(rowLine(row));
|
||||
// New agents wait for harness verification before their run is created:
|
||||
// their own rows, so that wait never blends into ordinary cold starts.
|
||||
|
||||
Reference in new issue
Block a user