mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-12 14:19:00 +01:00
feat(observability): anchor native time to first token at the accepted wake (#19838)
## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - When someone messages an agent, the reply must start fast. The durable ownership plan (#19831) makes time to first token (TTFT) a hard invariant. > - Phase 0 of that plan records a TTFT baseline per adapter and environment, measured from the moment the message or wake is accepted. > - Today `task.time_to_first_token` starts at the wake comment, the answered question, or the run row's creation. A wake request that was accepted earlier (deferred, coalesced or retried) is not part of the measurement, and the span does not say which start it used. > - This pull request moves the start back to the earliest accepted input and names it on the span. > - The benefit is that the baseline and later budgets measure what the user waits for, with no new work before `turn.start`. ## Linked Issues or Issue Description Refs #19831 **What is the problem?** `task.time_to_first_token` does not include the time between an accepted wake request and the creation of its run row. It also does not record which input it started from. **What is the expected outcome?** The span starts at the earliest accepted input and carries an `anchor` attribute: `comment`, `question_response`, `wake_request` or `run_created`. **Why does it matter?** Phase 0 of the durable ownership plan sets TTFT budgets from this baseline. A start that skips queue time hides the latency that deferred wakes add. ## What Changed - `resolveNativeTimeToFirstTokenStart` (pure) in `native-run-trace.ts` picks the start and the anchor. `anchor` joins the closed span-attribute allowlist. - `readNativeRunWakeRequestedAtMs` reads `agent_wakeup_requests.requested_at` for the run. It never throws. - `native-session-executor.ts` calls it only after the first deliverable text, so it adds no wait before `turn.start`. The span now ends at the text commit time, not after the trace write. - Updated `doc/run-log-events.md` and `doc/observability.md`. ## Verification - `cd server && npx vitest run src/services/native-runtime/native-run-trace.test.ts src/services/native-runtime/native-run-wake-anchor.test.ts` (26 pass). - `cd server && npx vitest run src/services/native-runtime/native-session-executor.test.ts -t first` (41 pass). The existing TTFT test now asserts the anchor for each ingress. ## Risks - Low risk. This changes only the run-log and OTLP span. It is not Telemetry (AGENTS.md §5.7), and it does not change runtime behavior. - One indexed primary-key read per native dispatch, after the first text. A read failure drops the anchor and keeps the old start. - TTFT values can grow for deferred wakes. That is the intended correction. `startOffsetMs` can be negative when the wake request comes before the trace start. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), via Claude Code with tool use and code execution. ## 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 <noreply@anthropic.com>
This commit is contained in:
1 parent
84908d176b
commit
e2d490c61b
9 files changed
+426
-15
No files matched your search
@@ -139,6 +139,9 @@ vi.mock("../usage-receipts.js", async (importOriginal) => ({
|
||||
createRunUsageRecorder: usageRecorder.create,
|
||||
}));
|
||||
|
||||
const wakeAnchor = vi.hoisted(() => ({ read: vi.fn(async (_db: unknown, _runId: string): Promise<number | null> => null) }));
|
||||
vi.mock("./native-run-wake-anchor.js", () => ({ readNativeRunWakeRequestedAtMs: wakeAnchor.read }));
|
||||
|
||||
vi.mock("./native-usage-delivery.js", () => ({
|
||||
createNativeUsageDelivery: vi.fn(async () => ({ capture: async () => undefined })),
|
||||
}));
|
||||
@@ -8826,7 +8829,9 @@ describe("native resumed preparation timing", () => {
|
||||
const ttft = events.filter((event) => event.payload?.span === "task.time_to_first_token");
|
||||
expect(ttft).toHaveLength(1);
|
||||
expect(ttft[0]?.payload).toMatchObject({ parentSpan: "task.provider_session", startOffsetMs: 0,
|
||||
durationMs: ingress === "native_dispatch" ? 500 : 4_500, eventKind: "agentMessage", outcome: "ok" });
|
||||
durationMs: ingress === "native_dispatch" ? 500 : 4_500, eventKind: "agentMessage", outcome: "ok",
|
||||
anchor: ingress === "comment.to_run_created" ? "comment"
|
||||
: ingress === "question_response.to_run_created" ? "question_response" : "run_created" });
|
||||
expect(events.find((event) => event.payload?.span === "provider.time_to_first_agent_event")?.payload)
|
||||
.toMatchObject({ parentSpan: "agent.turn", eventKind: "agentMessage" });
|
||||
expect(JSON.stringify(ttft)).not.toContain("first text");
|
||||
@@ -8834,6 +8839,41 @@ describe("native resumed preparation timing", () => {
|
||||
},
|
||||
);
|
||||
|
||||
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[] = [];
|
||||
const clock = vi.spyOn(Date, "now").mockReturnValue(startedAtMs + 4_000);
|
||||
let answerRead!: (value: number) => void;
|
||||
wakeAnchor.read.mockImplementationOnce(() => new Promise<number>((resolve) => { answerRead = resolve; }));
|
||||
const event = (eventType: string, payload: Record<string, unknown>) => ({
|
||||
eventType, payload, itemId: "message", emittedAt: new Date(startedAtMs + 2_000).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 + 4_500);
|
||||
await accountingEvents.committed!(event("item.delta", { kind: "agentMessage", text: "first text" }));
|
||||
// The anchor read is still pending; later events are not held behind it.
|
||||
await accountingEvents.committed!(event("item.delta", { kind: "agentMessage", text: "later text" }));
|
||||
expect(events.some((candidate) => candidate.payload?.span === "task.time_to_first_token")).toBe(false);
|
||||
answerRead(startedAtMs - 2_000);
|
||||
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); },
|
||||
});
|
||||
} finally { clock.mockRestore(); }
|
||||
expect(wakeAnchor.read).toHaveBeenCalledWith(expect.anything(), execution.binding.runId);
|
||||
const ttft = events.filter((event) => event.payload?.span === "task.time_to_first_token");
|
||||
expect(ttft).toHaveLength(1);
|
||||
expect(ttft[0]?.payload).toMatchObject({ parentSpan: "task.provider_session", startOffsetMs: -2_000,
|
||||
durationMs: 6_500, anchor: "wake_request", eventKind: "agentMessage" });
|
||||
});
|
||||
|
||||
it.each([
|
||||
["item.delta", { kind: "reasoning", text: "thinking" }, "reasoning"],
|
||||
["item.completed", { kind: "reasoning", text: "thought" }, "reasoning"],
|
||||
|
||||
Reference in new issue
Block a user