From 906c9dce4307b1b95d56d08bfbe37d529ca321ec Mon Sep 17 00:00:00 2001 From: kemalelmizan Date: Sat, 17 Oct 2026 10:13:23 +0700 Subject: [PATCH] feat(steps): report what the planning pass costs (#73) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The planning pass asks the run's own model for a plan before step 1 and every `n` steps after it — but that call happens **outside** the loop. Adaptive MCP's observation path is about tool executions, so nothing saw it: no telemetry, no `/cost`, no `costSummary()`, no decoding report. With `--plan-interval 1` on an 8-step run, half the model calls were invisible, so the reported cost could understate the run by roughly half — on exactly the flag a budget-conscious user turns on. The host half is a report; the library half is a decision (#73): - `PlanningPassOptions.onCall` fires for **every** planning call — including one that failed and one whose answer was unusable, because both were paid for. It reports the step, the latency, the backend's `usage` (when it has one) and whether the call worked. - `PlanUsage` accumulates those into the run summary: a run with `--plan-interval` now ends `stop=completed steps=4 plans=2 plan_tokens=1234 plan_ms=4100`. A run without the flag prints exactly what it printed before (`""` when nothing was planned), so nothing else changes. - `plan_tokens` is **omitted** rather than printed as `0` when no backend reports usage: `plan_tokens=0` would read as "planning is free", which is not what happened. - The REPL gets the same number where a REPL user can see it: `/steps` ends with a `planning: plans=…` footer next to the history it describes. The issue's third acceptance point is respected: no new protocol concept. A planning call is a *host* model call, and the place to account for it is the host. Verified end to end: the `--plan-interval 1` e2e run now asserts `plans=2` in its summary. Unit tests cover the hook (success, failure, unusable answer, not-due), the totals, and the omission of `plan_tokens`. `pnpm build`, `pnpm typecheck`, `pnpm lint` and `pnpm test:coverage` are green (328 passed / 5 skipped; coverage 90.3 / 84.1 / 89.3 / 90.3). Pre-existing prettier drift in `src/steps.ts` and `src/cli.e2e.test.ts` is left alone (see #49); the lines added here follow prettier's output. --- AGENTS.md | 6 ++- README.md | 7 +++- docs/architecture.md | 6 ++- src/cli.e2e.test.ts | 3 ++ src/cli.ts | 22 ++++++++--- src/steps.test.ts | 93 ++++++++++++++++++++++++++++++++++++++++++-- src/steps.ts | 69 +++++++++++++++++++++++++++++++- 7 files changed, 193 insertions(+), 13 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 32e4c1b..7dca671 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -195,7 +195,11 @@ previous plan) rather than from the conversation, the plan is stored as a plan is reported (`warning: planning pass skipped (…)`) and the step proceeds unplanned; a delegated child never plans. The loop seam is `steer` (`RunAgentOptions.steer`, the pre-step mirror of `review`), and `/steps` renders -the merged history. +the merged history. A planning call is the run's **own** model call made _outside_ +the loop, so the Adaptive MCP observation path never sees it — the CLI's run +summary is where it is accounted for (`plans=… plan_tokens=… plan_ms=…`, via +`PlanningPassOptions.onCall` → `PlanUsage`), with a `planning:` line on `/steps` +for the REPL (#73). `AgentRuntime` is the bridge into Adaptive MCP. It wires `AdaptiveRuntime` (telemetry → store → evaluation → derived view), `ThinClient` (approval gate + diff --git a/README.md b/README.md index 7f4f877..2f76c30 100644 --- a/README.md +++ b/README.md @@ -140,7 +140,12 @@ history — tasks, actions, plans), `/metadata`, `/cost`, reported and the step proceeds unplanned, so planning never fails a run. Because the history is typed, one read (`store.getSteps`) returns tasks, actions and plans in order, and `/steps` renders exactly that. A delegated child never plans: the - pass reads the leader's session. + pass reads the leader's session. Because a planning call is the run's own model + call and happens **outside** the loop, nothing in the recorded telemetry sees it; + the run summary is where its cost is reported instead — + `stop=completed steps=4 plans=2 plan_tokens=1234 plan_ms=4100` (`plan_tokens` is + omitted when no backend reports usage), and `/steps` ends with a + `planning: plans=…` footer. - **Cost.** Priced models record their token cost per tool call; `/cost` shows the recorded totals. - **Decoding telemetry.** The decoding applied per step is recorded on each tool diff --git a/docs/architecture.md b/docs/architecture.md index 4ca0287..7774a20 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -91,7 +91,11 @@ pass reads `store.getSteps(session)` rather than the conversation, so a plan survives a restart and costs a bounded prompt however long the run got, and a pass that cannot plan (the model errors, or answers with nothing usable) is reported and skipped — planning never fails a run. A delegated child never plans: the pass -reads the leader's session, and a child is not the leader. +reads the leader's session, and a child is not the leader. Because that call is the +run's own model call made **outside** the loop, the recorded telemetry never sees +it; `PlanningPassOptions.onCall` reports each one and the CLI aggregates it into the +run summary (`plans=… plan_tokens=… plan_ms=…`), so planning is visible rather than +free-looking (#73). The runtime's two supporting hooks are `queueMessage`/`drainQueuedMessages` (how a background child reports back without the parent polling) and the `store` option (how a child shares the parent's memory; a runtime handed a store does not close diff --git a/src/cli.e2e.test.ts b/src/cli.e2e.test.ts index 33a5a0f..e98078d 100644 --- a/src/cli.e2e.test.ts +++ b/src/cli.e2e.test.ts @@ -316,6 +316,9 @@ describe("cli, end to end and offline", () => { expect(run.stdout).toContain("stop=completed"); // The plan reached the model as a turn it could act on. expect(run.stdout).toContain("Plan (asked before step 1"); + // The planning calls happen outside the loop, so the run summary is the one + // place their cost is visible (#73). + expect(run.stdout).toContain("plans=2"); const planningRequests = model.requests.filter((request) => request.messages.some( diff --git a/src/cli.ts b/src/cli.ts index 4c29417..ab8d661 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -48,7 +48,7 @@ import { } from "./skills.js"; import { tasksPrompt, tasksToolset } from "./tasks.js"; import { modePrompt, modeTools, tasksStopGuard } from "./modes.js"; -import { PlanningPass, formatSteps } from "./steps.js"; +import { PlanningPass, PlanUsage, formatSteps } from "./steps.js"; import { renderOneShot, stringify } from "./render.js"; import type { ChatMessage, ChatModel, ToolExecutionResult, ToolSpec } from "./types.js"; @@ -368,12 +368,18 @@ async function main(): Promise { // built here, next to the store it uses (the tools read it lazily, and so // does this). It never fails a run: a pass that cannot plan is reported and // the step proceeds unplanned. + // + // Its model calls happen outside the loop, so the runtime's cost/telemetry + // never sees them; `planUsage` is where they are counted, and the run summary + // prints them (#73). + const planUsage = new PlanUsage(); const planner = args.planInterval ? new PlanningPass({ model: defaultModel, session: sessionId, store: () => activeStore, interval: args.planInterval, + onCall: (call) => planUsage.record(call), onError: (error) => { const detail = error instanceof Error ? error.message : String(error); console.error(`warning: planning pass skipped (${detail})`); @@ -575,7 +581,7 @@ async function main(): Promise { onEvent: (event) => renderOneShot(event, args.verbose), }); console.log(` -[agent] stop=${result.stopReason} steps=${result.steps}`); +[agent] stop=${result.stopReason} steps=${result.steps}${planUsage.summary()}`); if (result.stopReason === "suspended") reportPaused(runtime, result.messages); return; } @@ -601,8 +607,14 @@ async function main(): Promise { : undefined, metadata: () => runtime.toolsMetadata(), graph: () => runtime.graphView(), - // The typed history the planning pass reads and writes (steps.ts). - steps: () => formatSteps(activeStore?.getSteps?.(sessionId) ?? []), + // The typed history the planning pass reads and writes (steps.ts). The + // footer is what the planning calls cost: they are the run's own model + // calls, so nothing else in the session reports them (#73). + steps: () => { + const history = formatSteps(activeStore?.getSteps?.(sessionId) ?? []); + const usage = planUsage.summary(); + return usage ? `${history}\nplanning:${usage.trim()}` : history; + }, models: () => catalog.describe(), decodingFor: (tool) => { const recommendation = runtime.suggestDecoding(tool, runConfig.capabilities, { @@ -635,7 +647,7 @@ async function main(): Promise { }, }); - console.log(`\n[agent] stop=${result.stopReason} steps=${result.steps}`); + console.log(`\n[agent] stop=${result.stopReason} steps=${result.steps}${planUsage.summary()}`); if (result.stopReason === "suspended") reportPaused(runtime, result.messages); if (denials > 0) { console.log( diff --git a/src/steps.test.ts b/src/steps.test.ts index f3e79c7..4587b29 100644 --- a/src/steps.test.ts +++ b/src/steps.test.ts @@ -3,6 +3,7 @@ import { MemoryStore } from "@adaptivemcp/memory"; import type { Task } from "@adaptivemcp/spec"; import { PlanningPass, + PlanUsage, actionStep, actionSummary, formatSteps, @@ -12,9 +13,10 @@ import { planReasoning, planningMessages, recordedLines, + type PlanCall, } from "./steps.js"; import { AgentRuntime } from "./runtime.js"; -import type { ChatMessage, ChatModel, ChatStep, ToolSpec } from "./types.js"; +import type { ChatMessage, ChatModel, ChatStep, ChatUsage, ToolSpec } from "./types.js"; function newStore(): MemoryStore { return new MemoryStore({ path: ":memory:" }); @@ -25,12 +27,15 @@ class AnsweringModel implements ChatModel { readonly name = "answering"; readonly calls: ChatMessage[][] = []; - constructor(private readonly answer: string | Error = "ok") {} + constructor( + private readonly answer: string | Error = "ok", + private readonly usage?: ChatUsage, + ) {} async step(messages: ChatMessage[]): Promise { this.calls.push(messages); if (this.answer instanceof Error) throw this.answer; - return { text: this.answer, toolCalls: [], finishReason: "stop" }; + return { text: this.answer, toolCalls: [], finishReason: "stop", usage: this.usage }; } } @@ -154,7 +159,8 @@ describe("reading a session's history back", () => { ).toEqual(["- task t2 [completed] audit (reviewer) → clean"]); }); - it("reads only the tail of a long history", () => { const records = Array.from({ length: 60 }, (_, index) => ({ + it("reads only the tail of a long history", () => { + const records = Array.from({ length: 60 }, (_, index) => ({ id: `act-${index}`, sessionId: "s1", kind: "action" as const, @@ -434,6 +440,85 @@ describe("the planning pass", () => { expect(store.getSteps("s1")).toEqual([]); store.close(); }); + + it("reports every planning call, so its cost is not invisible", async () => { + // The planning call happens outside the loop, so the runtime's telemetry and + // cost never see it: this hook is the only report a host gets (#73). + const store = newStore(); + const calls: PlanCall[] = []; + const pass = new PlanningPass({ + model: new AnsweringModel('{"steps":["read it"]}', { inputTokens: 30, outputTokens: 7 }), + store: () => store, + session: "s1", + interval: 1, + onCall: (call) => calls.push(call), + }); + + await pass.steer({ step: 0, messages: goal }); + + expect(calls).toHaveLength(1); + expect(calls[0]).toMatchObject({ + step: 0, + ok: true, + usage: { inputTokens: 30, outputTokens: 7 }, + }); + expect(calls[0]?.durationMs).toBeGreaterThanOrEqual(0); + store.close(); + }); + + it("reports a failed call too, and an unusable answer, because both were paid for", async () => { + const store = newStore(); + const calls: PlanCall[] = []; + const options = { + store: () => store, + session: "s1", + interval: 1, + onCall: (call: PlanCall) => calls.push(call), + }; + + await new PlanningPass({ ...options, model: new AnsweringModel(new Error("down")) }).steer({ + step: 0, + messages: goal, + }); + // The model answered; the plan was unusable. Tokens still spent. + await new PlanningPass({ ...options, model: new AnsweringModel(" ") }).steer({ + step: 1, + messages: goal, + }); + // Not due, so nothing was called and nothing is reported. + await new PlanningPass({ ...options, interval: 5, model: new AnsweringModel("x") }).steer({ + step: 2, + messages: goal, + }); + + expect(calls.map((call) => call.ok)).toEqual([false, true]); + expect(store.getSteps("s1", { kind: "plan" })).toEqual([]); + store.close(); + }); + + it("summarises planning for a run, and says nothing when there was none", () => { + const usage = new PlanUsage(); + // A run without --plan-interval prints exactly what it printed before. + expect(usage.summary()).toBe(""); + + usage.record({ + step: 0, + durationMs: 40, + ok: true, + usage: { inputTokens: 10, outputTokens: 5 }, + }); + usage.record({ step: 3, durationMs: 10, ok: false }); + // Tokens are reported once any backend reports them, and the failed call + // contributes its latency but no tokens. + expect(usage.summary()).toBe(" plans=2 plan_tokens=15 plan_ms=50"); + }); + + it("omits tokens rather than reporting zero when no backend reports usage", () => { + const usage = new PlanUsage(); + usage.record({ step: 0, durationMs: 5, ok: true }); + // `plan_tokens=0` would read as "planning is free", which is not what happened. + expect(usage.summary()).toBe(" plans=1 plan_ms=5"); + }); }); describe("the runtime records actions", () => { diff --git a/src/steps.ts b/src/steps.ts index d060129..76e1279 100644 --- a/src/steps.ts +++ b/src/steps.ts @@ -24,7 +24,7 @@ */ import { randomUUID } from "node:crypto"; import type { ActionStep, PlanStep, StepRecord, Store, Task } from "@adaptivemcp/spec"; -import type { ChatMessage, ChatModel, ToolExecutionResult } from "./types.js"; +import type { ChatMessage, ChatModel, ChatUsage, ToolExecutionResult } from "./types.js"; /** How much of a tool's error message a step keeps. Enough to act on, not a dump. */ const MAX_ERROR_CHARS = 200; @@ -255,6 +255,59 @@ export interface PlanningPassOptions { interval: number; /** A pass that produced no plan: reported, never fatal. */ onError?: (error: unknown) => void; + /** Every planning call, including one that failed — so a host can account for it. */ + onCall?: (call: PlanCall) => void; +} + +/** + * One planning model call. + * + * A planning call is the run's *own* model call outside the loop, so nothing in + * the Adaptive MCP observation path sees it: telemetry is about tool executions. + * Reporting it here is what lets a host put it in front of a user (#73). + */ +export interface PlanCall { + /** The loop step the pass ran for. */ + step: number; + durationMs: number; + /** The backend's token usage, when it reports one. */ + usage?: ChatUsage; + /** False when the call itself failed; the step then proceeded unplanned. */ + ok: boolean; +} + +/** + * What a run's planning calls cost, for a run summary. + * + * Deliberately small: a count, tokens and latency, and nothing at all when the run + * never planned — so `--plan-interval` is the only thing that changes what a + * summary says. + */ +export class PlanUsage { + private calls = 0; + private durationMs = 0; + private tokens: number | undefined; + + record(call: PlanCall): void { + this.calls += 1; + this.durationMs += call.durationMs; + if (call.usage) { + this.tokens = + (this.tokens ?? 0) + (call.usage.inputTokens ?? 0) + (call.usage.outputTokens ?? 0); + } + } + + /** + * The suffix for a run summary, or `""` when nothing was planned — a run + * without `--plan-interval` prints exactly what it printed before. Tokens are + * omitted rather than shown as 0 when no backend reported any, which a count of + * `0` would misrepresent as "planning is free". + */ + summary(): string { + if (this.calls === 0) return ""; + const tokens = this.tokens === undefined ? "" : ` plan_tokens=${this.tokens}`; + return ` plans=${this.calls}${tokens} plan_ms=${this.durationMs}`; + } } /** @@ -283,17 +336,31 @@ export class PlanningPass { if (!store) return undefined; const records = store.getSteps?.(this.options.session) ?? []; + const started = Date.now(); let answer: string; + let usage: ChatUsage | undefined; try { const step = await this.options.model.step( planningMessages(goalOf(context.messages), recordedLines(records)), [], ); answer = step.text ?? ""; + usage = step.usage; } catch (error) { + // Report the call before the error: it was made, so it was paid for. + this.options.onCall?.({ step: context.step, durationMs: Date.now() - started, ok: false }); this.options.onError?.(error); return undefined; } + // + // Reported before the plan is parsed, for the same reason: the tokens were + // spent whether or not the answer was usable. + this.options.onCall?.({ + step: context.step, + durationMs: Date.now() - started, + usage, + ok: true, + }); const parsed = parsePlan(answer); if (parsed.steps.length === 0) {