Add per-round performance instrumentation

src/host/conversation.ts

@@ -6,7 +6,7 @@ import { shouldIgnoreFile } from '../config.js';
 import type { DiffStats } from '../git/commands.js';
 import type { ResolvedRange } from '../git/resolver.js';
 import type { LLMMessage, LLMProvider, ToolDefinition, ToolUseBlock } from '../llm/provider.js';
-import { debug, timer } from '../logger.js';
+import { debug, logPerformanceReport, timer } from '../logger.js';
 import { getInitialPrompt, getSystemPrompt } from '../prompts/system.js';
 import { getFocusInstructions } from '../prompts/templates.js';
 import type { ReviewResult } from '../reviewer.js';
@@ -61,6 +61,30 @@ function describeToolCalls(blocks: ToolUseBlock[]): string {
   return `${descriptions[0]} ${chalk.dim(`(+${descriptions.length - 1} more)`)}`;
 }
 
+/**
+ * Estimate the total character count of the messages array.
+ * Used for logging context growth between rounds.
+ */
+function estimateMessageChars(messages: LLMMessage[]): number {
+  let total = 0;
+  for (const msg of messages) {
+    if (typeof msg.content === 'string') {
+      total += msg.content.length;
+    } else if (Array.isArray(msg.content)) {
+      for (const block of msg.content) {
+        if (block.type === 'text') {
+          total += (block as { text: string }).text.length;
+        } else if (block.type === 'tool_result') {
+          total += ((block as { content?: string }).content ?? '').length;
+        } else if (block.type === 'tool_use') {
+          total += JSON.stringify((block as { input: unknown }).input).length;
+        }
+      }
+    }
+  }
+  return total;
+}
+
 /**
  * Maximum number of tool-call rounds before forcing the LLM to produce a final answer.
  * After this many rounds, we stop sending tools so the model must respond with text.
@@ -284,14 +308,22 @@ Analyzing ${stats.filesChanged} files. Use the available tools to understand the
     }));
 
     // Build initial messages
+    const initialPrompt = this.buildInitialPrompt(diff, stats, fileContents);
     const messages: LLMMessage[] = [
       {
         role: 'user',
-        content: this.buildInitialPrompt(diff, stats, fileContents),
+        content: initialPrompt,
       },
     ];
 
+    const initialPromptChars = initialPrompt.length;
+    debug(
+      'perf',
+      `Initial prompt: ${initialPromptChars.toLocaleString()} chars (~${Math.ceil(initialPromptChars / CHARS_PER_TOKEN).toLocaleString()} tokens)`,
+    );
+
     // Run conversation loop
+    const endReviewLoop = timer('perf', 'conversation loop (all turns)');
     let turnNumber = 0;
 
     if (spinner) {
@@ -306,9 +338,17 @@ Analyzing ${stats.filesChanged} files. Use the available tools to understand the
       tools,
       messages,
     });
-    endFirstCall();
+    const firstCallMs = endFirstCall();
 
     tracker.addUsage(response.usage.inputTokens, response.usage.outputTokens);
+    tracker.addTurn({
+      turn: turnNumber,
+      inputTokens: response.usage.inputTokens,
+      outputTokens: response.usage.outputTokens,
+      apiTimeMs: firstCallMs,
+      toolTimeMs: 0,
+      toolResultChars: 0,
+    });
     debug(
       'llm',
       `Turn ${turnNumber}: stopReason=${response.stopReason}, tokens=${response.usage.inputTokens}in/${response.usage.outputTokens}out`,
@@ -352,10 +392,24 @@ Analyzing ${stats.filesChanged} files. Use the available tools to understand the
           };
         }),
       );
-      endToolCalls();
+      const toolCallMs = endToolCalls();
+
+      // Measure tool result sizes added to context
+      const toolResultChars = toolResults.reduce((sum, r) => sum + (r.content?.length ?? 0), 0);
+      debug(
+        'perf',
+        `Tool round ${toolRounds}: ${toolResults.length} result(s), ${toolResultChars.toLocaleString()} chars (~${Math.ceil(toolResultChars / CHARS_PER_TOKEN).toLocaleString()} tokens) added to context`,
+      );
 
       messages.push({ role: 'user', content: toolResults });
 
+      // Estimate total message payload before next API call
+      const messagePayloadChars = estimateMessageChars(messages);
+      debug(
+        'perf',
+        `Message payload before turn ${turnNumber + 1}: ~${Math.ceil(messagePayloadChars / CHARS_PER_TOKEN).toLocaleString()} tokens (${messagePayloadChars.toLocaleString()} chars)`,
+      );
+
       // Determine whether to allow more tool calls or force a final answer
       const atLimit = toolRounds >= MAX_TOOL_ROUNDS;
 
@@ -378,21 +432,37 @@ Analyzing ${stats.filesChanged} files. Use the available tools to understand the
         ...(atLimit ? {} : { tools }),
         messages,
       });
-      endApiCall();
+      const apiCallMs = endApiCall();
 
       tracker.addUsage(response.usage.inputTokens, response.usage.outputTokens);
+      tracker.addTurn({
+        turn: turnNumber,
+        inputTokens: response.usage.inputTokens,
+        outputTokens: response.usage.outputTokens,
+        apiTimeMs: apiCallMs,
+        toolTimeMs: toolCallMs,
+        toolResultChars,
+      });
       debug(
         'llm',
         `Turn ${turnNumber}: stopReason=${response.stopReason}, tokens=${response.usage.inputTokens}in/${response.usage.outputTokens}out`,
       );
     }
 
+    const totalReviewMs = endReviewLoop();
+
     if (spinner) {
       spinner.text = 'Parsing review output...';
     }
 
     debug('llm', `Conversation complete after ${turnNumber} turn(s)`);
 
+    // Emit per-round performance report
+    logPerformanceReport(tracker.getTurns(), {
+      initialPromptChars,
+      totalReviewMs,
+    });
+
     // Parse final response
     const textContent = response.content.find((b) => b.type === 'text');
     if (!textContent || textContent.type !== 'text') {

src/logger.ts

@@ -77,3 +77,65 @@ export function logTimingSummary(timings: Record<string, number>): void {
   console.error(`[perf]   Total: ${total.toFixed(0)}ms`);
   console.error('[perf] ────────────────────');
 }
+
+interface TurnReportEntry {
+  turn: number;
+  inputTokens: number;
+  outputTokens: number;
+  apiTimeMs: number;
+  toolTimeMs: number;
+  toolResultChars: number;
+}
+
+/**
+ * Log a per-round performance report at the end of a review.
+ *
+ * Shows API call time vs tool execution time per round, input token growth,
+ * and tool result sizes — everything needed to identify whether context
+ * growth is the bottleneck.
+ */
+export function logPerformanceReport(
+  turns: TurnReportEntry[],
+  extras: { initialPromptChars: number; totalReviewMs: number },
+): void {
+  if (!isEnabled()) return;
+
+  const fmt = (n: number) => n.toLocaleString('en-US');
+  const estTokens = (chars: number) => Math.ceil(chars / 4);
+
+  console.error('\n[perf] ═══ Performance Report ═══');
+  console.error(
+    `[perf]   Initial prompt: ~${fmt(estTokens(extras.initialPromptChars))} tokens (${fmt(extras.initialPromptChars)} chars)`,
+  );
+
+  let prevInput = 0;
+  let totalApiMs = 0;
+  let totalToolMs = 0;
+
+  for (const t of turns) {
+    const inputGrowth = prevInput > 0 ? ` (+${fmt(t.inputTokens - prevInput)})` : '';
+    const toolInfo =
+      t.toolTimeMs > 0
+        ? ` | Tools=${t.toolTimeMs.toFixed(0)}ms (${fmt(t.toolResultChars)} chars added)`
+        : '';
+    console.error(
+      `[perf]   Turn ${t.turn}: API=${t.apiTimeMs.toFixed(0)}ms | In=${fmt(t.inputTokens)}${inputGrowth} | Out=${fmt(t.outputTokens)}${toolInfo}`,
+    );
+    prevInput = t.inputTokens;
+    totalApiMs += t.apiTimeMs;
+    totalToolMs += t.toolTimeMs;
+  }
+
+  console.error('[perf]   ───');
+  console.error(
+    `[perf]   Totals: API=${totalApiMs.toFixed(0)}ms | Tools=${totalToolMs.toFixed(0)}ms | Wall=${extras.totalReviewMs.toFixed(0)}ms`,
+  );
+  const apiPct =
+    extras.totalReviewMs > 0 ? ((totalApiMs / extras.totalReviewMs) * 100).toFixed(0) : '0';
+  const toolPct =
+    extras.totalReviewMs > 0 ? ((totalToolMs / extras.totalReviewMs) * 100).toFixed(0) : '0';
+  console.error(
+    `[perf]   Breakdown: API=${apiPct}% | Tools=${toolPct}% | Overhead=${(100 - Number(apiPct) - Number(toolPct)).toFixed(0)}%`,
+  );
+  console.error('[perf] ═════════════════════════════');
+}

