fix(logs): measure the decode rate over the generation window

docs-site/src/content/docs/guides/web-dashboard.md

@@ -154,6 +154,13 @@ fallback until a valid sample is available. Speed uses output tokens per second
 full request duration: below 15, 15 to below 50, or at least 50. Unavailable speed values are
 excluded when a speed filter is active. Success means 2xx; errors mean 4xx or 5xx.
 
+The request detail also shows **Decode rate (est.)**. When the proxy observed both ends, it is
+output tokens over the generation window: from the first output item or block, reasoning included,
+to the last output delta. Older rows without that window use the time after the first visible
+token instead. Both are proxy-side observations, not the provider's internal token timing, so the
+value is always an estimate, and a window under one second shows as unavailable. The end-to-end
+tok/s column and speed filter above are not affected.
+
 Active filters show the matching count out of the loaded total. Reset filters restores all
 rows and returns keyboard focus to the All surface control; “No matching requests”
 differs from an empty log ring. Use arrow keys or Home/End in

gui/src/i18n/de.ts

@@ -1011,7 +1011,7 @@ export const de: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "Dekodierrate (geschätzt)",
   "logs.detail.reason.ttft_missing": "Für diese Anfrage wurde keine Zeit bis zum ersten Token erfasst, es gibt also kein Dekodierfenster zum Messen.",
-  "logs.detail.reason.decode_window_too_short": "Das Fenster nach dem ersten Token lag unter einer Sekunde und ist zu kurz für eine Schätzung der Dekodierrate.",
+  "logs.detail.reason.decode_window_too_short": "Das gemessene Ausgabefenster lag unter einer Sekunde und ist zu kurz für eine Schätzung der Dekodierrate.",
   "logs.detail.costTotal": "Listenpreis-Äquivalent",
   "logs.detail.totalTokens": "Tokens gesamt",
   "logs.detail.matchedKey": "Zugeordneter Preisschlüssel",

gui/src/i18n/en.ts

@@ -1069,7 +1069,7 @@ export const en = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "Decode rate (est.)",
   "logs.detail.reason.ttft_missing": "No time-to-first-token was recorded for this request, so there is no decode window to measure.",
-  "logs.detail.reason.decode_window_too_short": "The window after the first token was under a second, which is too short to estimate a decode rate from.",
+  "logs.detail.reason.decode_window_too_short": "The measured output window was under a second, which is too short to estimate a decode rate from.",
   "logs.detail.costTotal": "List-price equivalent",
   "logs.detail.totalTokens": "Total tokens",
   "logs.detail.matchedKey": "Matched price key",

gui/src/i18n/fr.ts

@@ -1050,7 +1050,7 @@ export const fr: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "Débit de décodage (est.)",
   "logs.detail.reason.ttft_missing": "Aucun délai jusqu’au premier token n’a été enregistré pour cette requête, il n’y a donc pas de fenêtre de décodage à mesurer.",
-  "logs.detail.reason.decode_window_too_short": "La fenêtre après le premier token durait moins d’une seconde, ce qui est trop court pour estimer un débit de décodage.",
+  "logs.detail.reason.decode_window_too_short": "La fenêtre de sortie mesurée durait moins d’une seconde, ce qui est trop court pour estimer un débit de décodage.",
   "logs.detail.costTotal": "Équivalent au tarif catalogue",
   "logs.detail.totalTokens": "Nombre total de jetons",
   "logs.detail.matchedKey": "Clé de tarif correspondante",

gui/src/i18n/ja.ts

@@ -952,7 +952,7 @@ export const ja: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "デコード速度（推定）",
   "logs.detail.reason.ttft_missing": "このリクエストでは最初のトークンまでの時間が記録されていないため、測定できるデコード区間がありません。",
-  "logs.detail.reason.decode_window_too_short": "最初のトークン以降の区間が1秒未満で、デコード速度を推定するには短すぎます。",
+  "logs.detail.reason.decode_window_too_short": "計測された出力区間が1秒未満で、デコード速度を推定するには短すぎます。",
   "logs.detail.costTotal": "定価相当額",
   "logs.detail.totalTokens": "合計トークン",
   "logs.detail.matchedKey": "一致した価格キー",

gui/src/i18n/ko.ts

