feat(timing): split TTFT into api-server and client portions

.changeset/ttft-client-server-split.md

@@ -0,0 +1,5 @@
+---
+"@moonshot-ai/kimi-code": patch
+---
+
+Split LLM streaming timing in the session log and `KIMI_CODE_DEBUG=1` output into client vs. API-server portions, so slow turns can be attributed without parsing the wire log. Time-to-first-token splits into the API-server portion (network + server) and the client portion (in-process request building); the decode window splits into time awaiting tokens from the server and time the client spends processing each streamed chunk.

apps/kimi-code/src/utils/usage/debug-timing.ts

@@ -10,6 +10,20 @@ interface DebugTokenUsage {
 export interface StepTimingInput {
   readonly llmFirstTokenLatencyMs?: number;
   readonly llmStreamDurationMs?: number;
+  /**
+   * Split of `llmFirstTokenLatencyMs` into the client-side request-build
+   * portion (`llmRequestBuildMs`) and the network + API-server portion
+   * (`llmServerFirstTokenMs`). Both present together or not at all.
+   */
+  readonly llmRequestBuildMs?: number;
+  readonly llmServerFirstTokenMs?: number;
+  /**
+   * Split of `llmStreamDurationMs` (the decode window) into server time spent
+   * awaiting parts (`llmServerDecodeMs`) and client time spent processing parts
+   * (`llmClientConsumeMs`). Both present together or not at all.
+   */
+  readonly llmServerDecodeMs?: number;
+  readonly llmClientConsumeMs?: number;
   readonly usage?: DebugTokenUsage;
 }
 
@@ -26,12 +40,14 @@ export function formatStepDebugTiming(input: StepTimingInput): string | undefine
   const streamMs = input.llmStreamDurationMs;
   if (latency === undefined || streamMs === undefined) return undefined;
 
-  const parts: string[] = [`TTFT: ${formatDuration(latency)}`];
+  const parts: string[] = [`TTFT: ${formatTtft(input)}`];
   const outputTokens = input.usage?.output;
   if (outputTokens !== undefined && outputTokens > 0) {
     if (streamMs >= MIN_STREAM_MS_FOR_TPS) {
       const tps = (outputTokens / (streamMs / 1000)).toFixed(1);
-      parts.push(`TPS: ${tps} tok/s (${outputTokens} tokens in ${formatDuration(streamMs)})`);
+      parts.push(
+        `TPS: ${tps} tok/s (${outputTokens} tokens in ${formatDuration(streamMs)}${formatDecodeSplit(input)})`,
+      );
     } else {
       parts.push(
         `${outputTokens} tokens in ${formatDuration(streamMs)} (stream too short for TPS)`,
@@ -65,6 +81,27 @@ function usageInputTotal(usage: DebugTokenUsage | undefined): number {
   return (usage.inputOther ?? 0) + (usage.inputCacheRead ?? 0) + (usage.inputCacheCreation ?? 0);
 }
 
+// Render TTFT, splitting the latency into the network + API-server portion and
+// the in-process request-build portion when the provider reported the
+// boundary. Falls back to the bare total otherwise.
+function formatTtft(input: StepTimingInput): string {
+  const total = formatDuration(input.llmFirstTokenLatencyMs ?? 0);
+  const build = input.llmRequestBuildMs;
+  const server = input.llmServerFirstTokenMs;
+  if (build === undefined || server === undefined) return total;
+  return `${total} (api ${formatDuration(server)} + client ${formatDuration(build)})`;
+}
+
+// Render the decode-window split as a trailing clause, e.g.
+// `; server 4.6s + client 0.4s`. A large client share means the host's per-part
+// processing is throttling decode. Empty when the provider did not report it.
+function formatDecodeSplit(input: StepTimingInput): string {
+  const server = input.llmServerDecodeMs;
+  const client = input.llmClientConsumeMs;
+  if (server === undefined || client === undefined) return '';
+  return `; server ${formatDuration(server)} + client ${formatDuration(client)}`;
+}
+
 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

@@ -89,6 +89,52 @@ describe('formatStepDebugTiming', () => {
     expect(result).toContain('900ms');
   });
 
+  it('splits TTFT into api-server and client portions when both are present', () => {
+    const result = formatStepDebugTiming({
+      llmFirstTokenLatencyMs: 2500,
+      llmStreamDurationMs: 5000,
+      llmServerFirstTokenMs: 2400,
+      llmRequestBuildMs: 100,
+      usage: { output: 200 },
+    });
+    expect(result).toBe(
+      '[Debug] TTFT: 2.5s (api 2.4s + client 100ms) | TPS: 40.0 tok/s (200 tokens in 5.0s)',
+    );
+  });
+
+  it('falls back to the bare TTFT when only one split component is present', () => {
+    const result = formatStepDebugTiming({
+      llmFirstTokenLatencyMs: 800,
+      llmStreamDurationMs: 5000,
+      llmServerFirstTokenMs: 700,
+      usage: { output: 0 },
+    });
+    expect(result).toBe('[Debug] TTFT: 800ms');
+  });
+
+  it('appends the decode wait/consume split to the TPS clause', () => {
+    const result = formatStepDebugTiming({
+      llmFirstTokenLatencyMs: 800,
+      llmStreamDurationMs: 5000,
+      llmServerDecodeMs: 4600,
+      llmClientConsumeMs: 400,
+      usage: { output: 200 },
+    });
+    expect(result).toBe(
+      '[Debug] TTFT: 800ms | TPS: 40.0 tok/s (200 tokens in 5.0s; server 4.6s + client 400ms)',
+    );
+  });
+
+  it('omits the decode split when only one component is present', () => {
+    const result = formatStepDebugTiming({
+      llmFirstTokenLatencyMs: 800,
+      llmStreamDurationMs: 5000,
+      llmServerDecodeMs: 4600,
+      usage: { output: 200 },
+    });
+    expect(result).toBe('[Debug] TTFT: 800ms | TPS: 40.0 tok/s (200 tokens in 5.0s)');
+  });
+
   it('formats durations at or above 1s as seconds', () => {
     const result = formatStepDebugTiming({
       llmFirstTokenLatencyMs: 1500,

apps/vis/web/src/components/analysis/TimelineTab.tsx

@@ -290,7 +290,27 @@ function StepRow({ step, turnDurationMs }: { step: StepNode; turnDurationMs?: nu
         ) : null}
         <span className="text-fg-3 tabular" title="step wall-clock duration">{formatDuration(step.durationMs)}</span>
         {step.llmFirstTokenLatencyMs !== undefined ? (
-          <span className="text-fg-3 tabular" title="time to first token">ttft {step.llmFirstTokenLatencyMs}ms</span>
+          <span
+            className="text-fg-3 tabular"
+            title={
+              step.llmServerFirstTokenMs !== undefined && step.llmRequestBuildMs !== undefined
+                ? `time to first token (api ${step.llmServerFirstTokenMs}ms + client ${step.llmRequestBuildMs}ms)`
+                : 'time to first token'
+            }
+          >
+            ttft {step.llmFirstTokenLatencyMs}ms
+            {step.llmServerFirstTokenMs !== undefined && step.llmRequestBuildMs !== undefined
+              ? ` (api ${step.llmServerFirstTokenMs} + client ${step.llmRequestBuildMs})`
+              : ''}
+          </span>
+        ) : null}
+        {step.llmServerDecodeMs !== undefined && step.llmClientConsumeMs !== undefined ? (
+          <span
+            className="text-fg-3 tabular"
+            title="decode window split (server awaiting parts + client processing parts)"
+          >
+            decode {step.llmServerDecodeMs}+{step.llmClientConsumeMs}ms
+          </span>
         ) : null}
         {step.contextTokens !== undefined ? (
           <span className="text-fg-3 tabular" title="context-window fill after step">ctx {formatTokens(step.contextTokens)}</span>

apps/vis/web/src/components/wire/parts.tsx

@@ -362,11 +362,31 @@ export function LoopEventDetail({ event }: { event: LoopRecordedEvent }) {
                 <span className="text-fg-1">{event.llmFirstTokenLatencyMs} ms</span>
               </FieldRow>
             ) : null}
+            {event.llmServerFirstTokenMs !== undefined ? (
+              <FieldRow label="firstToken/api">
+                <span className="text-fg-1">{event.llmServerFirstTokenMs} ms</span>
+              </FieldRow>
+            ) : null}
+            {event.llmRequestBuildMs !== undefined ? (
+              <FieldRow label="firstToken/client">
+                <span className="text-fg-1">{event.llmRequestBuildMs} ms</span>
+              </FieldRow>
+            ) : null}
             {event.llmStreamDurationMs !== undefined ? (
               <FieldRow label="streamDuration">
                 <span className="text-fg-1">{event.llmStreamDurationMs} ms</span>
               </FieldRow>
             ) : null}
+            {event.llmServerDecodeMs !== undefined ? (
+              <FieldRow label="streamDuration/server">
+                <span className="text-fg-1">{event.llmServerDecodeMs} ms</span>
+              </FieldRow>
+            ) : null}
+            {event.llmClientConsumeMs !== undefined ? (
+              <FieldRow label="streamDuration/client">
+                <span className="text-fg-1">{event.llmClientConsumeMs} ms</span>
+              </FieldRow>
+            ) : null}
           </div>
           {usage !== undefined ? (
             <div>

apps/vis/web/src/lib/analysis.ts

@@ -54,6 +54,12 @@ export interface StepNode {
   contextTokens?: number;
   llmFirstTokenLatencyMs?: number;
   llmStreamDurationMs?: number;
+  /** TTFT split: client-side request-build vs. network + API-server time. */
+  llmRequestBuildMs?: number;
+  llmServerFirstTokenMs?: number;
+  /** Decode split: server time awaiting parts vs. client time processing them. */
+  llmServerDecodeMs?: number;
+  llmClientConsumeMs?: number;
   content: ContentSummary;
   toolCalls: ToolCallNode[];
 }
@@ -317,6 +323,10 @@ export function analyzeWire(entries: readonly WireEntry[]): Analysis {
             step.finishReason = ev.finishReason;
             step.llmFirstTokenLatencyMs = ev.llmFirstTokenLatencyMs;
             step.llmStreamDurationMs = ev.llmStreamDurationMs;
+            step.llmRequestBuildMs = ev.llmRequestBuildMs;
+            step.llmServerFirstTokenMs = ev.llmServerFirstTokenMs;
+            step.llmServerDecodeMs = ev.llmServerDecodeMs;
+            step.llmClientConsumeMs = ev.llmClientConsumeMs;
             if (step.beginTime !== undefined && t !== undefined) step.durationMs = t - step.beginTime;
             // Steps don't carry a generic 'error' finish reason (errors are
             // thrown, not recorded). 'filtered' means the provider blocked the

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

@@ -997,6 +997,10 @@ function mapLoopEvent(event: LoopEvent, turnId: number): AgentEvent | undefined
         finishReason: event.finishReason,
         llmFirstTokenLatencyMs: event.llmFirstTokenLatencyMs,
         llmStreamDurationMs: event.llmStreamDurationMs,
+        llmRequestBuildMs: event.llmRequestBuildMs,
+        llmServerFirstTokenMs: event.llmServerFirstTokenMs,
+        llmServerDecodeMs: event.llmServerDecodeMs,
+        llmClientConsumeMs: event.llmClientConsumeMs,
         providerFinishReason: event.providerFinishReason,
         rawFinishReason: event.rawFinishReason,
       };

packages/agent-core/src/agent/turn/kosong-llm.ts

@@ -25,6 +25,7 @@ import {
   type GenerateCallbacks,
   type Message,
   type ModelCapability,
+  type StreamDecodeStats,
   type StreamedMessagePart,
 } from '@moonshot-ai/kosong';
 
@@ -87,13 +88,19 @@ export class KosongLLM implements LLM {
 
   async chat(params: LLMChatParams): Promise<LLMChatResponse> {
     let requestStartedAt = Date.now();
+    let requestSentAt: number | undefined;
     let firstChunkAt: number | undefined;
     let streamEndedAt: number | undefined;
+    let decodeStats: StreamDecodeStats | undefined;
     const markRequestStart = (): void => {
       requestStartedAt = Date.now();
     };
-    const markStreamEnd = (): void => {
+    const markRequestSent = (): void => {
+      requestSentAt ??= Date.now();
+    };
+    const markStreamEnd = (stats?: StreamDecodeStats): void => {
       streamEndedAt = Date.now();
+      decodeStats = stats;
     };
     const markStreamOutput = (): void => {
       firstChunkAt ??= Date.now();
@@ -113,6 +120,7 @@ export class KosongLLM implements LLM {
     const options: GenerateOptionsWithRequestLogFields = {
       signal: params.signal,
       onRequestStart: markRequestStart,
+      onRequestSent: markRequestSent,
       onStreamEnd: markStreamEnd,
       requestLogFields: params.requestLogFields,
     };
@@ -147,7 +155,7 @@ export class KosongLLM implements LLM {
       streamTiming:
         firstChunkAt === undefined
           ? undefined
-          : buildStreamTiming(requestStartedAt, firstChunkAt, streamEndedAt),
+          : buildStreamTiming(requestStartedAt, requestSentAt, firstChunkAt, streamEndedAt, decodeStats),
     };
 
     return response;
@@ -160,14 +168,34 @@ export class KosongLLM implements LLM {
 
 function buildStreamTiming(
   requestStartedAt: number,
+  requestSentAt: number | undefined,
   firstChunkAt: number,
   streamEndedAt: number | undefined,
+  decodeStats: StreamDecodeStats | undefined,
 ): LLMStreamTiming {
   const outputEndedAt = streamEndedAt ?? Date.now();
-  return {
-    firstTokenLatencyMs: Math.max(0, firstChunkAt - requestStartedAt),
+  const firstTokenLatencyMs = Math.max(0, firstChunkAt - requestStartedAt);
+  const timing: {
+    -readonly [K in keyof LLMStreamTiming]: LLMStreamTiming[K];
+  } = {
+    firstTokenLatencyMs,
     streamDurationMs: Math.max(0, outputEndedAt - firstChunkAt),
   };
+  // Split TTFT across the request-dispatch boundary when the provider reported
+  // it. Clamp `requestSentAt` into [requestStartedAt, firstChunkAt] so a stray
+  // clock reading can never produce a negative or over-long component.
+  if (requestSentAt !== undefined) {
+    const sentAt = Math.min(Math.max(requestSentAt, requestStartedAt), firstChunkAt);
+    timing.requestBuildMs = sentAt - requestStartedAt;
+    timing.serverFirstTokenMs = firstChunkAt - sentAt;
+  }
+  // Split the decode window into server (awaiting parts) vs. client (processing
+  // parts) time, as accounted by the stream loop.
+  if (decodeStats !== undefined) {
+    timing.serverDecodeMs = Math.max(0, decodeStats.serverDecodeMs);
+    timing.clientConsumeMs = Math.max(0, decodeStats.clientConsumeMs);
+  }
+  return timing;
 }
 
 function buildKosongCallbacks(

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

@@ -21,6 +21,20 @@ export interface LoopStepEndEvent {
   readonly finishReason?: LoopStepStopReason | undefined;
   readonly llmFirstTokenLatencyMs?: number | undefined;
   readonly llmStreamDurationMs?: number | undefined;
+  /**
+   * Split of `llmFirstTokenLatencyMs`: in-process request-building time on the
+   * client vs. network + API-server time to the first token. Both `undefined`
+   * when the provider does not report the client/server boundary.
+   */
+  readonly llmRequestBuildMs?: number | undefined;
+  readonly llmServerFirstTokenMs?: number | undefined;
+  /**
+   * Split of `llmStreamDurationMs` (the decode window): time awaiting parts
+   * from the provider vs. time processing parts in-process. Both `undefined`
+   * when the provider stream did not report decode accounting.
+   */
+  readonly llmServerDecodeMs?: number | undefined;
+  readonly llmClientConsumeMs?: number | undefined;
   /**
    * Provider diagnostics are optional and must not drive loop control.
    * Use `finishReason` for normalized behavior.

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

@@ -31,6 +31,27 @@ export interface LLMRequestLogFields {
 export interface LLMStreamTiming {
   readonly firstTokenLatencyMs: number;
   readonly streamDurationMs: number;
+  /**
+   * Portion of `firstTokenLatencyMs` spent in-process building the request
+   * (message serialization, param assembly) before the provider dispatched the
+   * network call. `undefined` when the provider does not report the
+   * client/server boundary (no `onRequestSent`).
+   */
+  readonly requestBuildMs?: number;
+  /**
+   * Portion of `firstTokenLatencyMs` spent waiting on the network + API server
+   * from request dispatch to the first streamed token. `undefined` when the
+   * provider does not report the client/server boundary.
+   */
+  readonly serverFirstTokenMs?: number;
+  /**
+   * Split of `streamDurationMs` (the decode window): time spent awaiting parts
+   * from the provider (`serverDecodeMs`, server + network) vs. time spent
+   * processing parts in-process (`clientConsumeMs`, host callbacks / merge).
+   * `undefined` when the provider stream did not report decode accounting.
+   */
+  readonly serverDecodeMs?: number;
+  readonly clientConsumeMs?: number;
 }
 
 export interface LLMChatParams {