LLM リクエストタイミング分解設計 (P3 Phase 4)

// loggingContentGenerator.ts — generateContentStream 内
const attemptStart = Date.now(); // 呼び出しごとのローカル
const requestEntryTime = Date.now(); // 呼び出しごとのローカル — D3参照
let ttftMs: number | undefined;
const attemptStartTimes: number[] = [attemptStart];
let retryTotalDelayMs = 0;
let finalAttempt = 1;
// ストリームラッパーは各チャンクを検査。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` はすべてのSDKバージョンにあるわけではないが、プロバイダーは出力する
      p.thought !== undefined,
  );
}

request_setup_ms = attemptStart_of_successful_attempt - requestEntryTime;

// utils/retry.ts
interface RetryOptions<T> {
  // ... 既存のフィールド ...
  /**
   * オプション。失敗した試行ごとに、バックオフスリープの前に1回呼び出される。
   * 試行番号（1ベース）、エラー、および次の試行までの遅延を受け取る。
   * LLM呼び出しサイトのテレメトリイベントを出力するために使用する。
   * 非LLM呼び出し元 (例: channels/weixin) には undefined を指定し、
   * LLM固有のテレメトリチャネルでサイレントにする。
   */
  onRetry?: (info: RetryAttemptInfo) => void;
}
 
interface RetryAttemptInfo {
  attempt: number; // 1ベース、debugLogger の出力と一致
  error: unknown;
  errorStatus?: number;
  delayMs: number; // 次の試行までのバックオフ遅延
}

// types.ts — 新しいイベントクラス、ContentRetryEvent と同階層
export class ApiRetryEvent implements BaseTelemetryEvent {
  'event.name': typeof EVENT_API_RETRY;
  'event.timestamp': string;
  model: string;
  prompt_id?: string;
  attempt_number: number; // 1始まり
  error_type: string;
  error_message: string; // 256文字に切り詰め
  status_code?: number;
  retry_delay_ms: number;
  // ... duration_ms は retry_delay_ms に設定されるため、LogToSpanProcessor は
  // 意味のある幅のブリッジスパンを描画する
  duration_ms: number;
}

recordApiRequestBreakdown(config, model, [
  { phase: ApiRequestPhase.REQUEST_PREPARATION, durationMs: requestSetupMs },
  { phase: ApiRequestPhase.NETWORK_LATENCY, durationMs: ttftMs }, // ttftMs = ネットワーク + 最初のトークン生成
  { phase: ApiRequestPhase.RESPONSE_PROCESSING, durationMs: samplingMs },
]);

// session-tracing.ts — endLLMRequestSpan
const llmCtx = activeSpans.get(spanRef);
if (!llmCtx) return;            // 既に終了 — 二重終了ガード
activeSpans.delete(spanRef);    // 終了を主張
 
// ... 期間を計算し、属性を設定 ...
if (metadata) {
  recordApiRequestBreakdown(config, llmCtx.attributes.model, [...]);   // 新規 — ゲート付き
  recordTokenUsageMetrics(...); // 既存
}
 
span.end();

// session-tracing.ts — LLMRequestMetadata インターフェースを拡張（追加的）
export interface LLMRequestMetadata {
  // ... 既存フィールド: inputTokens, outputTokens, cachedInputTokens, success, error, ...
 
  /** 成功した試行の開始から最初のユーザー可視コンテンツチャンクまでの時間（ms）。非ストリーミングまたは最初のチャンクより前に中断されたリクエストでは未定義。 */
  ttftMs?: number;
 
  /** generateContent エントリから成功した試行の開始までの時間（ms）。すべての失敗リトライ＋バックオフを含む。 */
  requestSetupMs?: number;
 
  /** 最終試行番号（1始まり）。1 = リトライなし。 */
  attempt?: number;
 
  /** 成功した試行までのすべてのバックオフ遅延の合計（ms）。 */
  retryTotalDelayMs?: number;
}
 
// 新しいエクスポートヘルパーは不要 — Phase 4 は拡張されたメタデータを使用して既存の startLLMRequestSpan / endLLMRequestSpan を再利用する。

// types.ts — 新しいイベントクラス
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、LogToSpanProcessor ブリッジスパンの幅を制御
 
  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 拡張
interface RetryOptions<T> {
  // ... 既存 ...
  onRetry?: (info: RetryAttemptInfo) => void;
}
 
interface RetryAttemptInfo {
  attempt: number;
  error: unknown;
  errorStatus?: number;
  delayMs: number;
}
 
// Inside retryWithBackoff, where logRetryAttempt is called today:
options.onRetry?.({ attempt, error, errorStatus, delayMs: actualDelay });
logRetryAttempt(attempt, error, errorStatus); // 既存の debugLogger 呼び出しは変更なし

// 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;
 
  // 既存の startLLMRequestSpan を使用（Phase 1）
  // 使用中のリトライレイヤーに onRetry コールバックを渡す：
  const onRetry: RetryAttemptInfo & { invoke: ... } = (info) => {
    finalAttempt = info.attempt + 1;        // これから attempt N+1 を開始する
    retryTotalDelayMs += info.delayMs;
    attemptStart = Date.now() + info.delayMs; // 概算；実際のリセットは次の試行の先頭で行われる
    attemptStartTimes.push(attemptStart);
    // ApiRetryEvent を出力
    logApiRetry(this.config, new ApiRetryEvent({
      model: req.model,
      promptId: userPromptId,
      attemptNumber: info.attempt,
      error: info.error,
      statusCode: info.errorStatus,
      retryDelayMs: info.delayMs,
    }));
  };
 
  // ストリームラッパーが最初のユーザー可視チャンクを検出：
  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（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,
      }),
    );
    // LoggingContentGenerator のローカルリトライアキュムレータにもフィードバックする
    // （スコープ内の場合 — LoggingContentGenerator を経由しない呼び出し元の場合、
    // LLM スパンはメタデータパスを通じて依然として `attempt` と `retry_total_delay_ms` を取得する。
    // endLLMRequestSpan は LLM レイヤーで呼び出されるため）
  },
});

call_A: attemptStart_A, ttftMs_A, ... (クロージャ)
call_B: attemptStart_B, ttftMs_B, ... (クロージャ)
call_C: attemptStart_C, ttftMs_C, ... (クロージャ)

