LLMリクエストタイミング分解設計 (P3 フェーズ4)

Issue #3731 — 階層型セッショントレーシングのフェーズ4。qwen-code.llm_request スパンに time-to-first-token、リクエストセットアップ時間、サンプリング時間、試行ごとのリトライテレメトリを追加し、オペレーターが「なぜこのLLM呼び出しは遅かったのか？」を推測なしに分析できるようにする。

フェーズ1 (#4126)、フェーズ1.5 (#4302)、フェーズ2 (#4321) に基づく。フェーズ3 (#4410、レビュー中) とは独立しているが、フェーズ4の試行ごとのフィールドがサブエージェントサブツリー配下でクリーンに集計できるよう、フェーズ3を先にリリースすることを推奨する。

問題

現状の qwen-code.llm_request スパンには model、prompt_id、input_tokens、output_tokens、success、error、duration_ms しか含まれていない。単一のトレースを読んでも以下を判断できない:

1. duration_ms のうちどれだけがモデルの思考時間でどれだけがネットワークセットアップ時間か。 12秒の duration_ms は「11秒のリトライ＋1秒の高速生成」かもしれないし、「100msのセットアップ＋12秒の低速ストリーミング」かもしれないが、トレースからは分からない。
2. ユーザーが最初のトークンを受け取ったタイミング。 TTFT (time-to-first-token) はチャットUIの標準レイテンシSLOだが、取得も計測もできていない。
3. リトライ中に何が起きたか。 retryWithBackoff (utils/retry.ts:285) は debugLogger.warn を呼ぶだけで、OTelイベントもスパン属性もない。これを通る4つのLLM呼び出しサイト (client.ts:1540、baseLlmClient.ts:193,282、geminiChat.ts:1039) はトレースにもメトリクスにもリトライの可視性がゼロ。ContentRetryEvent は geminiChat.ts:806,830 内のコンテンツ復旧リトライには存在するが、より一般的なレート制限/5xx リトライには存在しない。
4. api.request.breakdown がデッドコードであること。 このメトリクスは metrics.ts:242-251 で4つの ApiRequestPhase 値として定義され、index.ts:117 からエクスポートされ、metrics.test.ts:646-675 でテストされているが、本番コードで recordApiRequestBreakdown() を呼び出す箇所がゼロ。メトリクスのインフラは用意されているが、データフローは接続されていなかった。

これらのギャップにより、qwen-code.llm_request はトレースツリーの中で最も情報量の少ないスパンとなっている。ツールスパン (#4126/#4321) やサブエージェントスパン (#4410) はライフサイクルフェーズを公開しているが、LLMスパンはリクエスト全体を一つの不透明な duration に押しつぶしている。

変更しない既存の面

スコープ外 (延期)

• SDKレベルのリトライ (openai SDK maxRetries=3、google-genai SDK内部リトライ)。これらはサードパーティSDK内で完結するため、観測するにはSDKリトライを無効化して retryWithBackoff で再実装する必要がある。フェーズ4の対象外。
• トークンごとのストリーミングメトリクス (トークン間レイテンシ、チャンクサイズ)。推論エンジンのパフォーマンスデバッグには有用だが、フェーズ4が対象とするユーザー体感レイテンシの問題には該当しない。
• 思考/reasoningブロックの別途TTFT。 「最初のトークン」には思考コンテンツが含まれる (D1参照)。将来の拡張として ttft_to_reasoning_ms と ttft_to_answer_ms の分割が可能だが、需要が確認されてから対応する。
• 専用子スパンとしてのサンプリングフェーズ。 duration_ms - ttft_ms - request_setup_ms で算出可能。子スパンはOTelのみのバックエンドでは何も追加しない (claude-code はPerfettoのみ使用)。スパン属性として保存する — D6参照。
• 永続的リトライモード (QWEN_CODE_UNATTENDED_RETRY) のイベントレベルのレート制限。 単一のLLMリクエストで50件以上の ContentRetryEvent / ApiRetryEvent レコードが発生する可能性がある。フェーズ4ではすべてのイベントを送出する。本番ボリュームが問題になった場合は、スパンごとの送出上限と「+N件以上の試行 (切り捨て)」サマリーイベントをフォローアップPRで追加する。
• TOKEN_PROCESSING フェーズ。 enum値は存在するが、qwen-codeはポストストリームのローカル処理が実質的に計測する価値がない (<10ms 典型)。本番呼び出し元ではスキップ。enum値は将来の利用のために保持する。
• ContentRetryEvent をLLMスパンのスパンイベントに移行すること。 フェーズ3の subagent_execution LogRecordと同じ理由: 既存コンシューマー (qwen-logger RUM、将来のメトリクス) がLogRecordに密結合している。ブリッジスパンのカバレッジで十分。

参考文献 (意思決定の根拠)

設計 — 7つの決定とその根拠

D1 — TTFTのセマンティクス: 「ユーザーが見える最初のコンテンツを含むチャンク」

TTFTは成功した試行のリクエスト送信からユーザーが見える出力を含む最初のストリームチャンクまでのウォールクロック時間を計測する。チャンクが「ユーザーが見える」とは、candidates[0].content.parts に含まれる正規化された Part が以下のいずれかの場合:

• text: 空でない文字列
• functionCall (ツール使用)
• inlineData (画像、バイナリ)
• executableCode
• thought / reasoningコンテンツ (プロバイダーが公開するもの — Geminiの thought、Anthropicの <thinking> ブロック、OpenAI o1 reasoningチャンク)

role メタデータのみ、または usageMetadata のみ (最終的な使用サマリーチャンク) を含むチャンクはTTFTをトリガーしない。

「任意の種類の最初のストリームイベント」(claude-codeの選択) としない理由: claude-codeはAnthropicプロセス固有のメタデータイベントである message_start でTTFTを計測している。これは実際のコンテンツより50〜300ms前に発火する。claude-codeの内部 headlessProfiler.ts は「ユーザーが何かを見た」というセマンティクスのために time_to_first_response_ms を別途分離しており、この区別を認識している。qwen-codeは複数のプロバイダー (Anthropic、OpenAI、Gemini、Qwen) にまたがっている。メタデータイベントのセマンティクスを選ぶと、AnthropicのTTFTがOpenAI (同様のメタデータのみの最初のイベントがない) のTTFTと本質的に異なるものになる。ユーザーが見えるコンテンツのセマンティクスは4つのプロバイダーで均一であり、「time-to-first-token」を文字通りに解釈したものに一致する。

thought / reasoningを含める理由: オペレーターの観点からは、reasoningチャンクも「モデルが出力を生成した」という事実。除外するとreasoningが多いモデル (o1、Qwen thinkingバリアント) のTTFTが過小評価される。将来の拡張として ttft_to_reasoning_ms と ttft_to_answer_ms への分割は可能だが、フェーズ4の対象外。

ツール呼び出しのみのチャンクを含める理由: エージェントのツール決定LLM呼び出し (1つの tool_use、テキストなし) はqwen-codeのワークフローで一般的。除外するとこれらのリクエストでTTFTが未定義になる。functionCall Partは意味のある出力。

製品間比較の注記: 設計文書は qwen-code.ttft_ms ≈ claude-code.time_to_first_response_ms ≠ claude-code.ttft_ms と明記する。製品をまたいで比較するオペレーターはユーザーが見えるコンテンツのセマンティクスで揃えるべき。

D2 — TTFT計測の場所: LoggingContentGenerator.generateContentStream のメソッドローカル変数

最初のチャンク検出は loggingContentGenerator.ts:393 の既存ストリームラッパー (async function* processStreamGenerator) 内で実行される。呼び出しごとの変数 (start、ttftMs) はメソッドのクロージャ内に存在し、インスタンスフィールドには絶対に格納しない。

インスタンスフィールドにしない理由: LoggingContentGenerator は ContentGenerator ごとに1回インスタンス化 (contentGenerator.ts:377) され、すべての並行する generateContentStream 呼び出し (サブエージェントのファンアウト、ウォームアップクエリ、geminiChat からのサイドクエリ) で共有される。インスタンスフィールドは並行する呼び出し間で上書きされ、インターリーブされたリクエストの片方でTTFTが無意味な値になる。

AsyncLocalStorage にしない理由: ALSは機能するが、メソッドを外に出る必要のない状態にコンテキスト管理レイヤーを追加することになる。メソッドローカルはよりシンプルで、オーバーヘッドゼロ、リークリスクゼロ。

// 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;

hasUserVisibleContent(chunk) はラッパーと同じ場所にある小さなスタンドアロンヘルパーで、テスト用にエクスポートされる:

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,
  );
}

D3 — request_setup_ms の計算: エントリー時刻 vs 成功した試行の開始時刻

request_setup_ms は generateContentStream/generateContent のエントリーから成功した試行の開始までのウォールクロック時間を計測する。失敗したリトライ、バックオフスリープ、リトライ前の準備作業をすべて含む。

request_setup_ms = attemptStart_of_successful_attempt - requestEntryTime;

attempt === 1 でリトライが発生しなかった場合、request_setup_ms は小さい (SDKセットアップのみ)。リトライが発生した場合、リトライバジェット全体のオーバーヘッドを捉える。

OTelスパンに含める理由 (Perfettoにのみ含めるclaude-codeからの乖離): 3つのレベルで根拠がある:

1. Perfettoがない — qwen-codeには帯域外の可視化レイヤーがない。OTel属性が唯一のチャネル。
2. シングルトレースデバッグ — オペレーターは duration_ms=12000, request_setup_ms=11500, ttft_ms=200, sampling_ms=300 を見て即座に「リトライが11.5秒を費やし、モデル自体は高速だった」と診断できる。他のフィールドから request_setup_ms を計算するには sampling_ms も公開する必要があり、それはいずれにせよ行う (D6)。
3. 無視できるコスト — 1つのINT64属性。既存の input_tokens、output_tokens 属性と同等のオーダー。バックエンドの取り込みコストは重要でない。

D4 — リトライテレメトリ: retryWithBackoff の onRetry コールバックオプション + ApiRetryEvent + AsyncLocalStorage伝播

フェーズ4b更新 (設計後の発見): このセクションは当初、claude-codeの「1つのLLMスパンがリトライループを所有する」パターンを前提として書かれていた。フェーズ4bの実装中に、qwen-codeの4つの retryWithBackoff 呼び出しサイト (client.ts:2109、baseLlmClient.ts:235,333、geminiChat.ts:2035 — マージ時の行番号) がすべて apiCall = () => contentGenerator.generateContent(...) をラップしていることが判明した。リトライレイヤーはLoggingContentGeneratorの上位に位置する。各リトライ試行は apiCall() を新たに呼び出す → 新しい qwen-code.llm_request スパン。試行をまたがる単一の共有スパンは存在しない。LoggingContentGenerator内のアキュムレーターは機能しない。

解決策: AsyncLocalStorage (packages/core/src/utils/retryContext.ts の retryContext) 経由でリトライ状態を伝播する。retryWithBackoff は各 await fn() を retryContext.run({ attempt, requestSetupMs, retryTotalDelayMs }, fn) でラップする。LoggingContentGenerator は同期的なプリアンブルでALSを読み取り、値を endLLMRequestSpan に転送する。これにより当初の計画よりも豊富な観測性が得られる — 試行ごとのスパンは独自の duration_ms / ttft_ms / エラー詳細を持ち、さらに試行ごとの attempt / requestSetupMs / retryTotalDelayMs 属性を通じてリトライバジェット内の位置も把握できる。

ALSアプローチはコードベースの既存パターン (promptIdContext、subagentNameContext、agent-context) と一致する — 新しい面を最小限にし、十分に理解されたセマンティクスを持つ。プランモードレビュープロセスで3回のレビューラウンドを通じて22件の問題が発見され、マージ前にすべて対応された。

retryWithBackoff は現在 logRetryAttempt (retry.ts:343) を呼び出し、これは debugLogger.warn にのみ書き込む。RetryOptions インターフェースをオプトインコールバックで拡張する:

// 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; // 次の試行前のバックオフ遅延
}

4つのLLM呼び出しサイト (client.ts:1540、baseLlmClient.ts:193,282、geminiChat.ts:1039) は新しい ApiRetryEvent を送出するコールバックを登録する:

// 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;
}

新しいイベントクラスとして定義し ContentRetryEvent を拡張しない理由:

• ContentRetryEvent には2つのダウンストリームコンシューマー (qwen-logger、ログレコードエクスポート) がある。ペイロードを変更すると破壊的変更のリスクがある。
• 「content retry」という命名はセマンティクス的にコンテンツ復旧リトライ (無効なストリーム、スキーマ修復) を指す — レート制限リトライを含めるとスキーマが曖昧になる。
• 新しいイベントは加算的であり、コンシューマーへの驚きがない。

retry.ts にコールバックをハードコードしない理由: retry.ts は channels/weixin/src/api.ts (Microsoftメッセージング APIリトライ) からも呼び出される。retry.ts にLLMテレメトリをハードカップリングすると、非LLMリトライで ApiRetryEvent が送出される。onRetry コールバックは呼び出し元ごとのオプトイン — LLM呼び出し元はオプトイン、weixin呼び出し元はオプトアウト。

ContentRetryEvent との共存: ContentRetryEvent は geminiChat.ts:806,830 内のコンテンツ復旧リトライのためにそのまま残る。ApiRetryEvent は retryWithBackoff からのレート制限/5xx リトライをカバーする。2つのイベントは異なるレイヤーから発火され、重複することはない。両イベントの既存のログブリッジ動作は LogToSpanProcessor 経由で維持される — 両イベントはフェーズ1の配線により自動的にアクティブなLLMスパン配下にネストされる。

永続的リトライモード (QWEN_CODE_UNATTENDED_RETRY): 単一の429ループリクエストで50件以上のイベントが送出される可能性がある。フェーズ4での送出レート制限はスコープ外 — 本番ボリュームが問題になった場合は、スパンごとの上限とサマリーイベントをフォローアップPRで追加する。親LLMスパンの集計 attempt と retry_total_delay_ms (D5) はイベント上限に関係なく正確なまま。

D5 — 親LLMスパンの集計: スカラー属性のみ (マップ型属性なし)

OTelスパン属性はスカラー (string | number | boolean | これらの配列)。マップ型属性 (例: retry_count_by_status: {429:2, 503:1}) はJSONシリアライズが必要でクエリが煩雑。スキップする。

試行ごとのステータスコード分布 (例: 「3回の試行のうち2回が429」) は ApiRetryEvent レコードのログブリッジスパンからクエリ可能。親にフラット化された属性として重複させる必要はない。

sampling_ms と output_tokens_per_second をスパンに含める理由: 多くのスパンを集計するバックエンドクエリで計算するのは派生可能だが煩雑。request_setup_ms と同じコストベネフィット (D3)。

D6 — recordApiRequestBreakdown() を4フェーズのうち3フェーズで有効化

endLLMRequestSpan (またはそれを呼び出すラッパー) で、TTFT/セットアップ/サンプリングを計算した後に送出する:

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

TOKEN_PROCESSING をスキップする理由: qwen-codeはストリームチャンク処理をインライン (loggingContentGenerator.ts:644 のラッパーで統合) で行う。ポストストリームのラップアップフェーズは <10ms であり、アーキテクチャ的に区別する価値がない。無意味な値を入れるとヒストグラムが汚染される。enum値を未使用のままにするのは安全 — apiRequestBreakdownHistogram.record(value, {model, phase}) は phase をラベルとするヒストグラムであり、欠損ラベルはクエリに存在しないだけ。

NETWORK_LATENCY を再定義しない理由: スペックの名前は若干誤解を招く (純粋なネットワークレイテンシではなく、ネットワーク + 最初のトークン生成) が:

• enumは metrics.ts:330-334 に含まれ、index.ts:117 からエクスポートされ、テストされている。
• バックエンドダッシュボードはすでにこれらのフェーズ名を参照している可能性がある。
• リネームや新しいフェーズの追加は、わずかな精度向上のための破壊的変更になる。

設計文書でセマンティクスを文書化し、enumは変更しない。

スパンパスに置き、並列でなくする理由: recordApiRequestBreakdown をスパン属性の書き込みと同じ場所に置くことで — 単一のゲートされた送出ポイント (D7のべき等性参照)、単一の順序制約となる。

D7 — endLLMRequestSpan のべき等性: 既存のダブルエンドガードでゲートされたメトリクス記録

フェーズ1.5 (#4302) で endLLMRequestSpan が2回呼び出される可能性があることが確立された (中断パス + エラーパスの衝突)。session-tracing.ts:~470 の既存ガード (if (!activeSpans.has(...)) return;) はダブル span.end() を防ぐ。フェーズ4のメトリクス記録 (D6) は 同じガードブロック内、span.end() の前に位置しなければならない:

// session-tracing.ts — endLLMRequestSpan
const llmCtx = activeSpans.get(spanRef);
if (!llmCtx) return;            // すでに終了 — ダブルエンドガード
activeSpans.delete(spanRef);    // 終了を確定
 
// ... durationを計算し、属性を設定 ...
if (metadata) {
  recordApiRequestBreakdown(config, llmCtx.attributes.model, [...]);   // 新規 — ゲートされている
  recordTokenUsageMetrics(...); // 既存
}
 
span.end();

これにより、LLMリクエストごとにメトリクスが正確に1回記録され、スパンライフサイクルと一致することが保証される。

loggingContentGenerator で記録しない理由: 中断パスを検知できない。スパンライフサイクルレイヤーで記録することで、スパンを開いたすべてのLLMリクエストが成功/失敗/中断に関わらず正確に1つのbreakdownサンプルを生成することが保証される。

D8 — GenAI セマンティックコンベンション デュアルエミット (プライベート名が正規)

GenAI semconv属性に対応するフェーズ4の各属性はスパンに2回書き込まれる:

LLMスパンの既存トークン属性名 (endLLMRequestSpan でフェーズ4より前に設定): qwen-codeはすでにベア名の input_tokens と output_tokens を使用している。フェーズ4は #4410 のパターンに合わせて gen_ai.usage.* の兄弟を追加する。ベア名は残す。リネームしない。

GenAI semconv に相当するものがないフィールド — request_setup_ms、sampling_ms、retry_total_delay_ms、attempt、output_tokens_per_second — はqwen-code名前空間のみで送出される。

「プライベートが正規、semconv は互換」の理由:

• 内部ダッシュボード、SLO、debugLogger出力、qwen-logger RUM、ARMSクエリ — すべて ttft_ms 等を参照する。これらを正規として扱うことで、一斉移行が不要になる。
• Experimental GenAI semconv は Stable に達する前に gen_ai.server.time_to_first_token をリネームする可能性がある。その場合はsemconv送出を更新するが、qwen-codeの名前は変わらない。
• 将来のスペック対応バックエンド (Datadog AI views、Honeycomb AI、ARMS GenAI dashboards) は私たちの関与なしに gen_ai.* 属性を自動的に取得する。

デュアルエミット単位変換の理由 (ms ↔ 秒): GenAI semconv はレイテンシに秒をdoubleとして選択したが、qwen-codeはms-as-int を選択した (スパン上の既存の duration_ms と一致)。両方の表現に価値があり、変換は安価。

ヘルパーAPI (session-tracing.ts への加算)

// 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;
}
 