@@ -1050,7 +1050,7 @@ export const ko: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "디코드 속도(추정)",
   "logs.detail.reason.ttft_missing": "이 요청은 첫 토큰까지 걸린 시간이 기록되지 않아서 측정할 디코드 구간이 없어요.",
-  "logs.detail.reason.decode_window_too_short": "첫 토큰 이후 구간이 1초도 안 돼서 디코드 속도를 추정하기엔 너무 짧아요.",
+  "logs.detail.reason.decode_window_too_short": "측정된 출력 구간이 1초도 안 돼서 디코드 속도를 추정하기엔 너무 짧아요.",
   "logs.detail.costTotal": "정가 환산치",
   "logs.detail.totalTokens": "전체 토큰",
   "logs.detail.matchedKey": "매칭된 가격 키",

gui/src/i18n/ru.ts

@@ -1028,7 +1028,7 @@ export const ru: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "Скорость декодирования (оценка)",
   "logs.detail.reason.ttft_missing": "Для этого запроса не записано время до первого токена, поэтому измерять нечего.",
-  "logs.detail.reason.decode_window_too_short": "Окно после первого токена длилось меньше секунды — слишком мало для оценки скорости декодирования.",
+  "logs.detail.reason.decode_window_too_short": "Измеренное окно вывода длилось меньше секунды — слишком мало для оценки скорости декодирования.",
   "logs.detail.costTotal": "Эквивалент по прайс-листу",
   "logs.detail.totalTokens": "Всего токенов",
   "logs.detail.matchedKey": "Совпавший ключ цены",

gui/src/i18n/tr.ts

@@ -1055,7 +1055,7 @@ export const tr: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "Çözme hızı (tahmini)",
   "logs.detail.reason.ttft_missing": "Bu istek için ilk token süresi kaydedilmediğinden ölçülecek bir çözme aralığı yok.",
-  "logs.detail.reason.decode_window_too_short": "İlk token sonrasındaki aralık bir saniyenin altındaydı; çözme hızını tahmin etmek için fazla kısa.",
+  "logs.detail.reason.decode_window_too_short": "Ölçülen çıktı aralığı bir saniyenin altındaydı; çözme hızını tahmin etmek için fazla kısa.",
   "logs.detail.costTotal": "Liste fiyatı eşdeğeri",
   "logs.detail.totalTokens": "Toplam jeton",
   "logs.detail.matchedKey": "Eşleşen anahtar",

gui/src/i18n/vi.ts

@@ -1049,7 +1049,7 @@ export const vi: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "Tốc độ decode (ước tính)",
   "logs.detail.reason.ttft_missing": "Không ghi nhận thời gian đến token đầu tiên (time-to-first-token) cho request này, nên không có cửa sổ decode nào để đo lường.",
-  "logs.detail.reason.decode_window_too_short": "Cửa sổ sau token đầu tiên nhỏ hơn một giây, quá ngắn để ước tính tốc độ decode.",
+  "logs.detail.reason.decode_window_too_short": "Cửa sổ đầu ra đo được nhỏ hơn một giây, quá ngắn để ước tính tốc độ decode.",
   "logs.detail.costTotal": "Tương đương giá niêm yết",
   "logs.detail.totalTokens": "Tổng số tokens",
   "logs.detail.matchedKey": "Khoá giá trùng khớp (Matched price key)",

gui/src/i18n/zh-TW.ts

@@ -829,7 +829,7 @@ export const zhTW: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "解碼速率（估算）",
   "logs.detail.reason.ttft_missing": "此請求沒有記錄第一個 token 的時間，因此沒有可測量的解碼區間。",
-  "logs.detail.reason.decode_window_too_short": "第一個 token 之後的區間不到一秒，太短，無法估算解碼速率。",
+  "logs.detail.reason.decode_window_too_short": "測得的輸出區間不到一秒，太短，無法估算解碼速率。",
   "logs.detail.costTotal": "標價折算",
   "logs.detail.totalTokens": "Token 總數",
   "logs.detail.matchedKey": "符合的 jawcode 鍵",

gui/src/i18n/zh.ts

