feat(telemetry): Phase 4a — TTFT capture + GenAI semconv dual-emit (QwenLM#3731)

Adds time-to-first-token measurement and OTel GenAI semantic convention
dual-emit to the qwen-code.llm_request span. First slice of Phase 4 LLM
request timing decomposition (sub-issue QwenLM#4413).

Builds on Phase 1 (QwenLM#4126), Phase 1.5 (QwenLM#4302), Phase 2 (QwenLM#4321). Self-contained
— ships TTFT visibility without depending on the Phase 4b retry-callback work.

Changes
-------

- New hasUserVisibleContent(chunk) helper centralizes "is this chunk first
  user-visible output" detection across all 4 providers. Operates on the
  normalized GenerateContentResponse shape each provider emits before
  LoggingContentGenerator sees the stream. Recognizes text / functionCall /
  inlineData / executableCode / thought parts; skips role-only and
  usageMetadata-only chunks.

- TTFT capture in LoggingContentGenerator.generateContentStream's stream
  wrapper. Method-local closure variable, NEVER instance field — the
  generator is one-per-ContentGenerator and shared across concurrent calls
  (subagent fan-out, warmup, side-queries).

- Extends LLMRequestMetadata with: ttftMs, requestSetupMs, attempt,
  retryTotalDelayMs, cachedInputTokens. The first is populated in 4a; the
  middle three are declared as optional so Phase 4b's retry callback can
  populate them without touching the schema again.

- endLLMRequestSpan writes new span attrs: ttft_ms, sampling_ms (derived:
  duration - ttft - requestSetup, clamped to >= 0), output_tokens_per_second
  (derived: outputTokens / (sampling_ms / 1000), omitted when sampling_ms == 0
  to avoid divide-by-zero, rounded to 2 decimals), cached_input_tokens,
  plus Phase 4b placeholders (attempt, request_setup_ms, retry_total_delay_ms)
  when caller provides them.

- GenAI semconv dual-emit. Private qwen-code names stay authoritative
  (dashboards, SLOs, ARMS queries reference these); semconv is a compat
  layer for spec-aware backends. Same pattern as Phase 3 (QwenLM#4410):
    qwen-code.model            + gen_ai.request.model            (Stable)
    input_tokens               + gen_ai.usage.input_tokens       (Stable)
    output_tokens              + gen_ai.usage.output_tokens      (Stable)
    cached_input_tokens        + gen_ai.usage.cached_tokens      (Experimental)
    ttft_ms (ms, int)          + gen_ai.server.time_to_first_token
                                 (s, double, Experimental)

TTFT semantic intentionally diverges from claude-code's ttftMs (which fires
on Anthropic's message_start metadata event). qwen-code measures "first
user-visible content" — uniform across Anthropic / OpenAI / Gemini / Qwen,
matches the literal "first token" intent. See design doc D1 for rationale.

Design doc
----------

docs/design/telemetry-llm-request-timing-design.md (~530 lines) covers all
7 locked decisions with "Why not X" justifications, lifecycle wiring for
streaming + non-streaming + 4 retry sites, files-to-change table with LOC
estimates, test strategy, edge cases, rollback plan, and a comparison with
claude-code (full decomposition but only for Perfetto) and opencode
(no TTFT measurement at all).

Tests
-----

- streamContentDetection.test.ts (13 tests) covers part types matrix.
- session-tracing.test.ts +16 tests (new describe block) cover dual-emit
  for every gen_ai.* field, sampling_ms clamping at 0 for clock skew,
  output_tokens_per_second rounding + divide-by-zero, Phase 4b
  placeholder fields written when present, absent when not.
- loggingContentGenerator.test.ts +4 tests cover TTFT capture in
  streaming, undefined when stream yields only metadata chunks, and
  cachedInputTokens forwarding from usageMetadata on both stream and
  non-stream paths.

All 448 telemetry tests pass, tsc --noEmit clean, eslint clean.

Phase 4b (retry callback + ApiRetryEvent) and Phase 4c
(recordApiRequestBreakdown activation) follow in separate PRs per the
design doc split.

🤖 Generated with [Qwen Code](https://github.com/QwenLM/qwen-code)

Author: doudouOUC

docs/design/telemetry-llm-request-timing-design.md

@@ -165,6 +165,11 @@ vi.mock('../../telemetry/index.js', () => {
           success: boolean;
           inputTokens?: number;
           outputTokens?: number;
+          cachedInputTokens?: number;
+          ttftMs?: number;
+          requestSetupMs?: number;
+          attempt?: number;
+          retryTotalDelayMs?: number;
           durationMs?: number;
           error?: string;
         },
@@ -616,6 +621,150 @@ describe('LoggingContentGenerator', () => {
     });
   });
 
+  it('captures ttftMs on the first user-visible stream chunk (Phase 4a)', async () => {
+    // Two chunks: first has text (user-visible), second has only usage.
+    // ttftMs must be set on the first chunk and not overwritten by the second.
+    const streamFn = vi.fn().mockResolvedValue(
+      (async function* () {
+        yield createResponse('r1', 'test-model', [{ text: 'hi' }]);
+        yield createResponse('r2', 'test-model', [], {
+          promptTokenCount: 10,
+          candidatesTokenCount: 2,
+          totalTokenCount: 12,
+        });
+      })(),
+    );
+    const wrapped = createWrappedGenerator(vi.fn(), streamFn);
+    const generator = new LoggingContentGenerator(wrapped, createConfig(), {
+      model: 'test-model',
+      authType: AuthType.USE_OPENAI,
+      enableOpenAILogging: false,
+    });
+    const request = {
+      model: 'test-model',
+      contents: 'Hello',
+    } as unknown as GenerateContentParameters;
+
+    const stream = await generator.generateContentStream(
+      request,
+      'prompt-ttft',
+    );
+    for await (const _ of stream) {
+      // consume
+    }
+
+    const spanRecord = getStreamSpanRecord();
+    const meta = spanRecord.endMetadata as { ttftMs?: number } | undefined;
+    expect(meta).toBeDefined();
+    expect(typeof meta!.ttftMs).toBe('number');
+    expect(meta!.ttftMs!).toBeGreaterThanOrEqual(0);
+  });
+
+  it('forwards cachedInputTokens from usageMetadata to endLLMRequestSpan (Phase 4a)', async () => {
+    const streamFn = vi.fn().mockResolvedValue(
+      (async function* () {
+        yield createResponse('r1', 'test-model', [{ text: 'ok' }], {
+          promptTokenCount: 100,
+          candidatesTokenCount: 20,
+          cachedContentTokenCount: 40,
+          totalTokenCount: 160,
+        });
+      })(),
+    );
+    const wrapped = createWrappedGenerator(vi.fn(), streamFn);
+    const generator = new LoggingContentGenerator(wrapped, createConfig(), {
+      model: 'test-model',
+      authType: AuthType.USE_OPENAI,
+      enableOpenAILogging: false,
+    });
+    const request = {
+      model: 'test-model',
+      contents: 'Hello',
+    } as unknown as GenerateContentParameters;
+
+    const stream = await generator.generateContentStream(
+      request,
+      'prompt-cache',
+    );
+    for await (const _ of stream) {
+      // consume
+    }
+
+    const spanRecord = getStreamSpanRecord();
+    expect(spanRecord.endMetadata).toMatchObject({
+      success: true,
+      inputTokens: 100,
+      cachedInputTokens: 40,
+    });
+  });
+
+  it('leaves ttftMs undefined when stream yields no user-visible chunks (Phase 4a)', async () => {
+    // Stream emits only usage-metadata chunks (no text/functionCall/etc).
+    // ttftMs must stay undefined — TTFT is only meaningful when content arrives.
+    const streamFn = vi.fn().mockResolvedValue(
+      (async function* () {
+        yield createResponse('r1', 'test-model', [], {
+          promptTokenCount: 5,
+          candidatesTokenCount: 0,
+          totalTokenCount: 5,
+        });
+      })(),
+    );
+    const wrapped = createWrappedGenerator(vi.fn(), streamFn);
+    const generator = new LoggingContentGenerator(wrapped, createConfig(), {
+      model: 'test-model',
+      authType: AuthType.USE_OPENAI,
+      enableOpenAILogging: false,
+    });
+    const request = {
+      model: 'test-model',
+      contents: 'Hello',
+    } as unknown as GenerateContentParameters;
+
+    const stream = await generator.generateContentStream(
+      request,
+      'prompt-no-content',
+    );
+    for await (const _ of stream) {
+      // consume
+    }
+
+    const spanRecord = getStreamSpanRecord();
+    const meta = spanRecord.endMetadata as { ttftMs?: number } | undefined;
+    expect(meta!.ttftMs).toBeUndefined();
+  });
+
+  it('forwards cachedInputTokens to endLLMRequestSpan on non-stream success (Phase 4a)', async () => {
+    const generateFn = vi.fn().mockResolvedValue(
+      createResponse('resp-cache', 'test-model', [{ text: 'ok' }], {
+        promptTokenCount: 100,
+        candidatesTokenCount: 30,
+        cachedContentTokenCount: 60,
+        totalTokenCount: 190,
+      }),
+    );
+    const wrapped = createWrappedGenerator(generateFn, vi.fn());
+    const generator = new LoggingContentGenerator(wrapped, createConfig(), {
+      model: 'test-model',
+      authType: AuthType.USE_OPENAI,
+      enableOpenAILogging: false,
+    });
+    const request = {
+      model: 'test-model',
+      contents: 'Hi',
+    } as unknown as GenerateContentParameters;
+
+    await generator.generateContent(request, 'prompt-cache-non-stream');
+
+    const spanRecord = getGenerateContentSpanRecord();
+    expect(spanRecord.endMetadata).toMatchObject({
+      success: true,
+      inputTokens: 100,
+      outputTokens: 30,
+      cachedInputTokens: 60,
+    });
+  });
+
   it('preserves non-stream success when response and OpenAI logging fail', async () => {
     vi.mocked(logApiResponse).mockImplementationOnce(() => {
       throw new Error('response-log-fail');

packages/core/src/core/loggingContentGenerator/loggingContentGenerator.test.ts

@@ -61,6 +61,7 @@ import {
   API_CALL_ABORTED_SPAN_STATUS_MESSAGE,
   API_CALL_FAILED_SPAN_STATUS_MESSAGE,
 } from '../../telemetry/tracer.js';
+import { hasUserVisibleContent } from './streamContentDetection.js';
 
 const debugLogger = createDebugLogger('LOGGING_CONTENT_GENERATOR');
 
@@ -285,6 +286,7 @@ export class LoggingContentGenerator implements ContentGenerator {
         success: true,
         inputTokens: response.usageMetadata?.promptTokenCount,
         outputTokens: response.usageMetadata?.candidatesTokenCount,
+        cachedInputTokens: response.usageMetadata?.cachedContentTokenCount,
         durationMs: Date.now() - startTime,
       });
       return response;
@@ -462,6 +464,14 @@ export class LoggingContentGenerator implements ContentGenerator {
     let firstModelVersion = '';
     let lastUsageMetadata: GenerateContentResponseUsageMetadata | undefined;
     let errorOccurred = false;
+
+    // TTFT (time to first token): wall-clock from generateContentStream
+    // dispatch to the first stream chunk containing user-visible content.
+    // Method-local closure variable — NEVER an instance field — because
+    // LoggingContentGenerator is shared across concurrent generateContentStream
+    // calls (one per ContentGenerator, see contentGenerator.ts:createContentGenerator).
+    // See docs/design/telemetry-llm-request-timing-design.md (D1, D2).
+    let ttftMs: number | undefined;
     // Tracks whether the idle timeout fired and ended the span. If so,
     // a resumed-after-timeout consumer must not call endLLMRequestSpan
     // again (the helper would no-op, but more importantly we skip the
@@ -516,6 +526,13 @@ export class LoggingContentGenerator implements ContentGenerator {
         if (response.usageMetadata) {
           lastUsageMetadata = response.usageMetadata;
         }
+        // Capture TTFT on the first stream chunk that contains user-visible
+        // content. hasUserVisibleContent skips role-only / usageMetadata-only
+        // chunks, so TTFT reflects "model produced something the operator can
+        // attribute to user-perceived latency."
+        if (ttftMs === undefined && hasUserVisibleContent(response)) {
+          ttftMs = Date.now() - startTime;
+        }
         resetSpanTimeout?.();
         yield response;
       }
@@ -601,6 +618,8 @@ export class LoggingContentGenerator implements ContentGenerator {
           success: !errorOccurred,
           inputTokens: lastUsageMetadata?.promptTokenCount,
           outputTokens: lastUsageMetadata?.candidatesTokenCount,
+          cachedInputTokens: lastUsageMetadata?.cachedContentTokenCount,
+          ttftMs,
           durationMs: Date.now() - startTime,
           error: errorOccurred
             ? aborted

packages/core/src/core/loggingContentGenerator/loggingContentGenerator.ts

@@ -0,0 +1,108 @@
+/**
+ * @license
+ * Copyright 2026 Qwen Team
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import { describe, expect, it } from 'vitest';
+import { GenerateContentResponse } from '@google/genai';
+import { hasUserVisibleContent } from './streamContentDetection.js';
+
+function chunkWithParts(parts: unknown[]): GenerateContentResponse {
+  const r = new GenerateContentResponse();
+  r.candidates = [
+    {
+      content: { role: 'model', parts: parts as never },
+    },
+  ];
+  return r;
+}
+
+describe('hasUserVisibleContent', () => {
+  it('returns true for non-empty text part', () => {
+    expect(hasUserVisibleContent(chunkWithParts([{ text: 'hi' }]))).toBe(true);
+  });
+
+  it('returns false for empty text part', () => {
+    expect(hasUserVisibleContent(chunkWithParts([{ text: '' }]))).toBe(false);
+  });
+
+  it('returns true for functionCall part', () => {
+    expect(
+      hasUserVisibleContent(
+        chunkWithParts([{ functionCall: { name: 'read', args: {} } }]),
+      ),
+    ).toBe(true);
+  });
+
+  it('returns true for inlineData part', () => {
+    expect(
+      hasUserVisibleContent(
+        chunkWithParts([
+          { inlineData: { mimeType: 'image/png', data: 'abc' } },
+        ]),
+      ),
+    ).toBe(true);
+  });
+
+  it('returns true for executableCode part', () => {
+    expect(
+      hasUserVisibleContent(
+        chunkWithParts([
+          { executableCode: { language: 'PYTHON', code: 'print(1)' } },
+        ]),
+      ),
+    ).toBe(true);
+  });
+
+  it('returns true for thought / reasoning part', () => {
+    expect(hasUserVisibleContent(chunkWithParts([{ thought: true }]))).toBe(
+      true,
+    );
+  });
+
+  it('returns true when any part is user-visible (mixed)', () => {
+    expect(
+      hasUserVisibleContent(chunkWithParts([{ text: '' }, { text: 'hi' }])),
+    ).toBe(true);
+  });
+
+  it('returns false for empty parts array', () => {
+    expect(hasUserVisibleContent(chunkWithParts([]))).toBe(false);
+  });
+
+  it('returns false when candidates is missing', () => {
+    const r = new GenerateContentResponse();
+    expect(hasUserVisibleContent(r)).toBe(false);
+  });
+
+  it('returns false when content is missing', () => {
+    const r = new GenerateContentResponse();
+    r.candidates = [{}];
+    expect(hasUserVisibleContent(r)).toBe(false);
+  });
+
+  it('returns false when parts is undefined', () => {
+    const r = new GenerateContentResponse();
+    r.candidates = [{ content: { role: 'model' } }];
+    expect(hasUserVisibleContent(r)).toBe(false);
+  });
+
+  it('returns false for usage-only / role-only chunks', () => {
+    const r = new GenerateContentResponse();
+    r.candidates = [{ content: { role: 'model', parts: [] } }];
+    r.usageMetadata = { totalTokenCount: 42 };
+    expect(hasUserVisibleContent(r)).toBe(false);
+  });
+
+  it('handles parts that are non-objects defensively', () => {
+    expect(
+      hasUserVisibleContent(
+        chunkWithParts([null, undefined, 'string', 42, { text: 'real' }]),
+      ),
+    ).toBe(true);
+    expect(hasUserVisibleContent(chunkWithParts([null, undefined, 'x']))).toBe(
+      false,
+    );
+  });
+});

packages/core/src/core/loggingContentGenerator/streamContentDetection.test.ts

@@ -0,0 +1,54 @@
+/**
+ * @license
+ * Copyright 2026 Qwen Team
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import type { GenerateContentResponse } from '@google/genai';
+
+/**
+ * Detects whether a streaming chunk contains user-visible model output.
+ *
+ * Used by the LoggingContentGenerator stream wrapper to identify the first
+ * chunk that should trigger TTFT (time-to-first-token) measurement.
+ *
+ * A chunk is "user-visible" if any normalized Part in candidates[0].content.parts
+ * is one of:
+ *   - text with a non-empty string
+ *   - functionCall (tool use — even tool-call-only responses count)
+ *   - inlineData (image, binary blob)
+ *   - executableCode (sandbox / code-execution responses)
+ *   - thought / reasoning content (provider-dependent; o1, qwen thinking, Anthropic <thinking>)
+ *
+ * Chunks containing only role metadata, only usageMetadata (final summary
+ * chunk), or empty parts are NOT user-visible — TTFT should not fire on these.
+ *
+ * Centralised here (single predicate over the normalized GenerateContentResponse
+ * shape) so the four provider generators (Anthropic / OpenAI / Gemini / Qwen)
+ * don't each need their own first-token logic. Each provider already normalizes
+ * its native chunk shape to GenerateContentResponse before LoggingContentGenerator
+ * sees it (see loggingContentGenerator.ts generateContentStream).
+ */
+export function hasUserVisibleContent(chunk: GenerateContentResponse): boolean {
+  const parts = chunk.candidates?.[0]?.content?.parts;
+  if (!parts || parts.length === 0) return false;
+  return parts.some(isUserVisiblePart);
+}
+
+function isUserVisiblePart(part: unknown): boolean {
+  if (part === null || typeof part !== 'object') return false;
+  const p = part as {
+    text?: unknown;
+    functionCall?: unknown;
+    inlineData?: unknown;
+    executableCode?: unknown;
+    thought?: unknown;
+  };
+  if (typeof p.text === 'string' && p.text.length > 0) return true;
+  if (p.functionCall !== undefined) return true;
+  if (p.inlineData !== undefined) return true;
+  if (p.executableCode !== undefined) return true;
+  // `thought` is provider-dependent and not always present on Part — guard with `in` to be safe.
+  if (p.thought !== undefined) return true;
+  return false;
+}