feat(cli): profile ingest runs and split model vs tool time (#249)

* feat(cli): profile ingest runs to find where wall-clock time goes

Add opt-in profiling for `ktx ingest`. Each timed phase, work unit, and
agent loop now records durationMs / step count / token usage in the
trace, and a post-run aggregator rolls them up into a "where did the
time go" report printed to stderr.

Enable per run with KTX_PROFILE_INGEST (1/true -> human table, json ->
raw structured profile) or persistently via `ingest.profile` in
ktx.yaml. The json form emits raw milliseconds, token counts, and a
summary.headline one-line diagnosis so coding agents can parse it
directly; json wins when both env and config request profiling.

- runtime-port: RunLoopMetrics (totalMs, usage, stepCount,
  stepBoundariesMs) plus onMetrics callbacks on text/object generation
- ai-sdk + claude-code runtimes: capture per-loop timing and token usage
- work-unit-executor and stages 3/4: thread metrics into trace events
- ingest-bundle.runner: time worktree / triage / clustering / index /
  reconcile / squash phases and emit the profile in a finally block
  (best-effort; never affects the run outcome)
- ingest-profile: new trace+transcript aggregator with table/json formatters
- config: ingest.profile flag; docs: profiling section in ktx-ingest.mdx

* fix(cli): flush tool-call logs before reading ingest profile

Tool transcripts are appended fire-and-forget so the agent hot path never
blocks on logging. The ingest profiler read them before the writes settled,
so per-work-unit toolMs (and the model-vs-tool split derived from it) could
be incomplete. Track in-flight appends and expose flushToolCallLogs() —
bounded by a timeout so it can never hang — and flush before the profiler
reads the transcript.

packages/cli/test/context/ingest/ingest-profile.test.ts

@@ -0,0 +1,247 @@
+import { mkdir, mkdtemp, writeFile } from 'node:fs/promises';
+import { tmpdir } from 'node:os';
+import { join } from 'node:path';
+import { afterEach, describe, expect, it } from 'vitest';
+import {
+  aggregateIngestProfile,
+  formatIngestProfile,
+  formatIngestProfileJson,
+  type IngestProfilePaths,
+  parseTraceEvents,
+  readIngestProfile,
+  resolveIngestProfileMode,
+  type ProfiledTraceEvent,
+} from '../../../src/context/ingest/ingest-profile.js';
+import { rm } from 'node:fs/promises';
+
+function profilePaths(projectDir: string, jobId: string): IngestProfilePaths {
+  return {
+    tracePath: join(projectDir, '.ktx', 'ingest-traces', jobId, 'trace.jsonl'),
+    transcriptDir: join(projectDir, '.ktx', 'ingest-transcripts', jobId),
+  };
+}
+
+function traceLine(event: Partial<ProfiledTraceEvent> & { phase: string; event: string }): string {
+  return JSON.stringify({ schemaVersion: 1, level: 'debug', ...event });
+}
+
+describe('parseTraceEvents', () => {
+  it('parses valid JSONL lines and skips blank and malformed ones', () => {
+    const text = [
+      traceLine({ at: '2026-05-30T00:00:00.000Z', phase: 'fetch', event: 'fetch_finished', durationMs: 100 }),
+      '',
+      '{ not json',
+      traceLine({ phase: 'diff', event: 'compute_diff_set_finished', durationMs: 5 }),
+    ].join('\n');
+    const events = parseTraceEvents(text);
+    expect(events).toHaveLength(2);
+    expect(events[0].phase).toBe('fetch');
+    expect(events[1].event).toBe('compute_diff_set_finished');
+  });
+});
+
+describe('aggregateIngestProfile', () => {
+  it('sums durations per phase and sorts by total descending', () => {
+    const events = parseTraceEvents(
+      [
+        traceLine({ phase: 'fetch', event: 'fetch_finished', durationMs: 1000 }),
+        traceLine({ phase: 'work_unit', event: 'work_unit_executed', durationMs: 5000, data: { unitKey: 'a' } }),
+        traceLine({ phase: 'work_unit', event: 'work_unit_executed', durationMs: 3000, data: { unitKey: 'b' } }),
+        traceLine({ phase: 'diff', event: 'compute_diff_set_finished', durationMs: 50 }),
+      ].join('\n'),
+    );
+    const profile = aggregateIngestProfile({ jobId: 'job-1', events, toolMsByUnit: {} });
+    expect(profile.phases.map((p) => p.phase)).toEqual(['work_unit', 'fetch', 'diff']);
+    expect(profile.phases[0]).toEqual({ phase: 'work_unit', totalMs: 8000, count: 2 });
+  });
+
+  it('builds per-work-unit rows and derives model time from agent loop minus tool time', () => {
+    const events = parseTraceEvents(
+      [
+        traceLine({
+          phase: 'work_unit',
+          event: 'work_unit_child_created',
+          durationMs: 200,
+          data: { unitKey: 'cards/users' },
+        }),
+        traceLine({
+          phase: 'work_unit',
+          event: 'work_unit_executed',
+          durationMs: 12000,
+          data: { unitKey: 'cards/users', status: 'success', agentLoopMs: 10000, stepCount: 12, totalTokens: 48000 },
+        }),
+        traceLine({
+          phase: 'work_unit',
+          event: 'work_unit_child_cleanup',
+          durationMs: 80,
+          data: { unitKey: 'cards/users' },
+        }),
+      ].join('\n'),
+    );
+    const profile = aggregateIngestProfile({ jobId: 'job-1', events, toolMsByUnit: { 'cards/users': 2500 } });
+    expect(profile.workUnitCount).toBe(1);
+    const wu = profile.workUnits[0];
+    expect(wu).toMatchObject({
+      unitKey: 'cards/users',
+      status: 'success',
+      totalMs: 12000,
+      agentLoopMs: 10000,
+      toolMs: 2500,
+      modelMs: 7500,
+      createMs: 200,
+      cleanupMs: 80,
+      stepCount: 12,
+      totalTokens: 48000,
+    });
+  });
+
+  it('counts failed work units and tolerates missing tool transcripts', () => {
+    const events = parseTraceEvents(
+      [
+        traceLine({
+          phase: 'work_unit',
+          event: 'work_unit_executed',
+          durationMs: 4000,
+          data: { unitKey: 'wu-ok', status: 'success', agentLoopMs: 3800 },
+        }),
+        traceLine({
+          phase: 'work_unit',
+          event: 'work_unit_executed',
+          durationMs: 1000,
+          data: { unitKey: 'wu-bad', status: 'failed', agentLoopMs: 900 },
+        }),
+      ].join('\n'),
+    );
+    const profile = aggregateIngestProfile({ jobId: 'job-1', events, toolMsByUnit: {} });
+    expect(profile.failedWorkUnitCount).toBe(1);
+    // No tool transcript → model time falls back to the full agent-loop time.
+    expect(profile.workUnits.find((w) => w.unitKey === 'wu-ok')?.modelMs).toBe(3800);
+  });
+
+  it('derives total wall time from the first and last event timestamps', () => {
+    const events = parseTraceEvents(
+      [
+        traceLine({ at: '2026-05-30T00:00:00.000Z', phase: 'fetch', event: 'fetch_started' }),
+        traceLine({ at: '2026-05-30T00:01:30.000Z', phase: 'run', event: 'ingest_finished' }),
+      ].join('\n'),
+    );
+    const profile = aggregateIngestProfile({ jobId: 'job-1', events, toolMsByUnit: {} });
+    expect(profile.totalWallMs).toBe(90_000);
+  });
+});
+
+describe('formatIngestProfile', () => {
+  it('renders phase breakdown and work-unit rows', () => {
+    const events = parseTraceEvents(
+      [
+        traceLine({ at: '2026-05-30T00:00:00.000Z', phase: 'work_unit', event: 'work_unit_executed', durationMs: 8000, data: { unitKey: 'cards/users', status: 'success', agentLoopMs: 8000, stepCount: 10, totalTokens: 12000 } }),
+        traceLine({ at: '2026-05-30T00:00:10.000Z', phase: 'reconciliation', event: 'reconciliation_executed', durationMs: 2000 }),
+      ].join('\n'),
+    );
+    const profile = aggregateIngestProfile({ jobId: 'job-xyz', events, toolMsByUnit: { 'cards/users': 1000 } });
+    const text = formatIngestProfile(profile);
+    expect(text).toContain('job-xyz');
+    expect(text).toContain('Phase breakdown');
+    expect(text).toContain('work_unit');
+    expect(text).toContain('reconciliation');
+    expect(text).toContain('cards/users');
+    expect(text).toContain('success');
+  });
+});
+
+describe('readIngestProfile', () => {
+  const created: string[] = [];
+  afterEach(async () => {
+    for (const dir of created.splice(0)) {
+      await rm(dir, { recursive: true, force: true });
+    }
+  });
+
+  it('joins nested tool transcripts to work units by wuKey', async () => {
+    const projectDir = await mkdtemp(join(tmpdir(), 'ktx-profile-'));
+    created.push(projectDir);
+    const jobId = 'job-nested';
+    const paths = profilePaths(projectDir, jobId);
+    await mkdir(join(paths.transcriptDir, 'cards'), { recursive: true });
+    await mkdir(join(paths.tracePath, '..'), { recursive: true });
+    await writeFile(
+      paths.tracePath,
+      [
+        JSON.stringify({
+          phase: 'work_unit',
+          event: 'work_unit_executed',
+          durationMs: 10000,
+          data: { unitKey: 'cards/marketing', status: 'success', agentLoopMs: 9000, stepCount: 12 },
+        }),
+      ].join('\n'),
+      'utf-8',
+    );
+    // Work-unit key has a slash → transcript lives at cards/marketing.jsonl.
+    await writeFile(
+      join(paths.transcriptDir, 'cards', 'marketing.jsonl'),
+      [
+        JSON.stringify({ wuKey: 'cards/marketing', toolName: 'sl_write', durationMs: 2000, input: {} }),
+        JSON.stringify({ wuKey: 'cards/marketing', toolName: 'sl_validate', durationMs: 1000, input: {} }),
+      ].join('\n'),
+      'utf-8',
+    );
+
+    const profile = await readIngestProfile(jobId, paths);
+    const wu = profile.workUnits.find((entry) => entry.unitKey === 'cards/marketing');
+    expect(wu?.toolMs).toBe(3000);
+    expect(wu?.modelMs).toBe(6000);
+  });
+});
+
+describe('resolveIngestProfileMode', () => {
+  it('reads the table/json/off mode from the env var', () => {
+    expect(resolveIngestProfileMode(undefined, { KTX_PROFILE_INGEST: '1' })).toBe('table');
+    expect(resolveIngestProfileMode(undefined, { KTX_PROFILE_INGEST: 'true' })).toBe('table');
+    expect(resolveIngestProfileMode(undefined, { KTX_PROFILE_INGEST: 'json' })).toBe('json');
+    expect(resolveIngestProfileMode(undefined, { KTX_PROFILE_INGEST: '0' })).toBe('off');
+    expect(resolveIngestProfileMode(undefined, {})).toBe('off');
+  });
+
+  it('reads the mode from the config value', () => {
+    expect(resolveIngestProfileMode(true, {})).toBe('table');
+    expect(resolveIngestProfileMode('json', {})).toBe('json');
+    expect(resolveIngestProfileMode(false, {})).toBe('off');
+  });
+
+  it('lets either source request json (json wins)', () => {
+    expect(resolveIngestProfileMode(true, { KTX_PROFILE_INGEST: 'json' })).toBe('json');
+    expect(resolveIngestProfileMode('json', { KTX_PROFILE_INGEST: '1' })).toBe('json');
+  });
+});
+
+describe('summary and JSON output', () => {
+  function profileWithReconcileDominant() {
+    const events = parseTraceEvents(
+      [
+        traceLine({ at: '2026-05-30T00:00:00.000Z', phase: 'work_unit', event: 'work_unit_executed', durationMs: 10000, data: { unitKey: 'a', status: 'success', agentLoopMs: 10000, stepCount: 12, totalTokens: 40000 } }),
+        traceLine({ at: '2026-05-30T00:01:40.000Z', phase: 'reconciliation', event: 'reconciliation_executed', durationMs: 90000 }),
+      ].join('\n'),
+    );
+    return aggregateIngestProfile({ jobId: 'job-sum', events, toolMsByUnit: { a: 2000 } });
+  }
+
+  it('produces a headline naming the dominant phase and the model/tool split', () => {
+    const profile = profileWithReconcileDominant();
+    expect(profile.summary.dominantPhase?.phase).toBe('reconciliation');
+    expect(profile.summary.workUnits).toMatchObject({ count: 1, agentLoopMs: 10000, toolMs: 2000, modelMs: 8000, modelPct: 80 });
+    expect(profile.summary.headline).toContain('reconciliation');
+    expect(profile.summary.headline).toContain('80%');
+  });
+
+  it('emits raw structured JSON with stable keys for agents', () => {
+    const profile = profileWithReconcileDominant();
+    const text = formatIngestProfileJson(profile);
+    expect(text).toContain('ktx ingest profile (json)');
+    const json = JSON.parse(text.slice(text.indexOf('{')));
+    expect(json.jobId).toBe('job-sum');
+    expect(json.summary.headline).toEqual(expect.any(String));
+    // Raw milliseconds, not human-formatted strings.
+    expect(json.workUnits[0].agentLoopMs).toBe(10000);
+    expect(json.phases[0].totalMs).toBe(90000);
+  });
+});

packages/cli/test/context/ingest/local-bundle-runtime.test.ts

@@ -299,6 +299,7 @@ describe('createLocalBundleIngestRuntime', () => {
       'ingestTraceLevel',
       'memoryIngestionModel',
       'probeRowCount',
+      'profileIngest',
       'workUnitFailureMode',
       'workUnitMaxConcurrency',
       'workUnitStepBudget',

packages/cli/test/context/ingest/tools/tool-call-logger.test.ts

@@ -0,0 +1,54 @@
+import { mkdtemp, readFile, rm } from 'node:fs/promises';
+import { tmpdir } from 'node:os';
+import { join } from 'node:path';
+import { afterEach, describe, expect, it } from 'vitest';
+import { z } from 'zod';
+import { flushToolCallLogs, wrapToolsWithLogger } from '../../../../src/context/ingest/tools/tool-call-logger.js';
+
+describe('wrapToolsWithLogger + flushToolCallLogs', () => {
+  const dirs: string[] = [];
+  afterEach(async () => {
+    for (const dir of dirs.splice(0)) {
+      await rm(dir, { recursive: true, force: true });
+    }
+  });
+
+  function toolset() {
+    return {
+      my_tool: {
+        name: 'my_tool',
+        description: 'test tool',
+        inputSchema: z.object({}),
+        execute: async (_input: unknown) => ({ markdown: 'ok' }),
+      },
+    };
+  }
+
+  it('makes the fire-and-forget transcript write observable after a flush', async () => {
+    const dir = await mkdtemp(join(tmpdir(), 'ktx-toollog-'));
+    dirs.push(dir);
+    const logPath = join(dir, 'wu.jsonl');
+    const wrapped = wrapToolsWithLogger(toolset(), logPath, 'cards/users');
+
+    await wrapped.my_tool.execute({});
+    // The append is fire-and-forget; flushing must guarantee it has landed.
+    await flushToolCallLogs();
+
+    const entry = JSON.parse((await readFile(logPath, 'utf-8')).trim());
+    expect(entry.wuKey).toBe('cards/users');
+    expect(entry.toolName).toBe('my_tool');
+    expect(typeof entry.durationMs).toBe('number');
+  });
+
+  it('resolves immediately when there is nothing to flush', async () => {
+    await expect(flushToolCallLogs()).resolves.toBeUndefined();
+  });
+
+  it('is bounded by its timeout and never rejects', async () => {
+    const dir = await mkdtemp(join(tmpdir(), 'ktx-toollog-'));
+    dirs.push(dir);
+    const wrapped = wrapToolsWithLogger(toolset(), join(dir, 'wu.jsonl'), 'wu/1');
+    await wrapped.my_tool.execute({});
+    await expect(flushToolCallLogs(0)).resolves.toBeUndefined();
+  });
+});

packages/cli/test/context/llm/ai-sdk-runtime.test.ts

@@ -107,6 +107,73 @@ describe('AiSdkKtxLlmRuntime.runAgentLoop', () => {
     expect(result.error).toBe(err);
   });
 
+  it('returns metrics with stepCount, per-step boundaries, and aggregate token usage', async () => {
+    (generateText as any).mockImplementation(async (opts: any) => {
+      await opts.onStepFinish({});
+      await opts.onStepFinish({});
+      return {
+        text: 'ok',
+        toolCalls: [],
+        steps: [],
+        totalUsage: { inputTokens: 100, outputTokens: 20, totalTokens: 120 },
+      };
+    });
+
+    const result = await runtime.runAgentLoop({
+      modelRole: 'candidateExtraction',
+      systemPrompt: '',
+      userPrompt: '',
+      toolSet: {},
+      stepBudget: 10,
+      telemetryTags: {},
+    });
+
+    expect(result.metrics).toBeDefined();
+    expect(result.metrics?.stepCount).toBe(2);
+    expect(result.metrics?.stepBoundariesMs).toHaveLength(2);
+    expect(result.metrics?.totalMs).toBeGreaterThanOrEqual(0);
+    expect(result.metrics?.usage).toEqual({ inputTokens: 100, outputTokens: 20, totalTokens: 120 });
+  });
+
+  it('falls back to result.usage when totalUsage is absent', async () => {
+    (generateText as any).mockResolvedValue({
+      text: 'ok',
+      toolCalls: [],
+      steps: [],
+      usage: { inputTokens: 7, outputTokens: 3, totalTokens: 10 },
+    });
+
+    const result = await runtime.runAgentLoop({
+      modelRole: 'candidateExtraction',
+      systemPrompt: '',
+      userPrompt: '',
+      toolSet: {},
+      stepBudget: 10,
+      telemetryTags: {},
+    });
+
+    expect(result.metrics?.usage).toEqual({ inputTokens: 7, outputTokens: 3, totalTokens: 10 });
+    expect(result.metrics?.stepCount).toBe(0);
+  });
+
+  it('returns partial metrics even when the loop errors', async () => {
+    (generateText as any).mockRejectedValue(new Error('boom'));
+
+    const result = await runtime.runAgentLoop({
+      modelRole: 'candidateExtraction',
+      systemPrompt: '',
+      userPrompt: '',
+      toolSet: {},
+      stepBudget: 10,
+      telemetryTags: {},
+    });
+
+    expect(result.stopReason).toBe('error');
+    expect(result.metrics).toBeDefined();
+    expect(result.metrics?.stepCount).toBe(0);
+    expect(result.metrics?.usage).toEqual({});
+  });
+
   it('invokes caller onStepFinish with incrementing stepIndex and total budget', async () => {
     const calls: RunLoopStepInfo[] = [];
     (generateText as any).mockImplementation(async (opts: any) => {

packages/cli/test/context/llm/claude-code-runtime.test.ts

@@ -284,7 +284,7 @@ describe('ClaudeCodeKtxLlmRuntime', () => {
         stepBudget: 1,
         telemetryTags: { operationName: 'test' },
       }),
-    ).resolves.toEqual({ stopReason: 'budget' });
+    ).resolves.toMatchObject({ stopReason: 'budget' });
 
     const options = query.mock.calls[0][0].options;
     expect(options.allowedTools).toEqual(['mcp__ktx__load_skill']);
@@ -467,7 +467,7 @@ describe('ClaudeCodeKtxLlmRuntime', () => {
         telemetryTags: { operationName: 'test' },
         onStepFinish,
       }),
-    ).resolves.toEqual({ stopReason: 'natural' });
+    ).resolves.toMatchObject({ stopReason: 'natural' });
 
     expect(onStepFinish).toHaveBeenCalledTimes(1);
     expect(onStepFinish).toHaveBeenCalledWith({ stepIndex: 1, stepBudget: 40 });
@@ -513,7 +513,7 @@ describe('ClaudeCodeKtxLlmRuntime', () => {
           throw new Error('callback exploded');
         },
       }),
-    ).resolves.toEqual({ stopReason: 'natural' });
+    ).resolves.toMatchObject({ stopReason: 'natural' });
     expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('callback exploded'));
   });
 
