feat: expose LLM stream timing events (#101)

* feat: expose LLM stream timing events

* feat(kimi-code): show LLM timing in debug mode (KIMI_CODE_DEBUG=1)

* refactor: extract debug timing formatting into standalone module

* chore: remove changeset

---------

Co-authored-by: liruifengv <liruifeng1024@gmail.com>

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;

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`;
+}

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');
+  });
+});

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,
       };

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<LLMChatResponse> {
-    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<GenerateOptions, 'onRequestStart' | 'onStreamEnd'>,
+): 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);

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.

packages/agent-core/src/loop/index.ts

@@ -63,6 +63,7 @@ export type {
   LLMChatParams,
   LLMChatResponse,
   LLMRequestLogContext,
+  LLMStreamTiming,
   ToolCallDelta,
 } from './llm';
 

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 {

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),
   });
 

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;
 }

packages/agent-core/test/agent/harness/snapshots.ts

@@ -266,12 +266,14 @@ function normalizeValue(value: unknown, uuidLabels: Map<string, string>): 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'
-          ? '<time>'
-          : normalizeValue(nested, uuidLabels),
-      ]),
+      Object.entries(value)
+        .filter(([key]) => !isVolatileDurationKey(key))
+        .map(([key, nested]) => [
+          key,
+          (key === 'time' || key === 'created_at') && typeof nested === 'number'
+            ? '<time>'
+            : normalizeValue(nested, uuidLabels),
+        ]),
     );
   }
 
@@ -298,6 +300,10 @@ function isUuid(value: string): boolean {
   return /^[0-9a-f]{8}-[0-9a-f]{4}-[1-5][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i.test(value);
 }
 
+function isVolatileDurationKey(key: string): boolean {
+  return key === 'llmFirstTokenLatencyMs' || key === 'llmStreamDurationMs';
+}
+
 function isPlanModeReminder(value: string): boolean {
   return (
     value.includes('Plan mode is active. You MUST NOT make any edits') &&

packages/agent-core/test/agent/kosong-llm.test.ts

@@ -84,6 +84,53 @@ describe('KosongLLM streaming tool-call deltas', () => {
   });
 });
 
+describe('KosongLLM stream timing', () => {
+  it('returns timing measured from provider request start to stream end', async () => {
+    const generate: GenerateFn = async (
+      _provider,
+      _systemPrompt,
+      _tools,
+      _history,
+      callbacks,
+      options,
+    ) => {
+      options?.onRequestStart?.();
+      await callbacks?.onMessagePart?.({ type: 'text', text: 'timed' });
+      options?.onStreamEnd?.();
+      return {
+        id: 'response-1',
+        message: {
+          role: 'assistant',
+          content: [{ type: 'text', text: 'timed' }],
+          toolCalls: [],
+        },
+        usage: emptyUsage(),
+        finishReason: 'completed',
+        rawFinishReason: 'stop',
+      };
+    };
+    const llm = new KosongLLM({
+      provider,
+      modelName: 'test-model',
+      systemPrompt: 'system',
+      generate,
+    });
+
+    const response = await llm.chat({
+      messages: [],
+      tools: [],
+      signal: new AbortController().signal,
+    });
+
+    expect(response.streamTiming).toMatchObject({
+      firstTokenLatencyMs: expect.any(Number),
+      streamDurationMs: expect.any(Number),
+    });
+    expect(response.streamTiming?.firstTokenLatencyMs).toBeGreaterThanOrEqual(0);
+    expect(response.streamTiming?.streamDurationMs).toBeGreaterThanOrEqual(0);
+  });
+});
+
 describe('KosongLLM completion budget', () => {
   it('applies the model context window as the completion cap', async () => {
     let appliedCap: number | undefined;

packages/agent-core/test/agent/turn.test.ts

@@ -686,6 +686,23 @@ describe('Agent turn flow', () => {
     );
   });
 
+  it('emits LLM stream timing on step completion', async () => {
+    const ctx = testAgent();
+    ctx.configure();
+    ctx.mockNextResponse({ type: 'text', text: 'timed answer' });
+
+    await ctx.rpc.prompt({ input: [{ type: 'text', text: 'hello' }] });
+    await ctx.untilTurnEnd();
+
+    const stepCompleted = ctx.allEvents.find(
+      (event) => event.type === '[rpc]' && event.event === 'turn.step.completed',
+    );
+    expect(stepCompleted?.args).toMatchObject({
+      llmFirstTokenLatencyMs: expect.any(Number),
+      llmStreamDurationMs: expect.any(Number),
+    });
+  });
+
   it('logs LLM request metadata without message bodies', async () => {
     const { logger, entries } = captureLogs();
     const ctx = testAgent({ log: logger });

packages/agent-core/test/loop/api-shape.e2e.test.ts

@@ -225,6 +225,8 @@ function _typeOnlyChecks(): void {
     turnId: 't1',
     step: 1,
     finishReason: 'filtered',
+    llmFirstTokenLatencyMs: 10,
+    llmStreamDurationMs: 20,
     providerFinishReason: 'filtered',
     rawFinishReason: 'content_filter',
   };
@@ -498,7 +500,14 @@ function _typeOnlyChecks(): void {
   // LoopEvent is a closed union with the documented variants.
   const _evs: LoopEvent[] = [
     { type: 'step.begin', uuid: 's1', turnId: 't1', step: 1 },
-    { type: 'step.end', uuid: 's1', turnId: 't1', step: 1 },
+    {
+      type: 'step.end',
+      uuid: 's1',
+      turnId: 't1',
+      step: 1,
+      llmFirstTokenLatencyMs: 10,
+      llmStreamDurationMs: 20,
+    },
     {
       type: 'content.part',
       uuid: 'c1',

packages/kosong/src/generate.ts

@@ -103,6 +103,7 @@ export async function generate(
     throwAbortError();
   }
 
+  options?.onRequestStart?.();
   const stream = await provider.generate(systemPrompt, tools, history, options);
 
   // Post-await abort check: `provider.generate()` may have resolved before
@@ -156,6 +157,7 @@ export async function generate(
   }
 
   await throwIfAborted(options?.signal, stream);
+  options?.onStreamEnd?.();
 
   // Flush the last pending part.
   if (pendingPart !== null) {

packages/kosong/src/provider.ts

@@ -98,6 +98,16 @@ export interface GenerateOptions {
    * each request/retry so providers never retain mutable credential state.
    */
   auth?: ProviderRequestAuth;
+  /**
+   * Host-side instrumentation hook fired immediately before invoking the
+   * provider adapter's generate call.
+   */
+  onRequestStart?: () => void;
+  /**
+   * Host-side instrumentation hook fired after the provider stream is fully
+   * drained, before post-processing the assembled response.
+   */
+  onStreamEnd?: () => void;
 }
 
 /**

packages/node-sdk/test/session-event-types.test.ts

@@ -21,6 +21,15 @@ describe('Event public types', () => {
     expectTypeOf<EventByType<'tool.call.started'>['args']>().toEqualTypeOf<unknown>();
   });
 
+  it('exposes LLM stream timing on step completion events', () => {
+    expectTypeOf<EventByType<'turn.step.completed'>['llmFirstTokenLatencyMs']>().toEqualTypeOf<
+      number | undefined
+    >();
+    expectTypeOf<EventByType<'turn.step.completed'>['llmStreamDurationMs']>().toEqualTypeOf<
+      number | undefined
+    >();
+  });
+
   it('narrows subagent lifecycle events by type', () => {
     expectTypeOf<EventByType<'subagent.spawned'>['subagentId']>().toEqualTypeOf<string>();
     expectTypeOf<EventByType<'subagent.spawned'>['runInBackground']>().toEqualTypeOf<boolean>();