合計: 14ファイル、約610 LOC。フェーズ2 (#4321) より大きいですが、フェーズ3 (#4410) と同等であり、統合範囲（4つのリトライ箇所 + テレメトリー配管 + ストリーミングラッパー）の広さを考慮すると妥当です。

レビューでサイズが問題になった場合は、**フェーズ4a + 4b + 4c** に分割します:

- **4a** (~200 LOC): TTFTキャプチャ + 拡張された `LLMRequestMetadata` + デュアルエミット。それ単体で価値があります（初日からTTFTの可視性が得られます）。
- **4b** (~250 LOC): `onRetry` コールバック + `ApiRetryEvent` + 4つの呼び出し元への配線。**独立したバグ修正**であり、`retryWithBackoff` のテレメトリーギャップを埋めます。
- **4c** (~160 LOC): `recordApiRequestBreakdown` の有効化 + 親スパン集約属性（`attempt`、`retry_total_delay_ms`、`sampling_ms`、`output_tokens_per_second`）。4a + 4b に依存します。

## テスト戦略

| テスト                                                                                                                                         | 何を証明するか                        |
| -------------------------------------------------------------------------------------------------------------------------------------------- | ------------------------------------- |
| `hasUserVisibleContent` が text/functionCall/inlineData/executableCode/thought に対して true を返す                                            | パートタイプ間でのD1セマンティクス        |
| `hasUserVisibleContent` が role-only および usage-only チャンクに対して false を返す                                                             | D1の negative ケース                     |
| ストリーミング: TTFTが試行開始から最初のユーザー可視チャンクまで測定される                                                                      | エンドツーエンドのTTFT検出             |
| ストリーミング: ユーザー可視チャンクの前にストリームが中断された場合、TTFTは未定義                                                                    | エッジケース                             |
| ストリーミング: TTFTが（最初の試行ではなく）最終試行の開始から計算される                                                                      | D3 — リトライ時のTTFTリセット          |
| 非ストリーミング: TTFTは未定義のまま                                                                                                        | S3の決定                           |
| 同時の `generateContentStream` 呼び出しがTTFTを相互汚染しない                                                                        | D2 — メソッドローカルな保証           |
| `endLLMRequestSpan` がすべてのフェーズ4属性（ttft_ms、request_setup_ms、sampling_ms、attempt、retry_total_delay_ms、output_tokens_per_second）を設定する | 属性の存在                    |
| `endLLMRequestSpan` が gen_ai.server.time_to_first_token + gen_ai.usage.\* + gen_ai.request.model をデュアルエミットする                                    | D8 デュアルエミット                          |
| `endLLMRequestSpan` がストリーミングでは3フェーズ、非ストリーミングでは2フェーズで breakdown メトリクスを記録する                                                | D6                                    |
| `endLLMRequestSpan` が2回呼び出される: メトリクスは正確に1回記録され、属性は再設定されない                                                             | D7 冪等性                        |
| `retryWithBackoff` と `onRetry`: 失敗した試行ごとに正しい引数でコールバックが呼び出される                                                     | D4 コールバック契約                  |
| `onRetry` なしの `retryWithBackoff`: テレメトリーは出力されない（非LLM呼び出し元ではサイレント）                                                      | P2 — channels/weixin スコープの保護 |
| `client.ts` / `baseLlmClient.ts` / `geminiChat.ts` のリトライ呼び出し箇所が、リトライ時に `ApiRetryEvent` を出力する                                             | 4箇所でのD4統合          |
| `ApiRetryEvent` LogRecord が LogToSpanProcessor を介して、アクティブなLLMスパンの下の子スパンにブリッジされる                                               | トレースツリーの正確性                |
| LLMスパンの `attempt` フィールドがリトライ時の最終試行番号を正しく反映する                                                               | D5 集約                        |
| LLMスパンの `retry_total_delay_ms` が onRetry の遅延を正しく合計する                                                                                | D5 集約                        |
| `sampling_ms === 0`（ストリーミングなし）の場合、`output_tokens_per_second` は未定義                                                                 | ゼロ除算の回避                  |

## エッジケース

| ケース                                                                    | 処理                                                                                                                                                                                                                 |
| ----------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ |
| チャンクが到着する前にストリームが中断される                                  | `ttftMs = undefined`、`sampling_ms = undefined`、`output_tokens_per_second = undefined`となります。`attempt`、`request_setup_ms`は設定されたままです。`success = false`                                                                      |
| 最初のチャンク到着後にストリームが中断される                                         | `ttftMs`が設定されます; `sampling_ms` = `duration_ms - ttftMs - request_setup_ms`; 部分的な応答時間を反映します。`success = false`                                                                                               |
| リトライが試行1で成功する（リトライなし）                                | `attempt = 1`、`retry_total_delay_ms = 0`、`ApiRetryEvent`は出力されず、breakdownメトリクスは `request_setup_ms` が0に近い値を記録します                                                                                            |
| 永続リトライモードで50回以上の試行                                      | 50以上の `ApiRetryEvent` レコードが出力されます（上限設定はスコープ外で延期）; LLMスパン `attempt = 51`、`retry_total_delay_ms = 全遅延の合計`。オペレーターはスパンで集約ビューを確認; 完全な試行ごとの詳細はログブリッジスパンで確認可能 |
| 非LLMの `retryWithBackoff` 呼び出し元（channels/weixin）                     | `onRetry` が登録されていません; 既存の `debugLogger.warn` のみが発火します。`ApiRetryEvent` は出力されません; breakdownメトリクスも出力されません（呼び出し元がLLMサイトではないため）                                                                                      |
| `endLLMRequestSpan` が2回呼び出される（abort + error の競合）                   | フェーズ1.5のガードにより、`activeSpans.delete()` が2回目の呼び出しで早期リターンします; `recordApiRequestBreakdown` はガード内にあり、正確に1回記録されます                                                                           |
| Anthropicの `message_start` チャンクがコンテンツより先に到着する                   | `hasUserVisibleContent` はこれに対して false を返します（text/functionCallなどのパートがないため）; TTFTは後続の `content_block_delta` チャンクまでトリガーされません                                                                     |
| OpenAIの最初のチャンクに空の `delta.content` と `role` のみが含まれる           | `hasUserVisibleContent` は false を返します; TTFTは空でないデルタを持つ最初のチャンクまでトリガーされません                                                                                                                         |
| ツール呼び出しのみの応答（テキストなし）                                       | `functionCall` パートを含む最初のチャンクがTTFTをトリガーします; `output_tokens_per_second` はツール呼び出しのトークン数に対して計算されます                                                                                                    |
| 同時サブエージェント（3つの進行中の呼び出し）                                | 各呼び出しのクロージャは、独自の `attemptStart`、`ttftMs`、`attemptStartTimes` を持ちます。呼び出しごとのスパンは、`endLLMRequestSpan` で独自のメタデータを受け取ります。インターリーブは発生しません（D2）                                                      |
| openai-sdk 内でのSDKレベルのリトライ（`maxRetries=3`）                    | qwen-code テレメトリーからは不可視 — retryWithBackoff がリクエストを認識する前にSDK内で完全に発生します。`attempt` は retryWithBackoff の試行のみを反映します。スコープ外です（「スコープ外」を参照）                              |
| `gen_ai.server.time_to_first_token` の仕様変更がStableになる前のリネーム | 単一ファイルの更新: `session-tracing.ts:endLLMRequestSpan`。qwen-code ネイティブの `ttft_ms` は信頼できるソースのままです — ダウンストリームへの影響はありません                                                                                    |
| サブエージェントのLLMリクエスト                                                  | 親はサブエージェントスパンです（フェーズ3）。フェーズ4のフィールドは正しくネストされます。`qwen-code.subagent.id` でグループ化された集約により、サブエージェントごとのLLMパフォーマンスが得られます — 設計ドキュメントで将来対応、簡単なフォローアップです                                     |
| 長い思考ブロックを持つ推論モデル                                | 最初の `thought` パートがTTFTをトリガーします; `sampling_ms` には思考フェーズと回答フェーズの両方が含まれます。別々のメトリクスへの分割は延期されます                                                                                           |

## ロールバック

この変更は、OTelおよびメトリクスレベルで追加的です — すべての新しい属性はオプションであり、すべての新しいイベントは新しいクラスです。新しいフィールドでフィルタリングしない既存のダッシュボードは、変更なく動作し続けます。

動作に影響を与える変更:

- 新しい `ApiRetryEvent` LogRecord が流れ始める → ログボリュームがリトライ率に比例して増加します（通常、リクエストの1%未満がリトライします）。必要に応じてSDKレイヤーでLogRecordをサンプリングすることで軽減できます。
- 新しい breakdown メトリクス `qwen-code.api.request.breakdown` が時系列を生成し始める → Prometheusのカーディナリティが若干増加します（`{model, phase}` — 制限付き）。
- `output_tokens_per_second` 派生属性は、「すべての属性」でフィルタリングするダッシュボードでは異常に見える可能性があります — 文書化します。

ロールバックパス: 単一のPR（または4a/4b/4cのそれぞれ独立して）を元に戻します。すべての新しいフィールドは防御的なデフォルト値（undefined / 0）を使用し、スパン構造を変更しません。

## シーケンス

- **フェーズ3 (#4410、レビュー中) の後**: ハードな依存関係ではありません。フェーズ4の属性は、親が `qwen-code.subagent`（フェーズ3）であろうと `qwen-code.interaction`（フェーズ1）であろうと、`qwen-code.llm_request` スパンにアタッチされます。フェーズ3を先に導入して、サブエージェントサブツリー下での試行ごとの集約が自然に機能するようにすることを推奨します。
- **#4384 から独立**（`traceparent` + `X-Qwen-Code-Session-Id` のアウトバウンド伝搬）。これらはHTTPレイヤーに影響します; フェーズ4はストリーム/リトライ/メトリクスレイヤーに影響します。
- **`clearDetailedSpanState` チャット圧縮フォローアップから独立** (#4097 フォローアップ)。対象領域が異なります。

## 未解決の質問

1. **`onRetry` コールバックの発火セマンティクス**: バックオフスリープ**前**（現在の提案）と**後**（次の試行が開始されようとしているとき）、どちらで呼び出されるべきか？ 前者の方がシンプルです — コールバックはすべての情報を即座に利用できます; 後者の場合、完了したばかりの遅延を個別にキャプチャする必要があります。スリープ前が推奨です; コールバック契約に文書化します。
2. **LLMスパン上の試行ごとのタイミング**: `attempt_durations_ms: number[]` 配列を追加すべきか？ OTelはプリミティブ属性の配列をサポートしています。「N回目の試行のうち、どれが遅かったか」の診断に役立ちます。同等の情報はログブリッジスパンがすでに保持しているため、本番データが需要を示すまで延期します。
3. **永続リトライモードの出力上限**: `attempt > N` のどの閾値でサンプリングを開始すべきか？ `N = 5` で1/10? `N = 10` でサマリーのみ？ 本番ボリュームデータが得られるまで延期します。
4. **`TOKEN_PROCESSING` フェーズ**: 列挙値を休眠状態のままにするか、何か（例: 統合時間）に配線するか？ 延期 — 実際のユースケースを待ちます。
5. **サブエージェントレベルのLLMロールアップ**: フェーズ4が導入されれば、簡単なフォローアップです — サブエージェントサブツリーごとに `ttft_ms`/`output_tokens`/`input_tokens` を合計します。フェーズ4のスコープではありませんが、データフローによって可能になります。