@@ -525,6 +525,45 @@ describe('ClaudeCodeKtxLlmRuntime', () => {
     expect(mapClaudeCodeStopReason(resultMessage({ subtype: 'error_during_execution' }))).toBe('error');
   });
 
+  it('returns loop metrics including step count and mapped token usage', async () => {
+    const query = vi.fn((_input: any) =>
+      stream([
+        initMessage(),
+        {
+          type: 'assistant',
+          message: { role: 'assistant', content: [] },
+          parent_tool_use_id: null,
+          uuid: '00000000-0000-4000-8000-000000000006',
+          session_id: 'session-id',
+        } as unknown as SDKMessage,
+        resultMessage({
+          subtype: 'success',
+          terminal_reason: 'completed',
+          usage: { input_tokens: 50, output_tokens: 10 } as never,
+        }),
+      ]),
+    );
+    const runtime = new ClaudeCodeKtxLlmRuntime({
+      projectDir: '/tmp/project',
+      modelSlots: { default: 'sonnet' },
+      query,
+      env: {},
+    });
+
+    const result = await runtime.runAgentLoop({
+      modelRole: 'default',
+      systemPrompt: 'system',
+      userPrompt: 'user',
+      toolSet: {},
+      stepBudget: 40,
+      telemetryTags: { operationName: 'test' },
+    });
+
+    expect(result.metrics?.stepCount).toBe(1);
+    expect(result.metrics?.stepBoundariesMs).toHaveLength(1);
+    expect(result.metrics?.usage).toEqual({ inputTokens: 50, outputTokens: 10, totalTokens: 60 });
+  });
+
   it('auth probe uses isolation options and a scrubbed env', async () => {
     const query = vi.fn((_input: any) => stream([initMessage(), resultMessage({ result: 'ok' })]));
 

packages/cli/test/context/project/config.test.ts

@@ -50,6 +50,7 @@ connections:
           maxConcurrency: 1,
           failureMode: 'continue',
         },
+        profile: false,
       },
       agent: {
         run_research: {
@@ -156,6 +157,12 @@ ingest:
     });
   });
 
+  it('parses the ingest.profile flag (false default, true, or "json")', () => {
+    expect(parseKtxProjectConfig('ingest:\n  adapters: []\n').ingest.profile).toBe(false);
+    expect(parseKtxProjectConfig('ingest:\n  profile: true\n').ingest.profile).toBe(true);
+    expect(parseKtxProjectConfig('ingest:\n  profile: json\n').ingest.profile).toBe('json');
+  });
+
   it('parses global Vertex LLM config', () => {
     const config = parseKtxProjectConfig(`
 llm: