fix(dashboard): TPS over generation time (duration − TTFT) + reasoning-aware numerator (#13130) - #13373
Conversation
…tokens (diegosouzapw#13130) Dashboard/history/playground tokens-per-second were wall-clock rates (tokens_out / full request duration), which collapses for thinking models (kimi k2.6/k2.7/k3) whose long queue+prefill+first-token window dwarfs the generation window. Root causes and fix: - Denominator: TPS now divides by generation time (duration - TTFT), the rule already documented in open-sse/utils/generationThroughput.ts and used by the X-OmniRoute-Tokens-Per-Second header; falls back to full duration when TTFT is unknown. - Numerator: max(tokens_out, tokens_reasoning) so providers that exclude reasoning from completion_tokens (while reporting it in completion_tokens_details) no longer undercount; providers that fold reasoning in (verified live on nvidia/moonshotai/kimi-k3) are unchanged. - Persist TTFT per request: new call_logs.ttft_ms column (migration 176 + ensureCallLogsColumns reconciliation), threaded from streamTiming through persistAttemptLogs; exposed as log.ttft in the call-logs API. - UI: /dashboard/logs gains an opt-in TTFT column, the TPS cell tooltip breaks down TTFT/generation/reasoning, and the request detail shows a TTFT tile. Playground (Chat/Compare) TPS uses the same generation-time formula. Verified live against nvidia/moonshotai/kimi-k3 (max_tokens cap reached with mostly reasoning output proves completion_tokens already includes thinking for this provider; DB and stream totals match exactly). Refs diegosouzapw#13130
#13248) Merged after renumbering. `176_provider_connection_synced_models_at.sql` collided with `176_xp_action_counts.sql` (#12651), which made the migration runner abort on every DB open. Renamed to **177**; the doc count moves 173 → 174 across README.md, AGENTS.md, llm.txt and the i18n mirrors (operator-approved, 206 numeric substitutions and nothing else). - `check:migration-numbering`: OK, 174 migrations, no duplicates - `check:docs-counts` migrations: ✓ - 84/84 across the NVIDIA suite plus the seven DB-touching suites the collision had taken down - ESLint and `typecheck:core`: exit 0 Heads-up for whoever lands next: **177 is claimed by eight other open PRs** (#13610, #13602, #13580, #13554, #13405, #13331, #13177, #13116) and 176 by #13373 and #13102. With this merged, all of them need to renumber at merge time — `check:migration-numbering` forbids new gaps, so the next free number is always the only valid one.⚠️ base-red inherited: #12732
|
This is the more complete fix for the TPS problem — it doesn't just add the TTFT column |
176_call_logs_ttft_ms.sql collided with 176_xp_action_counts.sql (and the tip has since moved past 178/179) — renumbered to 180, the next free slot, and updated the internal comment plus the one code/test reference to the old number. Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com>
…ken) Renamed 180_api_key_preferred_connections.sql to 184_api_key_preferred_connections.sql: the release tip landed 180_memory_fts_au_conditional_memory_id.sql after this PR's previous renumbering pass. Slot 184 is the owner-assigned number for this PR among the 7 PRs that collided on the 180 slot (diegosouzapw#13610=181, diegosouzapw#12962=182, diegosouzapw#12967=183, diegosouzapw#13102=184, diegosouzapw#13222=185, diegosouzapw#13373=186, diegosouzapw#13554=187). Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com>
Six open PRs claimed migration slot 180 after diegosouzapw#13331 landed it on the release tip; the owner assigned diegosouzapw#13373 slot 186 in the sequence (diegosouzapw#13610=181, diegosouzapw#12962=182, diegosouzapw#12967=183, diegosouzapw#13102=184, diegosouzapw#13222=185, diegosouzapw#13373=186, diegosouzapw#13554=187). Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com>
|
Maintainer note for the merge: this will be squash-merged with |
Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com>
|
Migration number coordination: several open PRs claim the same slot, and the release tip is already at |
…ouzapw#12849) (diegosouzapw#13248) Merged after renumbering. `176_provider_connection_synced_models_at.sql` collided with `176_xp_action_counts.sql` (diegosouzapw#12651), which made the migration runner abort on every DB open. Renamed to **177**; the doc count moves 173 → 174 across README.md, AGENTS.md, llm.txt and the i18n mirrors (operator-approved, 206 numeric substitutions and nothing else). - `check:migration-numbering`: OK, 174 migrations, no duplicates - `check:docs-counts` migrations: ✓ - 84/84 across the NVIDIA suite plus the seven DB-touching suites the collision had taken down - ESLint and `typecheck:core`: exit 0 Heads-up for whoever lands next: **177 is claimed by eight other open PRs** (diegosouzapw#13610, diegosouzapw#13602, diegosouzapw#13580, diegosouzapw#13554, diegosouzapw#13405, diegosouzapw#13331, diegosouzapw#13177, diegosouzapw#13116) and 176 by diegosouzapw#13373 and diegosouzapw#13102. With this merged, all of them need to renumber at merge time — `check:migration-numbering` forbids new gaps, so the next free number is always the only valid one.⚠️ base-red inherited: diegosouzapw#12732
…mber TTFT migration to 195 Resolve additive conflicts in chatCore.ts / attemptLogging.ts (keep the tip's reasoningMeta plumbing plus the PR's ttft threading). Renumber 187_call_logs_ttft_ms.sql -> 195 (187-194 are taken on the tip) and update schemaColumns.ts / db-schema-columns-split.test.ts references.
…reeze RequestLogger growth Move the generation-time TPS tooltip into src/shared/utils/logTps.ts (buildLogTpsTitle, unit-tested) to shrink the RequestLoggerV2 call site, and record the remaining irreducible growth (TTFT column + detail tile) in file-size-baseline.json; the train-8 headroom for diegosouzapw#13373 was consumed after it was ejected.
# Conflicts: # config/quality/file-size-baseline.json
# Conflicts: # config/quality/file-size-baseline.json
) Boarded in the 2026-09-28 release-drain batch and re-validated on the current tip after #13373 took migration 195: migration 196 is now the next free slot (check-migration-numbering OK), token-limits-per-window 7/7 plus combo token-limit tests green, typecheck:core and eslint clean. Thank you @fouadSalkini!
…#13965) (#13969) Claude-format thinking blocks now count as observed reasoning (source + character count, never tokens) so the log detail can tell reasoned-but-unmetered apart from did-not-reason. Maintainer rework: merged the release tip twice (i18n locale and callLogs conflicts resolved keeping both sides, new key mirrored in bs.json, RequestLoggerDetail ceiling re-measured to 1241 after #13373). Validated on the tip: reasoning-thinking-blocks-13965 7/7, reasoning-token-source-6187 6/6, call-logs-requested-model 5/5, log-tps-13130 6/6, UI vitest 5/5, typecheck:core clean, the new key present in all 66 locales. Thank you @Iammilansoni!
#15115) Release-captain base-red fix (v3.8.51 release PR #11442, Vitest): 23 UI test reds were contract changes of this cycle (next-intl useLocale mocks for #14466/#14807, TPS over generation time #13373, compression preview enginesExplicit #14529/#14700); tests realigned with comments, 36/36 twice.
Summary
Fixes the TPS (tokens-per-second) metric confirmed in #13130: dashboards and usage history computed a wall-clock rate (
tokens_out / full request duration), which collapses for thinking/interleaved models (kimi k2.6/k2.7/k3) whose queue + prefill + first-token window dwarfs the generation window.Verification done on a live instance (nvidia/moonshotai/kimi-k3, interleaved thinking + tool calls)
max_tokens: 3000→finish_reason: lengthwhile visible content was only ~370 tokens (+6.3k chars ofreasoning_content). The cap can only be reached ifcompletion_tokensincludes thinking tokens, and OmniRoute's recordedtokens_outmatched the stream exactly (recorded TPS = 14.4 tok/s = true all-output throughput). So the numerator was already correct for shapes that fold reasoning intocompletion_tokens.RequestLoggerV2+getModelLatencyStatsdivided by full wall-clock duration, contradicting the repo's own rule inopen-sse/utils/generationThroughput.ts("tok/s MUST exclude TTFT"; the response-header path already follows it).tokens_reasoninginto the rate — a provider that excludes reasoning fromcompletion_tokenswhile reportingcompletion_tokens_details.reasoning_tokens(the reporter's kimi OAuth endpoints are suspected) would still undercount.Changes
src/shared/utils/logTps.ts(new):resolveGenerationMs()(duration − TTFT, full-duration fallback) andresolveTpsOutputTokens()(max(tokens_out, tokens_reasoning)— never double counts, since reasoning is a subset when the provider folds it in).call_logs.ttft_ms(migration176_call_logs_ttft_ms.sql+ensureCallLogsColumnsreconciliation): TTFT fromstreamTimingis threaded throughpersistAttemptLogsfor streaming completions; NULL for non-streaming/legacy rows.ttft; dashboard grid adds an opt-in TTFT column (therequestLogger.columns.ttfti18n key already existed in all 51 locales), the TPS cell tooltip breaks down TTFT / generation window / reasoning tokens, and the request-detail modal shows a TTFT tile with the generation window.getModelLatencyStats: per-row TPS sample now uses generation time + the reasoning-aware numerator (feeds auto-combo speed ranking).Tests
tests/unit/log-tps-13130.test.ts— generation-window math, reasoning-aware numerator (incl. the no-double-count and provider-excludes-reasoning cases),accumulateLatencySamplebehavior, andttft_mspersistence round-trip.latency-stats-ttft-6875.test.tsandplayground-stream-metrics.test.ts(they pinned the old wall-clock formula),db-schema-columns-split.test.tscovers the reconciler.node --import tsx/esm --teston all touched suites: green;eslint(with suppressions): clean;npm run typecheck:core: clean.Refs #13130
release/v3.8.51tip was red when this PR was opened; any suite failures that also fail on base are inherited, not from this change.