LLM-Request-Timing-Zerlegung – Design (P3 Phase 4)

// loggingContentGenerator.ts — inside generateContentStream
const attemptStart = Date.now(); // per-call local
const requestEntryTime = Date.now(); // also per-call local — see D3
let ttftMs: number | undefined;
const attemptStartTimes: number[] = [attemptStart];
let retryTotalDelayMs = 0;
let finalAttempt = 1;
// stream wrapper inspects each chunk; first one matching hasUserVisibleContent:
//   ttftMs = Date.now() - attemptStart;

function hasUserVisibleContent(chunk: GenerateContentResponse): boolean {
  const parts = chunk.candidates?.[0]?.content?.parts;
  if (!parts?.length) return false;
  return parts.some(
    (p) =>
      (typeof p.text === 'string' && p.text.length > 0) ||
      p.functionCall !== undefined ||
      p.inlineData !== undefined ||
      p.executableCode !== undefined ||
      // @ts-expect-error — `thought` is not on all SDK versions but providers emit it
      p.thought !== undefined,
  );
}

request_setup_ms = attemptStart_of_successful_attempt - requestEntryTime;

// utils/retry.ts
interface RetryOptions<T> {
  // ... existing fields ...
  /**
   * Optional. Wird einmal pro fehlgeschlagenem Versuch aufgerufen, vor dem Backoff-Sleep.
   * Erhält die Versuchsnummer (1-basiert), den Fehler und die Verzögerung vor
   * dem nächsten Versuch. Verwenden Sie dies, um Telemetrieereignisse für LLM-Aufrufstellen zu senden;
   * für Nicht-LLM-Aufrufer (z. B. channels/weixin) undefiniert lassen, damit diese
   * in LLM-spezifischen Telemetriekanälen still bleiben.
   */
  onRetry?: (info: RetryAttemptInfo) => void;
}
 
interface RetryAttemptInfo {
  attempt: number; // 1‑based, entspricht debugLogger‑Ausgabe
  error: unknown;
  errorStatus?: number;
  delayMs: number; // Verzögerung vor dem nächsten Versuch
}

// types.ts — new event class, sibling to ContentRetryEvent
export class ApiRetryEvent implements BaseTelemetryEvent {
  'event.name': typeof EVENT_API_RETRY;
  'event.timestamp': string;
  model: string;
  prompt_id?: string;
  attempt_number: number; // 1-based
  error_type: string;
  error_message: string; // truncated to 256 chars
  status_code?: number;
  retry_delay_ms: number;
  // ... duration_ms set to retry_delay_ms so LogToSpanProcessor renders
  // a bridge span of meaningful width
  duration_ms: number;
}

recordApiRequestBreakdown(config, model, [
  { phase: ApiRequestPhase.REQUEST_PREPARATION, durationMs: requestSetupMs },
  { phase: ApiRequestPhase.NETWORK_LATENCY, durationMs: ttftMs }, // ttftMs = network + first-token-generation
  { phase: ApiRequestPhase.RESPONSE_PROCESSING, durationMs: samplingMs },
]);

// session-tracing.ts — endLLMRequestSpan
const llmCtx = activeSpans.get(spanRef);
if (!llmCtx) return;            // bereits beendet – Double-End-Guard
activeSpans.delete(spanRef);    // Ende beanspruchen
 
// ... Dauer berechnen, Attribute setzen ...
if (metadata) {
  recordApiRequestBreakdown(config, llmCtx.attributes.model, [...]);   // NEU – geschützt
  recordTokenUsageMetrics(...); // vorhanden
}
 
span.end();

// session-tracing.ts — LLMRequestMetadata interface extended (additive)
export interface LLMRequestMetadata {
  // ... vorhandene Felder: inputTokens, outputTokens, cachedInputTokens, success, error, ...
 
  /** Zeit vom Start des erfolgreichen Versuchs bis zum ersten sichtbaren Inhalts-Chunk (ms). Undefiniert für Nicht-Streaming- oder vor dem ersten Chunk abgebrochene Anfragen. */
  ttftMs?: number;
 
  /** Zeit vom Eintritt in generateContent bis zum Start des erfolgreichen Versuchs (ms). Beinhaltet alle fehlgeschlagenen Retrys + Backoff. */
  requestSetupMs?: number;
 
  /** Letzte Versuchsnummer (1-basiert). 1 = keine Retrys. */
  attempt?: number;
 
