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

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

@@ -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.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/streamContentDetection.test.ts

@@ -0,0 +1,131 @@
+/**
+ * @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 with thought: true', () => {
+    expect(hasUserVisibleContent(chunkWithParts([{ thought: true }]))).toBe(
+      true,
+    );
+  });
+
+  it('returns false for thought: false (explicit non-thought part)', () => {
+    // Codebase convention: `thought` is a boolean flag where false means
+    // "explicitly not a thought." A part with only `thought: false` and no
+    // other content must not trigger TTFT.
+    expect(hasUserVisibleContent(chunkWithParts([{ thought: false }]))).toBe(
+      false,
+    );
+  });
+
+  it('returns false for thought: undefined / missing (default non-thought)', () => {
+    // A bare object without the `thought` key is the common case for non-thinking
+    // chunks; must not match the thought branch.
+    expect(hasUserVisibleContent(chunkWithParts([{}]))).toBe(false);
+  });
+
+  it('returns true when thought: true coexists with empty text', () => {
+    // First Anthropic <thinking> chunk often arrives as { text: '', thought: true }.
+    // Per design doc D1, "thought / reasoning content" is user-visible — TTFT fires.
+    expect(
+      hasUserVisibleContent(chunkWithParts([{ text: '', 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,
+    );
+  });
+});