diff options
| author | Adam Malczewski <[email protected]> | 2026-06-07 17:46:53 +0900 |
|---|---|---|
| committer | Adam Malczewski <[email protected]> | 2026-06-07 17:46:53 +0900 |
| commit | 7c459c7d919d1e08a228e8abc56129be174d8abe (patch) | |
| tree | 93011125c001945723ac9b9358c4ddd450f87f72 /packages/kernel/src/runtime/run-turn.ts | |
| parent | 5746cf4e545cd5b0d7faf0595554f273f236f3a9 (diff) | |
| download | dispatch-7c459c7d919d1e08a228e8abc56129be174d8abe.tar.gz dispatch-7c459c7d919d1e08a228e8abc56129be174d8abe.zip | |
feat(wire,kernel,session-orchestrator): live turn metrics on the stream
Expose the backend's authoritative token+timing metrics on the live AgentEvent
stream (observability-only -> now also client-facing). All additive/optional.
- [email protected]: new TurnStepCompleteEvent (type:step-complete) with per-step
ttftMs/decodeMs/genTotalMs; usage += stepId; tool-result += durationMs (exec);
done += durationMs (turn wall-clock) + usage (turn total). RunTurnInput += now?.
[email protected] (re-export bump).
- kernel-runtime: when now injected, measures + emits the above (reuses the
ttft/decode first-token detection); omits timing gracefully without a clock.
- session-orchestrator: adds now? to deps, threads into RunTurnInput; extension
activate injects () => Date.now().
- transport/cli/host-bin: untouched (verbatim pass-through; additive fields).
FE handoff: frontend-metrics-handoff.md. typecheck clean; 520 vitest + 89 bun;
biome 0/0. Replay/persistence = deferred Pass 2 (documented in tasks.md).
Diffstat (limited to 'packages/kernel/src/runtime/run-turn.ts')
| -rw-r--r-- | packages/kernel/src/runtime/run-turn.ts | 65 |
1 files changed, 62 insertions, 3 deletions
diff --git a/packages/kernel/src/runtime/run-turn.ts b/packages/kernel/src/runtime/run-turn.ts index a8ee6c9..06069a2 100644 --- a/packages/kernel/src/runtime/run-turn.ts +++ b/packages/kernel/src/runtime/run-turn.ts @@ -8,6 +8,7 @@ import { doneEvent, errorEvent, reasoningDeltaEvent, + stepCompleteEvent, textDeltaEvent, toolCallEvent, toolResultEvent, @@ -84,12 +85,15 @@ interface StepContext { readonly turnSpan: Span | undefined; readonly toolSpans: Map<string, Span>; readonly cwd: string | undefined; + readonly now: (() => number) | undefined; } interface TimingState { ttftSpan: Span | undefined; decodeSpan: Span | undefined; firstTokenSeen: boolean; + streamStartMs: number | undefined; + firstTokenMs: number | undefined; } interface StepResult { @@ -108,11 +112,15 @@ function processEvent( ctx: StepContext, stepSpan: Span | undefined, timing: TimingState, + toolDispatchTimes: Map<string, number>, ): void { switch (event.type) { case "text-delta": if (!timing.firstTokenSeen) { timing.firstTokenSeen = true; + if (ctx.now !== undefined) { + timing.firstTokenMs = ctx.now(); + } try { timing.ttftSpan?.end({ attrs: { firstToken: true } }); } catch { @@ -131,6 +139,9 @@ function processEvent( case "reasoning-delta": if (!timing.firstTokenSeen) { timing.firstTokenSeen = true; + if (ctx.now !== undefined) { + timing.firstTokenMs = ctx.now(); + } try { timing.ttftSpan?.end({ attrs: { firstToken: true } }); } catch { @@ -171,6 +182,11 @@ function processEvent( ), ); + // Capture dispatch time for tool-call durationMs + if (ctx.now !== undefined) { + toolDispatchTimes.set(event.toolCallId, ctx.now()); + } + // Open a tool-call span as a child of the step span (attrs: name, toolCallId) try { const tcSpan = @@ -194,7 +210,7 @@ function processEvent( break; } case "usage": - ctx.emit(usageEvent(ctx.conversationId, ctx.turnId, event.usage)); + ctx.emit(usageEvent(ctx.conversationId, ctx.turnId, event.usage, ctx.stepId)); break; case "finish": break; @@ -212,6 +228,7 @@ function processEvent( async function executeStep(ctx: StepContext): Promise<StepResult> { const chunks: Chunk[] = []; const toolCalls: ToolCall[] = []; + const toolDispatchTimes = new Map<string, number>(); let stepUsage = zeroUsage(); let finishReason = "stop"; @@ -250,6 +267,8 @@ async function executeStep(ctx: StepContext): Promise<StepResult> { ttftSpan: undefined, decodeSpan: undefined, firstTokenSeen: false, + streamStartMs: ctx.now !== undefined ? ctx.now() : undefined, + firstTokenMs: undefined, }; // Open TTFT span when spans are enabled @@ -268,7 +287,7 @@ async function executeStep(ctx: StepContext): Promise<StepResult> { const stream = ctx.provider.stream(ctx.messages, ctx.tools, opts); for await (const event of stream) { if (ctx.signal.aborted) break; - processEvent(event, chunks, toolCalls, dispatcher, ctx, stepSpan, timing); + processEvent(event, chunks, toolCalls, dispatcher, ctx, stepSpan, timing, toolDispatchTimes); if (event.type === "usage") { stepUsage = addUsage(stepUsage, event.usage); } @@ -305,6 +324,22 @@ async function executeStep(ctx: StepContext): Promise<StepResult> { // Swallow — D7. } + // Emit step-complete event with timing + const streamEndMs = ctx.now !== undefined ? ctx.now() : undefined; + if (timing.streamStartMs !== undefined && streamEndMs !== undefined) { + const genTotalMs = streamEndMs - timing.streamStartMs; + const stepTiming: { ttftMs?: number; decodeMs?: number; genTotalMs?: number } = { + genTotalMs, + }; + if (timing.firstTokenMs !== undefined) { + stepTiming.ttftMs = timing.firstTokenMs - timing.streamStartMs; + stepTiming.decodeMs = streamEndMs - timing.firstTokenMs; + } + ctx.emit(stepCompleteEvent(ctx.conversationId, ctx.turnId, ctx.stepId, stepTiming)); + } else { + ctx.emit(stepCompleteEvent(ctx.conversationId, ctx.turnId, ctx.stepId)); + } + if (!ctx.dispatch.eager) { for (const call of toolCalls) { dispatcher.submit(call); @@ -337,6 +372,9 @@ async function executeStep(ctx: StepContext): Promise<StepResult> { const result = results.get(call.id); if (result !== undefined) { const isError = result.isError ?? false; + const dispatchTime = toolDispatchTimes.get(call.id); + const toolDurationMs = + ctx.now !== undefined && dispatchTime !== undefined ? ctx.now() - dispatchTime : undefined; ctx.emit( toolResultEvent( ctx.conversationId, @@ -346,6 +384,7 @@ async function executeStep(ctx: StepContext): Promise<StepResult> { call.name, result.content, isError, + toolDurationMs, ), ); toolMessages.push({ @@ -400,6 +439,10 @@ export async function runTurn(input: RunTurnInput): Promise<RunTurnResult> { const turnId = input.turnId; const signal = input.signal ?? new AbortController().signal; const logger = input.logger; + const now = input.now; + + // Record turn start time for durationMs on done + const turnStartMs = now !== undefined ? now() : undefined; // Open a turn span (attrs: conversationId, turnId, model) let turnSpan: Span | undefined; @@ -444,6 +487,7 @@ export async function runTurn(input: RunTurnInput): Promise<RunTurnResult> { turnSpan, toolSpans, cwd: input.cwd, + now, }); totalUsage = addUsage(totalUsage, stepResult.usage); @@ -499,7 +543,22 @@ export async function runTurn(input: RunTurnInput): Promise<RunTurnResult> { } } - input.emit(doneEvent(conversationId, turnId, finishReason)); + const turnDurationMs = + turnStartMs !== undefined && now !== undefined ? now() - turnStartMs : undefined; + const hasUsage = + totalUsage.inputTokens > 0 || + totalUsage.outputTokens > 0 || + totalUsage.cacheReadTokens !== undefined || + totalUsage.cacheWriteTokens !== undefined; + input.emit( + doneEvent( + conversationId, + turnId, + finishReason, + turnDurationMs, + hasUsage ? totalUsage : undefined, + ), + ); return { messages: resultMessages, usage: totalUsage, finishReason }; } |