  /** Summe aller Backoff-Verzögerungen vor dem erfolgreichen Versuch (ms). */
  retryTotalDelayMs?: number;
}
 
// Keine neuen exportierten Hilfsfunktionen – Phase 4 verwendet startLLMRequestSpan / endLLMRequestSpan mit erweiterten Metadaten.

// types.ts — new event class
export class ApiRetryEvent implements BaseTelemetryEvent {
  'event.name': typeof EVENT_API_RETRY = EVENT_API_RETRY;
  'event.timestamp': string;
  model: string;
  prompt_id?: string;
  attempt_number: number;
  error_type: string;
  error_message: string;
  status_code?: number;
  retry_delay_ms: number;
  duration_ms: number;  // = retry_delay_ms, treibt die LogToSpanProcessor-Bridge-Span-Breite
 
  constructor(opts: { model: string; promptId?: string; attemptNumber: number; error: unknown; statusCode?: number; retryDelayMs: number }) { ... }
}
 
// constants.ts
export const EVENT_API_RETRY = 'qwen-code.api_retry';
 
// loggers.ts
export function logApiRetry(config: Config, event: ApiRetryEvent): void { ... }

// utils/retry.ts — RetryOptions extension
interface RetryOptions<T> {
  // ... vorhanden ...
  onRetry?: (info: RetryAttemptInfo) => void;
}
 
interface RetryAttemptInfo {
  attempt: number;
  error: unknown;
  errorStatus?: number;
  delayMs: number;
}
 
// Innerhalb von retryWithBackoff, wo heute logRetryAttempt aufgerufen wird:
options.onRetry?.({ attempt, error, errorStatus, delayMs: actualDelay });
logRetryAttempt(attempt, error, errorStatus); // vorhandener debugLogger-Aufruf unverändert

// loggingContentGenerator.ts:283 — generateContentStream
async generateContentStream(req, userPromptId): Promise<AsyncGenerator<GenerateContentResponse>> {
  const requestEntryTime = Date.now();
  let attemptStart = requestEntryTime;
  const attemptStartTimes: number[] = [attemptStart];
  let retryTotalDelayMs = 0;
  let finalAttempt = 1;
 
  // Vorhandenes startLLMRequestSpan verwenden (Phase 1)
  // onRetry-Callback an die verwendete Retry-Schicht weitergeben:
  const onRetry: RetryAttemptInfo & { invoke: ... } = (info) => {
    finalAttempt = info.attempt + 1;        // wir beginnen gleich Versuch N+1
    retryTotalDelayMs += info.delayMs;
    attemptStart = Date.now() + info.delayMs; // ungefähr; tatsächliches Zurücksetzen erfolgt am Anfang des nächsten Versuchs
    attemptStartTimes.push(attemptStart);
    // ApiRetryEvent auslösen
    logApiRetry(this.config, new ApiRetryEvent({
      model: req.model,
      promptId: userPromptId,
      attemptNumber: info.attempt,
      error: info.error,
      statusCode: info.errorStatus,
      retryDelayMs: info.delayMs,
    }));
  };
 
  // Stream-Wrapper erkennt den ersten für den Benutzer sichtbaren Chunk:
  return this.processStreamGenerator(stream, ..., {
    onFirstUserVisibleChunk: (now) => {
      ttftMs = now - attemptStart;
    },
  });
}

endLLMRequestSpan(llmSpan, {
  success: true,
  inputTokens,
  outputTokens,
  cachedInputTokens,
  ttftMs,
  requestSetupMs: attemptStart - requestEntryTime,
  attempt: finalAttempt,
  retryTotalDelayMs,
});

// client.ts:1540 (ähnlich in baseLlmClient.ts:193, 282, geminiChat.ts:1039)
const result = await retryWithBackoff(apiCall, {
  ...existingOptions,
  onRetry: (info) => {
    logApiRetry(
      this.config,
      new ApiRetryEvent({
        model,
        promptId: userPromptId,
        attemptNumber: info.attempt,
        error: info.error,
        statusCode: info.errorStatus,
        retryDelayMs: info.delayMs,
      }),
    );
    // auch an den lokalen Retry-Akkumulator von LoggingContentGenerator zurückmelden
    // (wenn im Scope – für Aufrufer, die nicht über LoggingContentGenerator gehen,
    // erhält der LLM-Span trotzdem `attempt` und `retry_total_delay_ms` über den
    // Metadaten-Pfad, da endLLMRequestSpan auf der LLM-Ebene aufgerufen wird)
  },
});