src/usage.ts

@@ -4,6 +4,15 @@ interface TokenUsage {
   estimatedCost: number;
 }
 
+export interface TurnRecord {
+  turn: number;
+  inputTokens: number;
+  outputTokens: number;
+  apiTimeMs: number;
+  toolTimeMs: number;
+  toolResultChars: number;
+}
+
 interface ModelPricing {
   inputPerMTok: number;
   outputPerMTok: number;
@@ -23,6 +32,8 @@ const DEFAULT_PRICING: ModelPricing = { inputPerMTok: 1, outputPerMTok: 5 };
 
 export interface UsageTracker {
   addUsage(inputTokens: number, outputTokens: number): void;
+  addTurn(record: TurnRecord): void;
+  getTurns(): TurnRecord[];
   getTotal(): TokenUsage;
   formatUsage(): string;
 }
@@ -31,6 +42,7 @@ export function createUsageTracker(model: string): UsageTracker {
   const pricing = MODEL_PRICING[model] ?? DEFAULT_PRICING;
   let totalInput = 0;
   let totalOutput = 0;
+  const turns: TurnRecord[] = [];
 
   function calculateCost(inputTokens: number, outputTokens: number): number {
     const inputCost = (inputTokens / 1_000_000) * pricing.inputPerMTok;
@@ -44,6 +56,14 @@ export function createUsageTracker(model: string): UsageTracker {
       totalOutput += outputTokens;
     },
 
+    addTurn(record: TurnRecord): void {
+      turns.push(record);
+    },
+
+    getTurns(): TurnRecord[] {
+      return [...turns];
+    },
+
     getTotal(): TokenUsage {
       return {
         inputTokens: totalInput,

tests/host/conversation.test.ts

@@ -4,6 +4,8 @@ import type { LLMProvider, LLMRequest, LLMResponse } from '../../src/llm/provide
 vi.mock('../../src/usage.js', () => ({
   createUsageTracker: () => ({
     addUsage: vi.fn(),
+    addTurn: vi.fn(),
+    getTurns: () => [],
     getTotal: () => ({ inputTokens: 100, outputTokens: 50, estimatedCost: 0.001 }),
     formatUsage: () => '100 in / 50 out',
   }),
@@ -12,6 +14,7 @@ vi.mock('../../src/usage.js', () => ({
 vi.mock('../../src/logger.js', () => ({
   debug: vi.fn(),
   timer: vi.fn(() => () => 0),
+  logPerformanceReport: vi.fn(),
 }));
 
 import { ConversationManager, truncateDiff } from '../../src/host/conversation.js';