ktx/packages/cli/src/context/llm/ai-sdk-runtime.ts
Andrey Avtomonov 21744fc520
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.
2026-06-01 15:49:17 +02:00

202 lines
7.3 KiB
TypeScript

import { KtxMessageBuilder, splitKtxSystemMessages } from '../../llm/message-builder.js';
import type { KtxLlmProvider } from '../../llm/types.js';
import { generateText, Output, stepCountIs, type FlexibleSchema, type TelemetrySettings, type ToolSet } from 'ai';
import type { z } from 'zod';
import { noopLogger, type KtxLogger } from '../../context/core/config.js';
import { summarizeKtxLlmDebugRequest, type KtxLlmDebugRequestRecorder } from './debug-request-recorder.js';
import { createAiSdkToolSet } from './runtime-tools.js';
import type {
KtxGenerateObjectInput,
KtxGenerateTextInput,
KtxLlmRuntimePort,
LlmTokenUsage,
RunLoopParams,
RunLoopResult,
} from './runtime-port.js';
interface AgentTelemetryPort {
createTelemetry(tags: Record<string, string>): TelemetrySettings;
}
interface MaybeUsage {
inputTokens?: number;
outputTokens?: number;
totalTokens?: number;
}
function toLlmTokenUsage(usage: MaybeUsage | undefined): LlmTokenUsage {
if (!usage) {
return {};
}
return {
...(usage.inputTokens !== undefined ? { inputTokens: usage.inputTokens } : {}),
...(usage.outputTokens !== undefined ? { outputTokens: usage.outputTokens } : {}),
...(usage.totalTokens !== undefined ? { totalTokens: usage.totalTokens } : {}),
};
}
export interface AiSdkKtxLlmRuntimeDeps {
llmProvider: KtxLlmProvider;
telemetry?: AgentTelemetryPort;
logger?: KtxLogger;
debugRequestRecorder?: KtxLlmDebugRequestRecorder;
}
function hasTools(tools: Record<string, unknown>): boolean {
return Object.keys(tools).length > 0;
}
export class AiSdkKtxLlmRuntime implements KtxLlmRuntimePort {
private readonly logger: KtxLogger;
constructor(private readonly deps: AiSdkKtxLlmRuntimeDeps) {
this.logger = deps.logger ?? noopLogger;
}
async generateText(input: KtxGenerateTextInput): Promise<string> {
const model = this.deps.llmProvider.getModel(input.role);
if ((model as { provider?: string }).provider === 'deterministic') {
return `Deterministic description for ${input.prompt.slice(0, 64).trim() || 'data source'}`;
}
const tools = createAiSdkToolSet(input.tools ?? {});
const built = new KtxMessageBuilder(this.deps.llmProvider).wrapSimple({
system: input.system,
messages: [{ role: 'user', content: input.prompt }],
tools,
model,
});
const split = splitKtxSystemMessages(built.messages);
const startedAt = Date.now();
const result = await generateText({
model,
temperature: input.temperature ?? 0,
...(split.system ? { system: split.system } : {}),
messages: split.messages,
tools: built.tools as ToolSet,
...(hasTools(tools)
? {
experimental_repairToolCall: this.deps.llmProvider.repairToolCallHandler({
source: `ktx-${input.role}`,
}),
}
: {}),
});
input.onMetrics?.({ totalMs: Date.now() - startedAt, usage: toLlmTokenUsage(result.totalUsage ?? result.usage) });
if (typeof result.text !== 'string') {
throw new Error('KTX LLM text generation returned no text');
}
return result.text;
}
async generateObject<TOutput, TSchema extends z.ZodType<TOutput>>(
input: KtxGenerateObjectInput<TOutput, TSchema>,
): Promise<TOutput> {
const model = this.deps.llmProvider.getModel(input.role);
const tools = createAiSdkToolSet(input.tools ?? {});
const built = new KtxMessageBuilder(this.deps.llmProvider).wrapSimple({
system: input.system,
messages: [{ role: 'user', content: input.prompt }],
tools,
model,
});
const split = splitKtxSystemMessages(built.messages);
const startedAt = Date.now();
const result = await generateText({
model,
temperature: input.temperature ?? 0,
...(split.system ? { system: split.system } : {}),
messages: split.messages,
tools: built.tools as ToolSet,
...(hasTools(tools)
? {
experimental_repairToolCall: this.deps.llmProvider.repairToolCallHandler({
source: `ktx-${input.role}`,
}),
}
: {}),
output: Output.object({ schema: input.schema as unknown as FlexibleSchema<TOutput> }),
});
input.onMetrics?.({ totalMs: Date.now() - startedAt, usage: toLlmTokenUsage(result.totalUsage ?? result.usage) });
if (result.output == null) {
throw new Error('KTX LLM object generation returned no output');
}
return result.output as TOutput;
}
async runAgentLoop(params: RunLoopParams): Promise<RunLoopResult> {
let stepIndex = 0;
const startedAt = Date.now();
const stepBoundariesMs: number[] = [];
try {
const model = this.deps.llmProvider.getModel(params.modelRole);
const tools = createAiSdkToolSet(params.toolSet);
const builder = new KtxMessageBuilder(this.deps.llmProvider);
const built = builder.wrapSimple({
system: params.systemPrompt,
messages: [{ role: 'user', content: params.userPrompt }],
tools,
model,
});
const promptMessages = splitKtxSystemMessages(built.messages);
await this.deps.debugRequestRecorder?.record(
summarizeKtxLlmDebugRequest({
operationName: params.telemetryTags.operationName ?? 'ktx-agent-runner',
source: params.telemetryTags.source,
jobId: params.telemetryTags.jobId,
unitKey: params.telemetryTags.unitKey,
modelRole: params.modelRole,
modelId: (model as { modelId?: string }).modelId ?? params.modelRole,
messages: built.messages,
tools: built.tools as Record<string, { providerOptions?: unknown }>,
}),
);
const result = await generateText({
model,
temperature: 0,
stopWhen: stepCountIs(params.stepBudget),
experimental_telemetry: this.deps.telemetry?.createTelemetry(params.telemetryTags) ?? this.deps.llmProvider.telemetryConfig(),
experimental_repairToolCall: this.deps.llmProvider.repairToolCallHandler({
source: params.telemetryTags.operationName ?? 'ktx-agent-runner',
}),
...(promptMessages.system ? { system: promptMessages.system } : {}),
messages: promptMessages.messages,
tools: built.tools as ToolSet,
onStepFinish: async () => {
stepIndex += 1;
stepBoundariesMs.push(Date.now() - startedAt);
if (!params.onStepFinish) {
return;
}
try {
await params.onStepFinish({ stepIndex, stepBudget: params.stepBudget });
} catch (err) {
this.logger.warn(
`[agent-runner] onStepFinish callback threw; ignoring: ${
err instanceof Error ? err.message : String(err)
}`,
);
}
},
});
return {
stopReason: 'natural',
metrics: {
totalMs: Date.now() - startedAt,
stepCount: stepIndex,
stepBoundariesMs,
usage: toLlmTokenUsage(result.totalUsage ?? result.usage),
},
};
} catch (error) {
const err = error instanceof Error ? error : new Error(String(error));
this.logger.warn(`[agent-runner] loop failed: ${err.message}`);
return {
stopReason: 'error',
error: err,
metrics: { totalMs: Date.now() - startedAt, stepCount: stepIndex, stepBoundariesMs, usage: {} },
};
}
}
}