call_A: attemptStart_A, ttftMs_A, ... (Closure)
call_B: attemptStart_B, ttftMs_B, ... (Closure)
call_C: attemptStart_C, ttftMs_C, ... (Closure)

Gesamt: 14 Dateien, ~610 LOC. Größer als Phase 2 (#4321) aber vergleichbar mit Phase 3 (#4410) und gerechtfertigt durch die Breite der Integration (4 Retry-Stellen + Telemetrie-Infrastruktur + Streaming-Wrapper).

Falls das Review wegen der Größe Druck macht: Aufteilen in **Phase 4a + 4b + 4c**:

- **4a** (~200 LOC): TTFT-Erfassung + erweitertes `LLMRequestMetadata` + Dual-Emit. In sich geschlossener Wert (TTFT-Sichtbarkeit ab Tag eins).
- **4b** (~250 LOC): `onRetry`-Callback + `ApiRetryEvent` + 4 Aufrufer-Verdrahtung. **Unabhängig ein Bugfix** für die `retryWithBackoff`-Telemetrielücke.
- **4c** (~160 LOC): `recordApiRequestBreakdown`-Aktivierung + Parent-Span-Aggregationsattribute (`attempt`, `retry_total_delay_ms`, `sampling_ms`, `output_tokens_per_second`). Hängt von 4a + 4b ab.

## Teststrategie

| Test                                                                                                                                         | Beweis                                                                                   |
| -------------------------------------------------------------------------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------- |
| `hasUserVisibleContent` gibt true für text/functionCall/inlineData/executableCode/thought zurück                                              | D1-Semantik über Part-Typen hinweg                                                        |
| `hasUserVisibleContent` gibt false für reine-role- und reine-usage-Chunks zurück                                                             | D1-Negativfälle                                                                          |
| Streaming: TTFT gemessen vom Start eines Versuchs bis zum ersten sichtbaren Chunk                                                              | End-to-End-TTFT-Erkennung                                                                |
| Streaming: TTFT undefiniert, wenn der Stream vor dem ersten sichtbaren Chunk abbricht                                                          | Grenzfall                                                                                |
| Streaming: TTFT berechnet ab dem Start des letzten Versuchs (nicht des ersten)                                                                 | D3 — TTFT-Reset bei Wiederholung                                                         |
| Nicht-Streaming: TTFT bleibt undefiniert                                                                                                     | S3-Entscheidung                                                                          |
| Gleichzeitige `generateContentStream`-Aufrufe kontaminieren TTFT nicht gegenseitig                                                           | D2 — methodenlokale Garantie                                                             |
| `endLLMRequestSpan` setzt alle Phase-4-Attribute (ttft_ms, request_setup_ms, sampling_ms, attempt, retry_total_delay_ms, output_tokens_per_second) | Vorhandensein der Attribute                                                              |
| `endLLMRequestSpan` emittiert dual gen_ai.server.time_to_first_token + gen_ai.usage.\* + gen_ai.request.model                                  | D8-Dual-Emit                                                                             |
| `endLLMRequestSpan` zeichnet Breakdown-Metrik mit 3 Phasen für Streaming, 2 für Nicht-Streaming auf                                            | D6                                                                                       |
| `endLLMRequestSpan` zweimal aufgerufen: Metrik genau einmal aufgezeichnet, Attribute nicht zurückgesetzt                                      | D7-Idempotenz                                                                            |
| `retryWithBackoff` mit `onRetry`: Callback wird pro fehlgeschlagenem Versuch mit korrekten Argumenten aufgerufen                               | D4-Callback-Vertrag                                                                      |
| `retryWithBackoff` ohne `onRetry`: keine Telemetrie emittiert (stumm für Nicht-LLM-Aufrufer)                                                  | P2 — Channels/Weixin-Bereichsschutz                                                      |
| `client.ts` / `baseLlmClient.ts` / `geminiChat.ts`-Retry-Callstellen emittieren `ApiRetryEvent` bei Wiederholung                                | Integration von D4 an 4 Stellen                                                          |
| `ApiRetryEvent` LogRecord wird via LogToSpanProcessor zu einem Child-Span unter dem aktiven LLM-Span verbunden                                 | Korrektheit des Tracebaums                                                               |
| LLM-Span-Attribut `attempt` spiegelt korrekt die endgültige Versuchsnummer bei Wiederholungen wider                                            | D5-Aggregation                                                                           |
| LLM-Span-Attribut `retry_total_delay_ms` summiert korrekt onRetry-Verzögerungen                                                               | D5-Aggregation                                                                           |
| `output_tokens_per_second` undefiniert wenn `sampling_ms === 0` (kein Streaming)                                                               | Vermeidung von Division-durch-Null                                                        |

## Grenzfälle

| Fall                                                                                  | Behandlung                                                                                                                                                                                                                                        |
| ------------------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
| Stream bricht ab, bevor ein Chunk ankommt                                             | `ttftMs = undefined`, `sampling_ms = undefined`, `output_tokens_per_second = undefined`. `attempt`, `request_setup_ms` werden trotzdem gesetzt. `success = false`                                                                                 |
| Stream bricht nach dem ersten Chunk ab                                                | `ttftMs` gesetzt; `sampling_ms` = `duration_ms - ttftMs - request_setup_ms`; spiegelt partielle Antwortzeit wider. `success = false`                                                                                                              |
| Wiederholung erfolgreich bei Versuch 1 (keine Wiederholungen)                         | `attempt = 1`, `retry_total_delay_ms = 0`, kein `ApiRetryEvent` emittiert, Breakdown-Metrik zeichnet `request_setup_ms` nahe 0 auf                                                                                                                |
| Dauerhafter Wiederholungsmodus mit 50+ Versuchen                                      | 50+ `ApiRetryEvent`-Datensätze emittiert (Obergrenze außerhalb des Scopes zurückgestellt); LLM-Span `attempt = 51`, `retry_total_delay_ms = Summe aller Verzögerungen`. Operator sieht aggregierte Ansicht auf Span; vollständige Details pro Versuch in Log-Bridge-Spans |
| Nicht-LLM-`retryWithBackoff`-Aufrufer (channels/weixin)                                | Kein `onRetry` registriert; nur vorhandener `debugLogger.warn` feuert. Kein `ApiRetryEvent`; keine Breakdown-Metrik (Aufrufer ist keine LLM-Stelle)                                                                                               |
| `endLLMRequestSpan` zweimal aufgerufen (Abbruch + Fehler-Race)                        | Phase 1.5-Guarde bei `activeSpans.delete()` gibt bei zweitem Aufruf vorzeitig zurück; `recordApiRequestBreakdown` befindet sich innerhalb der Guarde, genau einmal aufgezeichnet                                                                  |
| Anthropic-`message_start`-Chunk kommt vor Inhalt an                                  | `hasUserVisibleContent` gibt false zurück (keine Parts mit text/functionCall/etc.); TTFT wird erst beim nachfolgenden `content_block_delta`-Chunk ausgelöst                                                                                        |
| OpenAI erster Chunk mit leerem `delta.content` aber nur `role`                        | `hasUserVisibleContent` gibt false zurück; TTFT wird erst beim ersten Chunk mit nicht-leerem delta ausgelöst                                                                                                                                      |
| Nur-Tool-Call-Antwort (kein Text)                                                      | Erster Chunk mit `functionCall`-Part löst TTFT aus; `output_tokens_per_second` wird gegen Tool-Call-Tokenanzahl berechnet                                                                                                                          |
| Gleichzeitige Subagenten (3 Aufrufe parallel)                                          | Jeder Aufruf hat seinen eigenen Closure mit `attemptStart`, `ttftMs`, `attemptStartTimes`. Pro-Aufruf-Span erhält eigene Metadaten bei `endLLMRequestSpan`. Keine Überlappung (D2)                                                                |
| SDK-interne Wiederholungen in openai-sdk (`maxRetries=3`)                              | Unsichtbar für qwen-code-Telemetrie – finden vollständig innerhalb des SDKs statt, bevor retryWithBackoff die Anfrage sieht. `attempt` spiegelt nur retryWithBackoff-Versuche wider. Außerhalb des Scopes (siehe Out-of-scope)                     |
| `gen_ai.server.time_to_first_token`-Spezifikation wird vor Stable umbenannt           | Einzelfile-Update: `session-tracing.ts:endLLMRequestSpan`. Das qwen-code-native `ttft_ms` bleibt maßgeblich – keine Auswirkungen nachgelagerter Systeme                                                                                            |
| LLM-Anfrage eines Subagenten                                                            | Parent ist der Subagenten-Span (Phase 3). Phase-4-Felder verschachteln sich korrekt. Aggregationen gruppiert nach `qwen-code.subagent.id` liefern LLM-Performance pro Subagent – Design-Doc-Zukunft, einfaches Follow-up                            |
| Reasoning-Modell mit langen Thought-Blöcken                                           | Erster `thought`-Part löst TTFT aus; `sampling_ms` umfasst sowohl Denk- als auch Antwortphase. Aufteilung in separate Metriken zurückgestellt                                                                                                     |

## Rollback

Die Änderung ist auf OTel- und Metrikebene additiv – jedes neue Attribut ist optional, jedes neue Event ist eine neue Klasse. Bestehende Dashboards, die nicht auf die neuen Felder filtern, funktionieren unverändert weiter.

Verhaltensändernde Auswirkungen:

- Neue `ApiRetryEvent` LogRecord fließen → Logvolumen steigt proportional zur Wiederholungsrate (typischerweise <1% der Anfragen wiederholt). Abmildern durch Sampling von LogRecord auf SDK-Ebene, falls nötig.
- Neue Breakdown-Metrik `qwen-code.api.request.breakdown` beginnt Zeitreihen zu produzieren → leichter Prometheus-Kardinalitätsanstieg (`{model, phase}` – begrenzt).
- Abgeleitetes Attribut `output_tokens_per_second` kann auf Dashboards, die „alle Attribute“ filtern, ungewöhnlich erscheinen – dokumentieren.

Rollback-Pfad: Den einzelnen PR zurücksetzen (oder unabhängig jeden von 4a/4b/4c). Alle neuen Felder verwenden defensive Defaults (undefined / 0) und ändern die Span-Struktur nicht.

## Sequenzierung

- **Nach Phase 3 (#4410, im Review)**: keine harte Abhängigkeit. Phase-4-Attribute werden an `qwen-code.llm_request`-Spans angehängt, unabhängig davon, ob sie unter einem `qwen-code.subagent` (Phase 3) oder `qwen-code.interaction` (Phase 1) als Parent liegen. Empfehlung: Phase 3 zuerst landen lassen, damit die Aggregation pro Versuch unter Subagenten-Subbäumen natürlich funktioniert.
- **Unabhängig von #4384** (`traceparent` + `X-Qwen-Code-Session-Id`-Outbound-Propagation). Sie betreffen die HTTP-Schicht; Phase 4 betrifft die Stream-/Retry-/Metrik-Schicht.
- **Unabhängig vom `clearDetailedSpanState`-Chat-Kompaktierungs-Follow-up** (#4097 Follow-up). Unterschiedliche Oberfläche.

## Offene Fragen

1. **Semantik des `onRetry`-Callback-Aufrufs**: Wird er **vor** dem Backoff-Schlaf (aktueller Vorschlag) oder **danach** (wenn der nächste Versuch kurz vor dem Start steht) aufgerufen? Vorher ist einfacher – der Callback hat alle Informationen sofort; danach müsste die gerade abgeschlossene Verzögerung separat erfasst werden. Vor-Schlaf wird empfohlen; im Callback-Vertrag dokumentieren.
2. **Timing pro Versuch auf dem LLM-Span**: Sollten wir ein Array `attempt_durations_ms: number[]` hinzufügen? OTel unterstützt Array-von-Primitiven-Attribute. Nützlich für die Diagnose „Welcher der N-Versuche war langsam“. Zurückstellen, bis Produktionsdaten Bedarf zeigen – Log-Bridge-Spans tragen bereits das Äquivalent.
3. **Obergrenze für Emission im dauerhaften Wiederholungsmodus**: Ab welchem `attempt > N`-Schwellwert sollten wir samplen? `N = 5` dann 1-in-10? `N = 10` dann nur zusammenfassend? Zurückstellen, bis wir Produktionsvolumendaten haben.
4. **`TOKEN_PROCESSING`-Phase**: Enum-Wert ruhend lassen oder mit etwas verbinden (z.B. Konsolidierungszeit)? Zurückstellen – auf einen echten Anwendungsfall warten.
5. **Subagenten-LLM-Zusammenfassungen**: Triviales Follow-up, sobald Phase 4 landet – summiere `ttft_ms`/`output_tokens`/`input_tokens` pro Subagenten-Subbaum. Nicht Phase-4-Scope, aber der Datenfluss ermöglicht es.