@@ -1023,7 +1023,7 @@ export const zh: Record<TKey, string> = {
   "logs.detail.ttft": "TTFT",
   "logs.detail.decodeTokPerSec": "解码速率（估算）",
   "logs.detail.reason.ttft_missing": "该请求没有记录首个 token 的时间，因此没有可测量的解码区间。",
-  "logs.detail.reason.decode_window_too_short": "首个 token 之后的区间不足一秒，太短，无法估算解码速率。",
+  "logs.detail.reason.decode_window_too_short": "测得的输出区间不足一秒，太短，无法估算解码速率。",
   "logs.detail.costTotal": "标价折算",
   "logs.detail.totalTokens": "Token 总数",
   "logs.detail.matchedKey": "匹配的价格键",

scripts/test-layout/layout.json

@@ -1458,6 +1458,7 @@
     "request-log-nonstream.test.ts": "usage",
     "request-log-protocol-trace.test.ts": "usage",
     "request-log-served-model.test.ts": "usage",
+    "request-log-generation-window.test.ts": "usage",
     "request-log.test.ts": "usage",
     "request-outcome-agreement.test.ts": "usage",
     "request-pacing.test.ts": "usage",

src/server/claude-messages.ts

@@ -61,6 +61,7 @@ import { resolveWireProtocolOverride } from "./adapter-resolve";
 import type { OcxConfig } from "../types";
 import { readJsonRequestBody, resolveInboundBodyLimitBytes } from "./request-decompress";
 import { addFinalRequestLog, httpStatusForRequestLogTerminal, recordFirstOutput, type RequestLogContext } from "./request-log";
+import { recordGenerationEvent } from "./request-log-generation-window";
 import { createFinalRequestLog } from "./inference/final-log";
 import {
   conversationIdFromClaudeMetadata,
@@ -334,6 +335,7 @@ export function tapAnthropicSseForLog(
     let data: unknown;
     try { data = JSON.parse(dataLine); } catch { return; }
     if (!isRec(data)) return;
+    recordGenerationEvent(logCtx, data.type);
     if (data.type === "message_start" && isRec(data.message) && isRec(data.message.usage)) {
       usageAcc = { ...usageAcc, ...data.message.usage };
     } else if (data.type === "message_delta" && isRec(data.usage)) {

src/server/management/shared.ts

@@ -100,7 +100,7 @@ export type CostResult =
   | { kind: "value"; estimate: NonNullable<ReturnType<typeof estimateRequestCost>>; estimateReasons: CostEstimateReason[] }
   | { kind: "unavailable"; reason: MetricUnavailableReason };
 
-export type MetricSource = Pick<RequestLogEntry, "provider" | "model" | "durationMs" | "firstOutputMs" | "usageStatus" | "usage" | "requestedServiceTier" | "configuredServiceTier" | "responseServiceTier" | "tierOutcome" | "routeDecision" | "cacheProvenance"> & {
+export type MetricSource = Pick<RequestLogEntry, "provider" | "model" | "durationMs" | "firstOutputMs" | "genStartMs" | "lastOutputMs" | "usageStatus" | "usage" | "requestedServiceTier" | "configuredServiceTier" | "responseServiceTier" | "tierOutcome" | "routeDecision" | "cacheProvenance"> & {
   attempts?: readonly PersistedUsageAttempt[];
 };
 
@@ -129,24 +129,38 @@ export function tokPerSecondResult(entry: Pick<MetricSource, "durationMs" | "usa
 export const MIN_DECODE_WINDOW_MS = 1_000;
 
 /**
- * Estimated DECODE throughput: output tokens over the window after the first token (#4038).
+ * Estimated DECODE throughput: output tokens over the measured output window (#4038): the generation window when
+ * recorded, otherwise the window after the first token.
  *
- * Strictly additive. `tokensPerSecond`, `tokPerSecondResult`, `RequestLogEntry` and
- * `usage.jsonl` are untouched, and the end-to-end rate beside it keeps meaning exactly what it
+ * Strictly additive. `tokensPerSecond` and `tokPerSecondResult` are untouched, rows only gain the
+ * optional window pair, and the end-to-end rate beside it keeps meaning exactly what it
  * has always meant — it is documented as end-to-end, so this is a missing metric rather than a
  * miscalculated one.
  *
  * Always `estimated: true`. The proxy's TTFT is when the FIRST BYTE reached the proxy, which is
  * not the provider's own generation start, so this can never be more than an estimate no matter
  * how long the window is. Saying so in the payload is the honest half of the answer to #4040;
  * MIN_DECODE_WINDOW_MS is the other half.
+ *
+ * When the row carries the generation window (`genStartMs` / `lastOutputMs`, #6309) that window is
+ * used instead. `firstOutputMs` is the first VISIBLE delta, so on a reasoning model the post-TTFT
+ * window leaves out the reasoning phase while `outputTokens` still counts its tokens; the
+ * generation window spans both and stops at the last delta rather than at stream close.
  */
 export function decodeTokPerSecondResult(
-  entry: Pick<MetricSource, "durationMs" | "firstOutputMs" | "usageStatus" | "usage">,
+  entry: Pick<MetricSource, "durationMs" | "firstOutputMs" | "genStartMs" | "lastOutputMs" | "usageStatus" | "usage">,
 ): TokPerSecondResult {
   if (!entry.usage) return { kind: "unavailable", reason: "usage_missing" };
   if (entry.usageStatus === "unsupported") return { kind: "unavailable", reason: "usage_unsupported" };
   if (entry.usage.outputTokens <= 0) return { kind: "unavailable", reason: "output_missing" };
+  const { genStartMs, lastOutputMs } = entry;
+  if (genStartMs !== undefined && lastOutputMs !== undefined && Number.isFinite(genStartMs) && Number.isFinite(lastOutputMs)) {
+    const generationMs = lastOutputMs - genStartMs;
+    if (generationMs <= 0) return { kind: "unavailable", reason: "invalid_duration" };
+    if (generationMs < MIN_DECODE_WINDOW_MS) return { kind: "unavailable", reason: "decode_window_too_short" };
+    const value = tokensPerSecond(entry.usage.outputTokens, generationMs);
+    return value === null ? { kind: "unavailable", reason: "invalid_duration" } : { kind: "value", value, estimated: true };
+  }
   // A row that predates TTFT capture, or a non-streaming turn that never recorded one, has no
   // window to measure. That is a different fact from a bad duration, so it gets its own reason.
   if (entry.firstOutputMs === undefined) return { kind: "unavailable", reason: "ttft_missing" };

src/server/request-log-generation-window.ts

@@ -0,0 +1,38 @@
+import type { RequestLogContext } from "./request-log";
+
+/**
+ * Generation window for the decode-rate estimate (#4038, #6309).
+ *
+ * `firstOutputMs` marks the first VISIBLE output delta. For a reasoning model that is the end of
+ * the reasoning phase, yet `outputTokens` includes the reasoning tokens, so
+ * `outputTokens / (durationMs - firstOutputMs)` divides the whole output by only part of the time
+ * that produced it. The window recorded here starts when the model starts producing ANY output
+ * item (reasoning included) and ends at the last output delta, so trailing stream bookkeeping
+ * after the final token does not count either.
+ *
+ * Event vocabulary: Anthropic `content_block_start` / `content_block_delta`, and Responses
+ * `response.output_item.added` / `response.*.delta`. Anything else leaves the window untouched.
+ */
+export function recordGenerationEvent(logCtx: RequestLogContext, type: unknown, now = Date.now()): void {
+  if (typeof type !== "string" || !Number.isFinite(now)) return;
+  if (type === "content_block_start" || type === "response.output_item.added") {
+    logCtx.generationStartedAt ??= now;
+  } else if (type === "content_block_delta" || (type.startsWith("response.") && type.endsWith(".delta"))) {
+    logCtx.generationStartedAt ??= now;
+    logCtx.lastOutputAt = now;
+  }
+}
+
+/** Request-relative `genStartMs` / `lastOutputMs`, present only when both ends were observed. */
+export function generationWindowFields(
+  logCtx: Pick<RequestLogContext, "generationStartedAt" | "lastOutputAt">,
+  requestStartedAt: number,
+): { genStartMs?: number; lastOutputMs?: number } {
+  const startedAt = logCtx.generationStartedAt;
+  const lastAt = logCtx.lastOutputAt;
+  if (startedAt === undefined || lastAt === undefined || !Number.isFinite(requestStartedAt)) return {};
+  return {
+    genStartMs: Math.max(0, startedAt - requestStartedAt),
+    lastOutputMs: Math.max(0, lastAt - requestStartedAt),
+  };
+}

src/server/request-log.ts

@@ -85,6 +85,7 @@ import {
   normalizePersistedJevDecision,
   type PersistedJevDecisionV1,
 } from "../usage/jev-stats";
+import { generationWindowFields, recordGenerationEvent } from "./request-log-generation-window";
 import type { RequestMetricsRecorder } from "./request-metrics";
 import type {
   CacheDiagnosticDraft,
@@ -136,6 +137,9 @@ export interface RequestLogContext {
   affinityMoveReasons?: CodexAffinityReason[];
   /** TTFT: ms from request start to the first non-empty model output delta (WP4, devlog 040). */
   firstOutputMs?: number;
+  /** Epoch ms of the first output item and of the last output delta; see request-log-generation-window.ts. */
+  generationStartedAt?: number;
+  lastOutputAt?: number;
   /** Best-effort chat/session correlation for Logs grouping (#330). Opaque; omit when unknown. */
   conversationId?: string;
   surface?: "claude" | "claude-desktop" | "grok";
@@ -282,6 +286,9 @@ export interface RequestLogEntry {
   provider: string;
   /** TTFT: ms from request start to the first non-empty model output delta; unset for non-streaming/tool-only. */
   firstOutputMs?: number;
+  /** Request-relative generation window (#6309): first output item of any kind, then the last output delta. */
+  genStartMs?: number;
+  lastOutputMs?: number;
   surface?: "claude" | "claude-desktop" | "grok";
   /**
    * Set when the proxy answered this turn locally and sent nothing upstream. Without it a zero-send
@@ -453,6 +460,8 @@ export function requestLogEntryFromPersistedUsage(entry: PersistedUsageEntry): R
     model: entry.model,
     provider: entry.provider,
     ...(entry.firstOutputMs !== undefined ? { firstOutputMs: entry.firstOutputMs } : {}),
+    ...(entry.genStartMs !== undefined ? { genStartMs: entry.genStartMs } : {}),
+    ...(entry.lastOutputMs !== undefined ? { lastOutputMs: entry.lastOutputMs } : {}),
     ...(isKnownUsageSurface(entry.surface) ? { surface: entry.surface } : {}),
     ...(entry.conversationId ? { conversationId: entry.conversationId } : {}),
     ...(isCodexUsageAccountLogLabel(entry.accountLogLabel)
@@ -668,6 +677,8 @@ export function addRequestLog(entry: RequestLogEntry) {
       status: entry.status,
       durationMs: entry.durationMs,
       ...(entry.firstOutputMs !== undefined ? { firstOutputMs: entry.firstOutputMs } : {}),
+      ...(entry.genStartMs !== undefined ? { genStartMs: entry.genStartMs } : {}),
+      ...(entry.lastOutputMs !== undefined ? { lastOutputMs: entry.lastOutputMs } : {}),
       usageStatus: entry.usageStatus,
       ...(entry.usage ? { usage: entry.usage } : {}),
       ...(entry.totalTokens !== undefined ? { totalTokens: entry.totalTokens } : {}),
@@ -1056,6 +1067,7 @@ export function inspectResponseLogSsePayloadParsed(
   if (!payload || payload.trim() === "[DONE]") return;
   const debugEnabled = isUsageDebugEnabled();
   const sseAlreadyMarked = logCtx.usageDebugBodyKind === "sse";
+  if (parsed !== undefined) recordGenerationEvent(logCtx, (parsed as { type?: unknown } | null)?.type);
   if (parsed !== undefined) applyResponseLogMetadata(logCtx, parsed);
   else logCtx.activeTierMetadata?.markResponseUnparseable();
   captureUpstreamErrorParsed(logCtx, payload, parsed);
@@ -1571,6 +1583,7 @@ export function addFinalRequestLog(
     status: effectiveStatus,
     durationMs,
     ...(logCtx.firstOutputMs !== undefined ? { firstOutputMs: logCtx.firstOutputMs } : {}),
+    ...generationWindowFields(logCtx, start),
     ...(errorCode ? { errorCode } : {}),
     ...(meta?.terminalStatus ? { terminalStatus: meta.terminalStatus } : {}),
     ...(closeReason ? { closeReason } : {}),