// 新しいエクスポートヘルパーなし — フェーズ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;
}
 
// retryWithBackoff 内、今日 logRetryAttempt が呼び出されている箇所:
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 を使用 (フェーズ1)
  // 使用中のリトライレイヤーに onRetry コールバックを渡す:
  const onRetry: RetryAttemptInfo & { invoke: ... } = (info) => {
    finalAttempt = info.attempt + 1;        // 試行 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;
    },
  });
}

スパン終了時 (フェーズ1の endLLMRequestSpan フローにすでにある)、LLMRequestMetadata に新しいフィールドを含める:

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

非ストリーミングパス

generateContent (loggingContentGenerator.ts:212) はストリーミングチャンクを生成しない。TTFTは undefined。request_setup_ms は引き続き意味を持つ (リトライオーバーヘッドを捉える)。breakdownメトリクスは3フェーズではなく2フェーズ (REQUEST_PREPARATION + RESPONSE_PROCESSING、RESPONSE_PROCESSING = duration_ms - request_setup_ms) を記録する。

リトライレイヤーの統合 (4サイト)

4つのLLM retryWithBackoff 呼び出しサイトそれぞれに onRetry を追加する:

// 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 を経由しない呼び出し元では、
    // endLLMRequestSpan がLLMレイヤーで呼び出されるため、LLMスパンはメタデータパス経由で
    // `attempt` と `retry_total_delay_ms` を受け取る)
  },
});

非LLM呼び出し元 (channels/weixin/src/api.ts) は onRetry を登録しない — そのリトライで ApiRetryEvent は送出されず、今日の動作と一致する。

並行安全性 — 主要な保証

LoggingContentGenerator インスタンスは共有される (ContentGenerator ごとに1つ、contentGenerator.ts:377)。3つの並行する generateContentStream 呼び出し (例: coreToolScheduler.runConcurrently 経由で3つのサブエージェントがファンアウト) は generateContentStream の3つの独立したクロージャを実行する:

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

呼び出しごとのローカルは重なることがない。ストリームチャンクは各呼び出しのローカル attemptStart に対して検出される。スパン属性は各呼び出し自身の endLLMRequestSpan で設定される。

AsyncLocalStorageContextManager (NodeSDKにより sdk.ts:273 で登録) はアクティブなOTelコンテキスト — したがって startLLMRequestSpan に渡される親スパン — がファイバーごとに正しいことをすでに保証している。

変更ファイル

合計: 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 に依存。

テスト戦略

エッジケース

ロールバック

変更は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.llm_request スパンに付与され、qwen-code.subagent (フェーズ3) 配下にあるか qwen-code.interaction (フェーズ1) 配下にあるかに関わらず機能する。サブエージェントサブツリー配下での試行ごとの集計が自然に機能するよう、フェーズ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 フェーズ: enum値を休眠状態のままにするか、何か (例: 統合時間) に配線するか？延期 — 実際のユースケースを待つ。
5. サブエージェントレベルのLLMロールアップ: フェーズ4がリリースされれば trivial なフォローアップ — サブエージェントサブツリーごとに ttft_ms/output_tokens/input_tokens を合計する。フェーズ4のスコープではないが、データフローはそれを可能にする。