diff --git a/apps/kimi-code/src/tui/kimi-tui.ts b/apps/kimi-code/src/tui/kimi-tui.ts index e05d51738..d1a3f5d3e 100644 --- a/apps/kimi-code/src/tui/kimi-tui.ts +++ b/apps/kimi-code/src/tui/kimi-tui.ts @@ -278,6 +278,7 @@ import { createTerminalState, type TerminalState } from './utils/terminal-state' import { installTerminalThemeTracking } from './utils/terminal-theme'; import { detectTmuxKeyboardWarning } from './utils/tmux-keyboard'; import { nextTranscriptId } from './utils/transcript-id'; +import { formatStepDebugTiming } from '#/utils/usage/debug-timing'; export interface KimiTUIStartupInput { readonly cliOptions: CLIOptions; @@ -2991,6 +2992,7 @@ export class KimiTUI { // notice pointing at the config knob. private handleStepCompleted(event: TurnStepCompletedEvent): void { this.flushStreamingUiUpdatesNow(); + this.maybeShowDebugTiming(event); if (event.finishReason !== 'max_tokens') return; // Scope the truncation marking to tool calls that belong to the @@ -3028,6 +3030,12 @@ export class KimiTUI { this.showNotice(title, detail); } + private maybeShowDebugTiming(event: TurnStepCompletedEvent): void { + if (process.env['KIMI_CODE_DEBUG'] !== '1') return; + const text = formatStepDebugTiming(event); + if (text !== undefined) this.showStatus(text); + } + private isAnthropicSessionActive(): boolean { const providerKey = this.state.appState.availableModels[this.state.appState.model]?.provider; if (providerKey === undefined) return false; diff --git a/apps/kimi-code/src/utils/usage/debug-timing.ts b/apps/kimi-code/src/utils/usage/debug-timing.ts new file mode 100644 index 000000000..76d400506 --- /dev/null +++ b/apps/kimi-code/src/utils/usage/debug-timing.ts @@ -0,0 +1,24 @@ +export interface StepTimingInput { + readonly llmFirstTokenLatencyMs?: number | undefined; + readonly llmStreamDurationMs?: number | undefined; + readonly usage?: { readonly output: number } | undefined; +} + +export function formatStepDebugTiming(input: StepTimingInput): string | undefined { + const latency = input.llmFirstTokenLatencyMs; + const streamMs = input.llmStreamDurationMs; + if (latency === undefined || streamMs === undefined) return undefined; + + const parts: string[] = [`TTFT: ${formatDuration(latency)}`]; + const outputTokens = input.usage?.output; + if (outputTokens !== undefined && outputTokens > 0 && streamMs > 0) { + const tps = (outputTokens / (streamMs / 1000)).toFixed(1); + parts.push(`TPS: ${tps} tok/s (${outputTokens} tokens in ${formatDuration(streamMs)})`); + } + return `[Debug] ${parts.join(' | ')}`; +} + +function formatDuration(ms: number): string { + if (ms < 1000) return `${Math.round(ms)}ms`; + return `${(ms / 1000).toFixed(1)}s`; +} diff --git a/apps/kimi-code/test/utils/usage/debug-timing.test.ts b/apps/kimi-code/test/utils/usage/debug-timing.test.ts new file mode 100644 index 000000000..b986f08e6 --- /dev/null +++ b/apps/kimi-code/test/utils/usage/debug-timing.test.ts @@ -0,0 +1,49 @@ +import { describe, expect, it } from 'vitest'; + +import { formatStepDebugTiming } from '#/utils/usage/debug-timing'; + +describe('formatStepDebugTiming', () => { + it('returns undefined when timing fields are missing', () => { + expect(formatStepDebugTiming({})).toBeUndefined(); + expect(formatStepDebugTiming({ llmFirstTokenLatencyMs: 100 })).toBeUndefined(); + expect(formatStepDebugTiming({ llmStreamDurationMs: 200 })).toBeUndefined(); + }); + + it('formats TTFT only when output tokens are zero', () => { + const result = formatStepDebugTiming({ + llmFirstTokenLatencyMs: 250, + llmStreamDurationMs: 3000, + usage: { output: 0 }, + }); + expect(result).toBe('[Debug] TTFT: 250ms'); + }); + + it('formats TTFT and TPS with output tokens', () => { + const result = formatStepDebugTiming({ + llmFirstTokenLatencyMs: 800, + llmStreamDurationMs: 5000, + usage: { output: 200 }, + }); + expect(result).toBe('[Debug] TTFT: 800ms | TPS: 40.0 tok/s (200 tokens in 5.0s)'); + }); + + it('formats durations under 1s as milliseconds', () => { + const result = formatStepDebugTiming({ + llmFirstTokenLatencyMs: 50, + llmStreamDurationMs: 900, + usage: { output: 10 }, + }); + expect(result).toContain('TTFT: 50ms'); + expect(result).toContain('900ms'); + }); + + it('formats durations at or above 1s as seconds', () => { + const result = formatStepDebugTiming({ + llmFirstTokenLatencyMs: 1500, + llmStreamDurationMs: 10000, + usage: { output: 500 }, + }); + expect(result).toContain('TTFT: 1.5s'); + expect(result).toContain('10.0s'); + }); +}); diff --git a/packages/agent-core/src/agent/turn/index.ts b/packages/agent-core/src/agent/turn/index.ts index 4f767d625..3efeb0b2c 100644 --- a/packages/agent-core/src/agent/turn/index.ts +++ b/packages/agent-core/src/agent/turn/index.ts @@ -637,6 +637,8 @@ function mapLoopEvent(event: LoopEvent, turnId: number): AgentEvent | undefined stepId: event.uuid, usage: event.usage, finishReason: event.finishReason, + llmFirstTokenLatencyMs: event.llmFirstTokenLatencyMs, + llmStreamDurationMs: event.llmStreamDurationMs, providerFinishReason: event.providerFinishReason, rawFinishReason: event.rawFinishReason, }; diff --git a/packages/agent-core/src/agent/turn/kosong-llm.ts b/packages/agent-core/src/agent/turn/kosong-llm.ts index ef164dcca..f8e254e07 100644 --- a/packages/agent-core/src/agent/turn/kosong-llm.ts +++ b/packages/agent-core/src/agent/turn/kosong-llm.ts @@ -18,6 +18,7 @@ import { emptyUsage, generate as kosongGenerate, + type GenerateOptions, isRetryableGenerateError, type ChatProvider, type GenerateCallbacks, @@ -26,7 +27,13 @@ import { type StreamedMessagePart, } from '@moonshot-ai/kosong'; -import type { LLM, LLMChatParams, LLMChatResponse, LLMRequestLogContext } from '../../loop'; +import type { + LLM, + LLMChatParams, + LLMChatResponse, + LLMRequestLogContext, + LLMStreamTiming, +} from '../../loop'; import { applyCompletionBudget, type CompletionBudgetConfig, @@ -34,8 +41,7 @@ import { export const GENERATE_REQUEST_LOG_CONTEXT = '__kimiRequestLogContext'; -export type GenerateOptionsWithRequestLog = { - readonly signal?: AbortSignal; +export type GenerateOptionsWithRequestLog = GenerateOptions & { readonly [GENERATE_REQUEST_LOG_CONTEXT]?: LLMRequestLogContext; }; @@ -78,7 +84,21 @@ export class KosongLLM implements LLM { } async chat(params: LLMChatParams): Promise { - const callbacks = buildKosongCallbacks(params); + let requestStartedAt = Date.now(); + let firstChunkAt: number | undefined; + let streamEndedAt: number | undefined; + const markRequestStart = (): void => { + requestStartedAt = Date.now(); + }; + const markStreamEnd = (): void => { + streamEndedAt = Date.now(); + }; + const markStreamOutput = (): void => { + if (firstChunkAt === undefined) { + firstChunkAt = Date.now(); + } + }; + const callbacks = buildKosongCallbacks(params, markStreamOutput); // Compute and apply the per-request completion budget against a // throwaway shallow clone. `effectiveProvider` is local to this call @@ -96,7 +116,10 @@ export class KosongLLM implements LLM { [...params.tools], [...params.messages], callbacks, - generateOptions(params), + generateOptions(params, { + onRequestStart: markRequestStart, + onStreamEnd: markStreamEnd, + }), ); // Replay merged content parts onto loop per-block callbacks after the @@ -117,6 +140,10 @@ export class KosongLLM implements LLM { providerFinishReason: result.finishReason ?? undefined, rawFinishReason: result.rawFinishReason ?? undefined, usage: result.usage ?? emptyUsage(), + streamTiming: + firstChunkAt === undefined + ? undefined + : buildStreamTiming(requestStartedAt, firstChunkAt, streamEndedAt), }; return response; @@ -127,20 +154,34 @@ export class KosongLLM implements LLM { } } -function generateOptions(params: LLMChatParams): GenerateOptionsWithRequestLog { - const options: GenerateOptionsWithRequestLog = { - signal: params.signal, +function buildStreamTiming( + requestStartedAt: number, + firstChunkAt: number, + streamEndedAt: number | undefined, +): LLMStreamTiming { + const outputEndedAt = streamEndedAt ?? Date.now(); + return { + firstTokenLatencyMs: Math.max(0, firstChunkAt - requestStartedAt), + streamDurationMs: Math.max(0, outputEndedAt - firstChunkAt), }; - if (params.requestLogContext !== undefined) { - return { - ...options, - [GENERATE_REQUEST_LOG_CONTEXT]: params.requestLogContext, - }; - } - return options; } -function buildKosongCallbacks(params: LLMChatParams): GenerateCallbacks { +function generateOptions( + params: LLMChatParams, + hooks: Pick, +): GenerateOptionsWithRequestLog { + return { + signal: params.signal, + onRequestStart: hooks.onRequestStart, + onStreamEnd: hooks.onStreamEnd, + [GENERATE_REQUEST_LOG_CONTEXT]: params.requestLogContext, + }; +} + +function buildKosongCallbacks( + params: LLMChatParams, + markStreamOutput: () => void, +): GenerateCallbacks { type ToolCallIdentity = { readonly toolCallId: string; readonly name: string }; type BufferedToolCallDelta = { readonly argumentsPart?: string | undefined }; @@ -159,6 +200,7 @@ function buildKosongCallbacks(params: LLMChatParams): GenerateCallbacks { return { onMessagePart: (part: StreamedMessagePart) => { + markStreamOutput(); if (part.type === 'text') { if (params.onTextDelta === undefined) return; params.onTextDelta(part.text); diff --git a/packages/agent-core/src/loop/events.ts b/packages/agent-core/src/loop/events.ts index 640ee7af4..592649658 100644 --- a/packages/agent-core/src/loop/events.ts +++ b/packages/agent-core/src/loop/events.ts @@ -19,6 +19,8 @@ export interface LoopStepEndEvent { readonly step: number; readonly usage?: TokenUsage | undefined; readonly finishReason?: LoopStepStopReason | undefined; + readonly llmFirstTokenLatencyMs?: number | undefined; + readonly llmStreamDurationMs?: number | undefined; /** * Provider diagnostics are optional and must not drive loop control. * Use `finishReason` for normalized behavior. diff --git a/packages/agent-core/src/loop/index.ts b/packages/agent-core/src/loop/index.ts index c0071df54..781097907 100644 --- a/packages/agent-core/src/loop/index.ts +++ b/packages/agent-core/src/loop/index.ts @@ -63,6 +63,7 @@ export type { LLMChatParams, LLMChatResponse, LLMRequestLogContext, + LLMStreamTiming, ToolCallDelta, } from './llm'; diff --git a/packages/agent-core/src/loop/llm.ts b/packages/agent-core/src/loop/llm.ts index cd56206e2..88bf716e7 100644 --- a/packages/agent-core/src/loop/llm.ts +++ b/packages/agent-core/src/loop/llm.ts @@ -31,6 +31,11 @@ export interface LLMRequestLogContext { readonly maxAttempts?: number; } +export interface LLMStreamTiming { + readonly firstTokenLatencyMs: number; + readonly streamDurationMs: number; +} + export interface LLMChatParams { messages: Message[]; tools: readonly Tool[]; @@ -60,6 +65,7 @@ export interface LLMChatResponse { providerFinishReason?: FinishReason; rawFinishReason?: string; usage: TokenUsage; + streamTiming?: LLMStreamTiming; } export interface LLM { diff --git a/packages/agent-core/src/loop/turn-step.ts b/packages/agent-core/src/loop/turn-step.ts index ceceb346a..ca7825bbc 100644 --- a/packages/agent-core/src/loop/turn-step.ts +++ b/packages/agent-core/src/loop/turn-step.ts @@ -139,6 +139,8 @@ export async function executeLoopStep(deps: ExecuteLoopStepDeps): Promise<{ step: currentStep, usage, finishReason: effectiveStopReason, + llmFirstTokenLatencyMs: response.streamTiming?.firstTokenLatencyMs, + llmStreamDurationMs: response.streamTiming?.streamDurationMs, ...stepEndProviderDiagnostics(response, effectiveStopReason), }); diff --git a/packages/agent-core/src/rpc/events.ts b/packages/agent-core/src/rpc/events.ts index cd19c7126..b9a488068 100644 --- a/packages/agent-core/src/rpc/events.ts +++ b/packages/agent-core/src/rpc/events.ts @@ -104,6 +104,8 @@ export interface TurnStepCompletedEvent { readonly stepId?: string | undefined; readonly usage?: TokenUsage | undefined; readonly finishReason?: string | undefined; + readonly llmFirstTokenLatencyMs?: number | undefined; + readonly llmStreamDurationMs?: number | undefined; readonly providerFinishReason?: FinishReason | undefined; readonly rawFinishReason?: string | undefined; } diff --git a/packages/agent-core/test/agent/harness/snapshots.ts b/packages/agent-core/test/agent/harness/snapshots.ts index 31b3d6caf..b04137b73 100644 --- a/packages/agent-core/test/agent/harness/snapshots.ts +++ b/packages/agent-core/test/agent/harness/snapshots.ts @@ -266,12 +266,14 @@ function normalizeValue(value: unknown, uuidLabels: Map): unknow if (value !== null && typeof value === 'object') { return Object.fromEntries( - Object.entries(value).map(([key, nested]) => [ - key, - (key === 'time' || key === 'created_at') && typeof nested === 'number' - ? '