diff --git a/docs-site/src/content/docs/guides/web-dashboard.md b/docs-site/src/content/docs/guides/web-dashboard.md index 3a4c01848ff..5698cd2b7d8 100644 --- a/docs-site/src/content/docs/guides/web-dashboard.md +++ b/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 diff --git a/gui/src/i18n/de.ts b/gui/src/i18n/de.ts index 0d41a71b036..893cda559c8 100644 --- a/gui/src/i18n/de.ts +++ b/gui/src/i18n/de.ts @@ -1011,7 +1011,7 @@ export const de: Record = { "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", diff --git a/gui/src/i18n/en.ts b/gui/src/i18n/en.ts index b71168448c5..2cfcde37e3f 100644 --- a/gui/src/i18n/en.ts +++ b/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", diff --git a/gui/src/i18n/fr.ts b/gui/src/i18n/fr.ts index 01b2f499219..0e9c89834cd 100644 --- a/gui/src/i18n/fr.ts +++ b/gui/src/i18n/fr.ts @@ -1050,7 +1050,7 @@ export const fr: Record = { "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", diff --git a/gui/src/i18n/ja.ts b/gui/src/i18n/ja.ts index e3f01974249..d33cd3ef4d9 100644 --- a/gui/src/i18n/ja.ts +++ b/gui/src/i18n/ja.ts @@ -952,7 +952,7 @@ export const ja: Record = { "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": "一致した価格キー", diff --git a/gui/src/i18n/ko.ts b/gui/src/i18n/ko.ts index 7c667aadc75..7708b3d651a 100644 --- a/gui/src/i18n/ko.ts +++ b/gui/src/i18n/ko.ts @@ -1050,7 +1050,7 @@ export const ko: Record = { "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": "매칭된 가격 키", diff --git a/gui/src/i18n/ru.ts b/gui/src/i18n/ru.ts index 9f6b89fbf03..e201bb13dbc 100644 --- a/gui/src/i18n/ru.ts +++ b/gui/src/i18n/ru.ts @@ -1028,7 +1028,7 @@ export const ru: Record = { "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": "Совпавший ключ цены", diff --git a/gui/src/i18n/tr.ts b/gui/src/i18n/tr.ts index 596ddc56929..f94f229e261 100644 --- a/gui/src/i18n/tr.ts +++ b/gui/src/i18n/tr.ts @@ -1055,7 +1055,7 @@ export const tr: Record = { "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", diff --git a/gui/src/i18n/vi.ts b/gui/src/i18n/vi.ts index fda93dd64fb..e29e41d13a9 100644 --- a/gui/src/i18n/vi.ts +++ b/gui/src/i18n/vi.ts @@ -1049,7 +1049,7 @@ export const vi: Record = { "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)", diff --git a/gui/src/i18n/zh-TW.ts b/gui/src/i18n/zh-TW.ts index 46d84a91689..c934c5f6eaa 100644 --- a/gui/src/i18n/zh-TW.ts +++ b/gui/src/i18n/zh-TW.ts @@ -829,7 +829,7 @@ export const zhTW: Record = { "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 鍵", diff --git a/gui/src/i18n/zh.ts b/gui/src/i18n/zh.ts index 0ffc79db81f..32dab4555dd 100644 --- a/gui/src/i18n/zh.ts +++ b/gui/src/i18n/zh.ts @@ -1023,7 +1023,7 @@ export const zh: Record = { "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": "匹配的价格键", diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index fde377d7131..52fb611b2af 100644 --- a/scripts/test-layout/layout.json +++ b/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", diff --git a/src/server/claude-messages.ts b/src/server/claude-messages.ts index b0753e3ef12..ff2b106757a 100644 --- a/src/server/claude-messages.ts +++ b/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)) { diff --git a/src/server/management/shared.ts b/src/server/management/shared.ts index 2e1c88a374a..559fb4dca69 100644 --- a/src/server/management/shared.ts +++ b/src/server/management/shared.ts @@ -100,7 +100,7 @@ export type CostResult = | { kind: "value"; estimate: NonNullable>; estimateReasons: CostEstimateReason[] } | { kind: "unavailable"; reason: MetricUnavailableReason }; -export type MetricSource = Pick & { +export type MetricSource = Pick & { attempts?: readonly PersistedUsageAttempt[]; }; @@ -129,10 +129,11 @@ export function tokPerSecondResult(entry: Pick, + entry: Pick, ): 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" }; diff --git a/src/server/request-log-generation-window.ts b/src/server/request-log-generation-window.ts new file mode 100644 index 00000000000..38503d38581 --- /dev/null +++ b/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, + 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), + }; +} diff --git a/src/server/request-log.ts b/src/server/request-log.ts index e34737ba04f..353a85a281d 100644 --- a/src/server/request-log.ts +++ b/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 } : {}), diff --git a/src/usage/log.ts b/src/usage/log.ts index 3bb24c940eb..627f19834dd 100644 --- a/src/usage/log.ts +++ b/src/usage/log.ts @@ -347,6 +347,9 @@ export interface PersistedUsageEntry { durationMs: number; /** TTFT relative to the request start (WP4); unset for non-streaming/tool-only. */ firstOutputMs?: number; + /** Request-relative generation window (#6309): first output item, last output delta. Written as a pair. */ + genStartMs?: number; + lastOutputMs?: number; usageStatus: UsageStatus; usage?: OcxUsage; totalTokens?: number; @@ -1035,6 +1038,10 @@ function normalizeUsageEntry(entry: PersistedUsageEntry): PersistedUsageEntry { ...(isNonNegativeFiniteNumber(entry.firstOutputMs) ? { firstOutputMs: entry.firstOutputMs } : {}), + ...(isNonNegativeFiniteNumber(entry.genStartMs) && isNonNegativeFiniteNumber(entry.lastOutputMs) + && entry.lastOutputMs >= entry.genStartMs + ? { genStartMs: entry.genStartMs, lastOutputMs: entry.lastOutputMs } + : {}), usageStatus: entry.usageStatus, ...(entry.usage ? { usage: normalizeUsageValue(entry.usage) } : {}), ...(typeof entry.totalTokens === "number" ? { totalTokens: entry.totalTokens } : {}), diff --git a/structure/dashboard-and-usage.md b/structure/dashboard-and-usage.md index 90536160170..dc58644dd8c 100644 --- a/structure/dashboard-and-usage.md +++ b/structure/dashboard-and-usage.md @@ -189,7 +189,6 @@ current physical response contribution, preserving prior sends on the same key w repeated inspections twice. Consumers sum the flat attempts once and keep subscription quota observations separate from token or API-equivalent cost totals. - `src/server/hub-usage.ts` serves `GET /v1/usage` on hubs for an explicit configured data key. The authenticated key selects the aggregate; query parameters cannot select an API-key identity. Unscoped environment/admin credentials and loopback bypass are not admitted. The response projects only this client's numeric totals, provider/model/day rows and incomplete-history metadata through `src/remote/hub-usage.ts`; accounts, raw records and key IDs are omitted. Unknown fields are stripped at every object boundary and the serialized body is capped at 1 MiB. Custom usage windows are immutable bounds on the streaming accumulator, applied before attribution and daily @@ -555,7 +554,6 @@ enabling it takes effect without a restart. unobserved. `src/quota/reset-activation.ts` installs the sink independently of the poller, so `pollSeconds: 0` observes live traffic only. - ## Usage history and model identity `src/server/request-log.ts` preserves upstream `servedModel` independently of route-derived @@ -572,6 +570,8 @@ re-validated on read; the Logs list shows it as a text badge, the detail dialog `src/server/request-log-filter.ts` owns the `/api/logs` query filters including `protocolMode`; its single-pass query applies provider, conversation, model, account, protocol mode and status before `tail`, then reports the pre-pagination count alongside the offset/limit page. [Protocol Paths](data-planes/protocol-paths.md) owns its derivation. +Rows may also carry `genStartMs` and `lastOutputMs`, an observed request-relative pair recorded by `src/server/request-log-generation-window.ts` from the Responses and Anthropic SSE taps: the first output item or content block (reasoning included) to the last output delta. They are proxy observation times, not provider-internal token timing, and `src/usage/log.ts` keeps them only as a pair of nonnegative finite values with `lastOutputMs >= genStartMs`. `decodeTokPerSecondResult` in `src/server/management/shared.ts` prefers that window when the pair is valid and otherwise falls back to the post-TTFT window (`durationMs - firstOutputMs`); both keep the one-second minimum, the `ttft_missing` / `decode_window_too_short` unavailable reasons and `estimated: true`, so a short measured window is still an estimate rather than a provider decode benchmark. The end-to-end tok/s column is unchanged, attempts carry no generation window of their own, and the request-history view does not present one. + Request-history selectors longer than 130 characters persist as a prefix plus a digest of the complete selector; exact-match filtering uses the same idempotent encoding. The derived index rebuilds when its projection version changes and encodes older raw-selector rows from canonical JSONL so exact filters diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index 46c16b4174a..830a1e08f78 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1469,6 +1469,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", diff --git a/tests/usage/request-log-generation-window.test.ts b/tests/usage/request-log-generation-window.test.ts new file mode 100644 index 00000000000..56e484943ba --- /dev/null +++ b/tests/usage/request-log-generation-window.test.ts @@ -0,0 +1,107 @@ +import { expect, test } from "bun:test"; +import { mkdtempSync, readFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { tapAnthropicSseForLog } from "../../src/server/claude-messages"; +import { decodeTokPerSecondResult } from "../../src/server/management/shared"; +import { + addFinalRequestLog, + clearRequestLogsForTests, + inspectResponseLogSsePayload, + type RequestLogContext, +} from "../../src/server/request-log"; +import { generationWindowFields, recordGenerationEvent } from "../../src/server/request-log-generation-window"; +import { normalizeUsageEntryForTest, resetUsageReadCacheForTests, usageLogPath } from "../../src/usage/log"; +import { removeTreeWithRetry } from "../helpers/remove-tree"; + +const ctx = (): RequestLogContext => ({ model: "m", provider: "openai" }); + +test("the window opens at the first output item, reasoning included, and closes at the last delta", () => { + const responses = ctx(); + recordGenerationEvent(responses, "response.created", 100); + recordGenerationEvent(responses, "response.output_item.added", 1_000); // reasoning item + recordGenerationEvent(responses, "response.reasoning_summary_text.delta", 2_000); + recordGenerationEvent(responses, "response.output_item.added", 6_000); // first visible item + recordGenerationEvent(responses, "response.output_text.delta", 9_000); + recordGenerationEvent(responses, "response.completed", 9_500); + expect(generationWindowFields(responses, 0)).toEqual({ genStartMs: 1_000, lastOutputMs: 9_000 }); + + const anthropic = ctx(); + recordGenerationEvent(anthropic, "message_start", 50); + recordGenerationEvent(anthropic, "content_block_start", 400); // thinking block + recordGenerationEvent(anthropic, "content_block_delta", 700); + recordGenerationEvent(anthropic, "content_block_delta", 3_400); + recordGenerationEvent(anthropic, "message_delta", 3_600); + recordGenerationEvent(anthropic, "message_stop", 3_700); + expect(generationWindowFields(anthropic, 100)).toEqual({ genStartMs: 300, lastOutputMs: 3_300 }); +}); + +test("no window is reported until an output delta has been seen", () => { + const started = ctx(); + recordGenerationEvent(started, "response.output_item.added", 1_000); + recordGenerationEvent(started, undefined, 2_000); + expect(generationWindowFields(started, 0)).toEqual({}); +}); + +test("the decode rate uses the generation window when the row carries one", () => { + // A reasoning turn: 800 output tokens (reasoning included) generated from 1s to 9s, first + // VISIBLE delta at 6s, stream closed at 10s. The post-TTFT window would be 4s and report 200. + const row = { durationMs: 10_000, firstOutputMs: 6_000, usageStatus: "reported" as const, usage: { inputTokens: 10, outputTokens: 800 } }; + expect(decodeTokPerSecondResult(row)).toEqual({ kind: "value", value: 200, estimated: true }); + expect(decodeTokPerSecondResult({ ...row, genStartMs: 1_000, lastOutputMs: 9_000 })) + .toEqual({ kind: "value", value: 100, estimated: true }); + // The floor still applies, and a generation window never falls back to the TTFT window. + expect(decodeTokPerSecondResult({ ...row, genStartMs: 8_500, lastOutputMs: 9_000 })) + .toEqual({ kind: "unavailable", reason: "decode_window_too_short" }); + expect(decodeTokPerSecondResult({ ...row, genStartMs: 9_000, lastOutputMs: 9_000 })) + .toEqual({ kind: "unavailable", reason: "invalid_duration" }); +}); + +test("the window persists to usage.jsonl as a pair, and an inverted pair is dropped", async () => { + const home = mkdtempSync(join(tmpdir(), "ocx-gen-window-")); + const previousHome = process.env.OPENCODEX_HOME; + process.env.OPENCODEX_HOME = home; + clearRequestLogsForTests(); + resetUsageReadCacheForTests(); + try { + const context = ctx(); + const start = Date.now() - 5_000; + recordGenerationEvent(context, "response.output_item.added", start + 1_000); + recordGenerationEvent(context, "response.output_text.delta", start + 4_000); + addFinalRequestLog("gen-window", start, context, 200); + const [row] = readFileSync(usageLogPath(home), "utf8").trimEnd().split("\n").map(line => JSON.parse(line)); + expect(row).toMatchObject({ requestId: "gen-window", genStartMs: 1_000, lastOutputMs: 4_000 }); + + const base = { requestId: "r", timestamp: 1, provider: "openai", model: "m", status: 200, durationMs: 10, usageStatus: "unreported" as const }; + expect(normalizeUsageEntryForTest({ ...base, genStartMs: 5, lastOutputMs: 2 })).not.toHaveProperty("genStartMs"); + expect(normalizeUsageEntryForTest({ ...base, genStartMs: 5 })).not.toHaveProperty("genStartMs"); + expect(normalizeUsageEntryForTest({ ...base, genStartMs: 2, lastOutputMs: 5 })) + .toMatchObject({ genStartMs: 2, lastOutputMs: 5 }); + } finally { + if (previousHome === undefined) delete process.env.OPENCODEX_HOME; + else process.env.OPENCODEX_HOME = previousHome; + clearRequestLogsForTests(); + resetUsageReadCacheForTests(); + await removeTreeWithRetry(home); + } +}); + +test("both live SSE taps feed the recorder", async () => { + const responses = ctx(); + inspectResponseLogSsePayload(responses, JSON.stringify({ type: "response.output_item.added" })); + inspectResponseLogSsePayload(responses, JSON.stringify({ type: "response.output_text.delta", delta: "hi" })); + expect(responses.generationStartedAt).toBeNumber(); + expect(responses.lastOutputAt).toBeNumber(); + + const anthropic = ctx(); + const frames = [ + { type: "message_start", message: { usage: { input_tokens: 1, output_tokens: 0 } } }, + { type: "content_block_start", index: 0, content_block: { type: "text", text: "" } }, + { type: "content_block_delta", index: 0, delta: { type: "text_delta", text: "hi" } }, + { type: "message_stop" }, + ].map(frame => `event: ${frame.type}\ndata: ${JSON.stringify(frame)}\n\n`).join(""); + const upstream = new Response(frames).body!; + await new Response(tapAnthropicSseForLog(upstream, anthropic, () => {})).text(); + expect(anthropic.generationStartedAt).toBeNumber(); + expect(anthropic.lastOutputAt).toBeNumber(); +});