mirror of
https://github.com/Kaelio/ktx.git
synced 2026-06-10 08:05:14 +02:00
21744fc520
* 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.
54 lines
1.9 KiB
TypeScript
54 lines
1.9 KiB
TypeScript
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();
|
|
});
|
|
});
|