diff --git a/desktop/src/api/sessions.ts b/desktop/src/api/sessions.ts index ba3a3e65..e2f17713 100644 --- a/desktop/src/api/sessions.ts +++ b/desktop/src/api/sessions.ts @@ -167,6 +167,14 @@ export type SessionUsageSnapshot = { costDisplay: string hasUnknownModelCost: boolean totalAPIDuration: number + /** + * Milliseconds the model spent emitting tokens, excluding prefill and tool execution. + * Absent or 0 means unknown (transcript source, aborted turn, non-streaming fallback) — + * never "instant", so a tokens/sec reading must be withheld rather than computed. + */ + totalDecodeDuration?: number + /** Milliseconds spent waiting for the first token, summed over the session's requests. */ + totalTtftDuration?: number totalDuration: number totalLinesAdded: number totalLinesRemoved: number @@ -479,6 +487,17 @@ export const sessionsApi = { }) }, + /** + * Running session totals only — one CLI control, no skills scan, no transcript re-read. + * Cheap enough to poll while the context panel is open. + */ + getSessionUsage(sessionId: string, signal?: AbortSignal) { + return api.get( + `/api/sessions/${sessionId}/inspection?includeContext=0&usageOnly=1`, + { timeout: 6_000, signal }, + ) + }, + getWorkspaceStatus(sessionId: string, signal?: AbortSignal) { return api.get(buildWorkspacePath(sessionId, 'status'), { signal }) }, diff --git a/desktop/src/components/chat/ContextUsageDetails.tsx b/desktop/src/components/chat/ContextUsageDetails.tsx index 71b644b9..dfb2f14f 100644 --- a/desktop/src/components/chat/ContextUsageDetails.tsx +++ b/desktop/src/components/chat/ContextUsageDetails.tsx @@ -1,8 +1,27 @@ +import { formatDurationMs } from '../../lib/trace/formatters' +import { + formatCacheHitRate, + formatCompactTokens, + formatTokensPerSecond, +} from '../../lib/sessionUsageMetrics' + type ContextCategory = { name: string tokens: number } +/** + * Lifetime figures for the whole session, as opposed to `categories` which describe only what + * currently occupies the context window. Kept as raw numbers so the formatting rules (never + * rounding a cache hit up to 100%, withholding a speed with no decode span) stay in one place. + */ +export type ContextUsageSessionStats = { + totalTokens: number + cacheHitRate: number | null + tokensPerSecond: number | null + apiDurationMs: number +} + export type ContextUsageDetailsStatus = 'ready' | 'pending' | 'loading' | 'unavailable' export type ContextUsageDetailsProps = { @@ -13,6 +32,7 @@ export type ContextUsageDetailsProps = { freeTokens: number maxTokens: number categories: ContextCategory[] + sessionStats?: ContextUsageSessionStats | null updatedAtLabel?: string estimate?: boolean status: ContextUsageDetailsStatus @@ -25,6 +45,13 @@ export type ContextUsageDetailsProps = { pendingDetail: string loading: string unavailableDetail: string + sessionUsage: string + sessionTotalTokens: string + sessionCacheHit: string + sessionSpeed: string + sessionApiDuration: string + sessionSpeedUnit: string + sessionScopeNote: string } } @@ -32,6 +59,71 @@ function formatNumber(value: number) { return new Intl.NumberFormat().format(value) } +/** + * Lifetime session totals. Rendered below the window breakdown because the two answer different + * questions: the bars say what is in the context right now, this says what the session has spent. + */ +function SessionUsage({ + stats, + labels, + density, +}: { + stats: ContextUsageSessionStats + labels: ContextUsageDetailsProps['labels'] + density: 'compact' | 'comfortable' +}) { + const labelClass = density === 'compact' + ? 'text-[12.5px] text-[var(--color-text-tertiary)]' + : 'text-xs text-[var(--color-text-tertiary)]' + const valueClass = 'font-mono text-sm text-[var(--color-text-primary)]' + + return ( +
+
{labels.sessionUsage}
+ +
+ {labels.sessionTotalTokens} + + {formatCompactTokens(stats.totalTokens)} + +
+ +
+
+
{labels.sessionCacheHit}
+
+ {stats.cacheHitRate === null ? '--' : formatCacheHitRate(stats.cacheHitRate)} +
+
+
+
{labels.sessionSpeed}
+
+ {formatTokensPerSecond(stats.tokensPerSecond ?? 0)} + {stats.tokensPerSecond !== null && ( + {labels.sessionSpeedUnit} + )} +
+
+
+ +
+ {labels.sessionApiDuration} + + {formatDurationMs(stats.apiDurationMs)} + +
+ + {/* Subagent transcripts are separate files and are never folded in here; saying so beats + letting the number quietly disagree with the user's bill. */} +
{labels.sessionScopeNote}
+
+ ) +} + function CategoryBars({ categories, maxTokens, @@ -81,6 +173,7 @@ export function ContextUsageDetails({ freeTokens, maxTokens, categories, + sessionStats, updatedAtLabel, estimate = false, status, @@ -120,11 +213,16 @@ export function ContextUsageDetails({ + {/* Above the session block on purpose: this timestamp describes the window + breakdown, which refreshes on a much slower cadence than the live totals. */} {updatedAtLabel && (
{updatedAtLabel}
)} + {sessionStats && ( + + )} ) : (
@@ -177,6 +275,8 @@ export function ContextUsageDetails({
+ {/* Above the session block on purpose: this timestamp describes the window + breakdown, which refreshes on a much slower cadence than the live totals. */} {updatedAtLabel && (
{updatedAtLabel} @@ -187,6 +287,9 @@ export function ContextUsageDetails({ )}
)} + {sessionStats && ( + + )} ) : status === 'pending' ? (
diff --git a/desktop/src/components/chat/ContextUsageIndicator.test.tsx b/desktop/src/components/chat/ContextUsageIndicator.test.tsx index 0ec6defb..5f07b0c9 100644 --- a/desktop/src/components/chat/ContextUsageIndicator.test.tsx +++ b/desktop/src/components/chat/ContextUsageIndicator.test.tsx @@ -5,6 +5,10 @@ import '@testing-library/jest-dom' const { sessionsApiMock, runtimeMocks } = vi.hoisted(() => ({ sessionsApiMock: { getInspection: vi.fn(), + // Defaulted rather than bare: every test that opens the breakdown now starts the usage + // poll, including the ones written before it existed that only care about the context + // meter. `clearAllMocks` clears calls, not implementations, so this survives beforeEach. + getSessionUsage: vi.fn(async () => ({ active: true, status: {} })), }, runtimeMocks: { isMobileViewport: false, @@ -28,6 +32,7 @@ vi.mock('../../api/sessions', async (importOriginal) => { sessionsApi: { ...actual.sessionsApi, getInspection: sessionsApiMock.getInspection, + getSessionUsage: sessionsApiMock.getSessionUsage, }, } }) @@ -751,3 +756,201 @@ describe('ContextUsageIndicator presentation', () => { expect(screen.queryByTestId('context-usage-popover')).not.toBeInTheDocument() }) }) + +describe('ContextUsageIndicator session usage', () => { + const usageInspection = (usage: Record) => ({ + active: true, + status: baseInspection.status, + context: baseInspection.context, + usage, + }) + + const baseUsage = { + source: 'current_process' as const, + totalCostUSD: 1.23, + costDisplay: '$1.23', + hasUnknownModelCost: false, + totalAPIDuration: 42_000, + totalDecodeDuration: 12_000, + totalTtftDuration: 3_000, + totalDuration: 300, + totalLinesAdded: 0, + totalLinesRemoved: 0, + totalInputTokens: 1_000, + totalOutputTokens: 2_400, + totalCacheReadInputTokens: 9_000, + totalCacheCreationInputTokens: 0, + totalWebSearchRequests: 0, + models: [], + } + + beforeEach(() => { + vi.clearAllMocks() + runtimeMocks.isMobileViewport = false + runtimeMocks.isDesktopRuntime = false + useSettingsStore.setState({ locale: 'en' }) + sessionsApiMock.getInspection.mockResolvedValue(baseInspection) + sessionsApiMock.getSessionUsage.mockResolvedValue(usageInspection(baseUsage)) + }) + + afterEach(() => { + cleanup() + }) + + it('does not poll session usage while the breakdown is closed', async () => { + render( + , + ) + + await waitFor(() => { + expect(screen.getByTestId('context-usage-indicator')).toHaveTextContent('21%') + }) + + // The poll is a per-open cost. Fetching for a panel nobody opened would put a CLI control + // round-trip on every session for no visible benefit. + expect(sessionsApiMock.getSessionUsage).not.toHaveBeenCalled() + }) + + it('renders lifetime totals once the breakdown opens', async () => { + render( + , + ) + await waitFor(() => { + expect(screen.getByTestId('context-usage-indicator')).toHaveTextContent('21%') + }) + + fireEvent.click(screen.getByTestId('context-usage-indicator')) + + // 1000 input + 9000 cache read + 2400 output; the cached tokens are counted once. + expect(await screen.findByTestId('session-total-tokens')).toHaveTextContent('12.4K') + expect(screen.getByTestId('session-cache-hit')).toHaveTextContent('90.0%') + expect(screen.getByTestId('session-speed')).toHaveTextContent('200') + expect(screen.getByTestId('session-speed')).toHaveTextContent('tok/s') + expect(sessionsApiMock.getSessionUsage).toHaveBeenCalledWith('session-1', expect.anything()) + }) + + it('never reports a partial cache as a perfect one', async () => { + sessionsApiMock.getSessionUsage.mockResolvedValue(usageInspection({ + ...baseUsage, + totalInputTokens: 4, + totalCacheReadInputTokens: 9_996, + })) + + render( + , + ) + await waitFor(() => { + expect(screen.getByTestId('context-usage-indicator')).toHaveTextContent('21%') + }) + fireEvent.click(screen.getByTestId('context-usage-indicator')) + + expect(await screen.findByTestId('session-cache-hit')).toHaveTextContent('99.96%') + expect(screen.getByTestId('session-cache-hit')).not.toHaveTextContent('100%') + }) + + it('withholds the speed reading when the session reported no decode span', async () => { + // Transcript-sourced usage has no generation timing. Showing a number here would mean + // dividing by wall clock, which includes tool execution. + sessionsApiMock.getSessionUsage.mockResolvedValue(usageInspection({ + ...baseUsage, + totalDecodeDuration: 0, + })) + + render( + , + ) + await waitFor(() => { + expect(screen.getByTestId('context-usage-indicator')).toHaveTextContent('21%') + }) + fireEvent.click(screen.getByTestId('context-usage-indicator')) + + expect(await screen.findByTestId('session-speed')).toHaveTextContent('--') + expect(screen.getByTestId('session-speed')).not.toHaveTextContent('tok/s') + }) + + it('hides the block entirely for a session that has spent nothing', async () => { + sessionsApiMock.getSessionUsage.mockResolvedValue(usageInspection({ + ...baseUsage, + totalInputTokens: 0, + totalOutputTokens: 0, + totalCacheReadInputTokens: 0, + totalDecodeDuration: 0, + })) + + render( + , + ) + await waitFor(() => { + expect(screen.getByTestId('context-usage-indicator')).toHaveTextContent('21%') + }) + fireEvent.click(screen.getByTestId('context-usage-indicator')) + + await screen.findByTestId('context-usage-popover') + // An all-zero row would read as a measurement rather than an absence. + expect(screen.queryByTestId('session-total-tokens')).not.toBeInTheDocument() + }) + + it('does not stack polls behind a request that has not answered yet', async () => { + vi.useFakeTimers() + try { + // A stuck CLI control: the request never settles, so every tick would pile another + // round-trip on top of it if the timer were the only gate. + sessionsApiMock.getSessionUsage.mockImplementation(() => new Promise(() => {})) + + render( + , + ) + await act(async () => { + await vi.advanceTimersByTimeAsync(0) + }) + fireEvent.click(screen.getByTestId('context-usage-indicator')) + await act(async () => { + await vi.advanceTimersByTimeAsync(0) + }) + + // Three poll intervals, including the one that fires while the first request is open. + await act(async () => { + await vi.advanceTimersByTimeAsync(9_000) + }) + + expect(sessionsApiMock.getSessionUsage).toHaveBeenCalledTimes(1) + } finally { + vi.useRealTimers() + } + }) + + it('polls while open and stops when the panel closes', async () => { + vi.useFakeTimers() + try { + render( + , + ) + await act(async () => { + await vi.advanceTimersByTimeAsync(0) + }) + + fireEvent.click(screen.getByTestId('context-usage-indicator')) + await act(async () => { + await vi.advanceTimersByTimeAsync(0) + }) + expect(sessionsApiMock.getSessionUsage).toHaveBeenCalledTimes(1) + + await act(async () => { + await vi.advanceTimersByTimeAsync(6_000) + }) + expect(sessionsApiMock.getSessionUsage.mock.calls.length).toBeGreaterThanOrEqual(3) + + const callsWhileOpen = sessionsApiMock.getSessionUsage.mock.calls.length + fireEvent.click(screen.getByTestId('context-usage-indicator')) + await act(async () => { + await vi.advanceTimersByTimeAsync(9_000) + }) + + // Nothing keeps ticking after the popover is dismissed — the timer is owned by the + // open state, not by the component's lifetime. + expect(sessionsApiMock.getSessionUsage.mock.calls.length).toBe(callsWhileOpen) + } finally { + vi.useRealTimers() + } + }) +}) diff --git a/desktop/src/components/chat/ContextUsageIndicator.tsx b/desktop/src/components/chat/ContextUsageIndicator.tsx index 6a32fe63..29b4a1e6 100644 --- a/desktop/src/components/chat/ContextUsageIndicator.tsx +++ b/desktop/src/components/chat/ContextUsageIndicator.tsx @@ -1,13 +1,22 @@ import { useCallback, useEffect, useLayoutEffect, useMemo, useRef, useState } from 'react' import { createPortal } from 'react-dom' -import { sessionsApi, type SessionContextSnapshot } from '../../api/sessions' +import { + sessionsApi, + type SessionContextSnapshot, + type SessionUsageSnapshot, +} from '../../api/sessions' import { useTranslation } from '../../i18n' import type { ChatState } from '../../types/chat' import { useMobileViewport } from '../../hooks/useMobileViewport' import { useDismissable } from '../../hooks/useDismissable' import { isDesktopRuntime } from '../../lib/desktopRuntime' +import { deriveSessionUsageMetrics } from '../../lib/sessionUsageMetrics' import { MobileBottomSheet } from '@/components/ui/MobileBottomSheet' -import { ContextUsageDetails, type ContextUsageDetailsStatus } from './ContextUsageDetails' +import { + ContextUsageDetails, + type ContextUsageDetailsStatus, + type ContextUsageSessionStats, +} from './ContextUsageDetails' type Props = { sessionId?: string @@ -31,6 +40,11 @@ const ACTIVE_REFRESH_MS = 30_000 // racing a client abort that can strand loopback sockets on Windows. const CONTEXT_REQUEST_TIMEOUT_MS = 30_000 const AUTO_REFRESH_MIN_INTERVAL_MS = 10_000 +// Lifetime totals only change when a turn completes, but a turn can run for minutes and the +// user is staring at the panel while it does. Polling is scoped to the open popover/sheet — +// a closed panel costs nothing — and the request it makes is the single-control `usageOnly` +// path, not the full inspection. +const USAGE_POLL_MS = 3_000 // Right after a completed turn, compaction, or runtime restart the CLI can // still be settling, so retry the event-driven refresh once. const FORCED_REFRESH_RETRY_MS = 5_000 @@ -115,6 +129,8 @@ export function ContextUsageIndicator({ const [error, setError] = useState(null) const [updatedAt, setUpdatedAt] = useState(null) const [inspectionModel, setInspectionModel] = useState(null) + const [usage, setUsage] = useState(null) + const usageSessionIdRef = useRef(undefined) const [detailsOpen, setDetailsOpen] = useState(false) const [popoverPosition, setPopoverPosition] = useState(null) const triggerRef = useRef(null) @@ -308,6 +324,48 @@ export function ContextUsageIndicator({ return () => clearInterval(timer) }, [chatState, messageCount, refresh]) + // Lifetime session totals, polled only while the breakdown is on screen. The request is the + // single-control `usageOnly` one, so a 3s cadence costs far less than the context refresh it + // sits next to, and closing the panel takes the timer with it — nothing runs in the + // background, and a hidden document skips its ticks rather than queueing them. + useEffect(() => { + if (!detailsOpen || !sessionId) return + if (typeof sessionsApi.getSessionUsage !== 'function') return + let cancelled = false + // The poll interval is shorter than the request deadline, so a slow server would otherwise + // let ticks stack up behind the in-flight one. Skipping a tick loses nothing: the answer + // that is still outstanding is the same answer the new tick would have asked for. + let inFlight = false + const controller = new AbortController() + + const load = () => { + if (inFlight || !isDocumentVisible()) return + inFlight = true + void sessionsApi.getSessionUsage(sessionId, controller.signal) + .then((inspection) => { + if (cancelled || !inspection.usage) return + usageSessionIdRef.current = sessionId + setUsage(inspection.usage) + }) + .catch(() => { + // A failed poll (CLI busy, control timeout) leaves the last good numbers on screen. + // The panel is a readout, not a task; a flickering error would be worse than a + // value that is three seconds stale. + }) + .finally(() => { + inFlight = false + }) + } + + load() + const timer = setInterval(load, USAGE_POLL_MS) + return () => { + cancelled = true + controller.abort() + clearInterval(timer) + } + }, [detailsOpen, sessionId]) + // If the presentation mode flips (Workbench drag, H5 resize), drop any open // shell so we don't leave a desktop popover stranded on a sheet layout. useEffect(() => { @@ -369,8 +427,32 @@ export function ContextUsageIndicator({ pendingDetail: t('contextIndicator.pendingDetail'), loading: t('contextIndicator.loading'), unavailableDetail: t('contextIndicator.unavailableDetail'), + sessionUsage: t('contextIndicator.sessionUsage'), + sessionTotalTokens: t('contextIndicator.sessionTotalTokens'), + sessionCacheHit: t('contextIndicator.sessionCacheHit'), + sessionSpeed: t('contextIndicator.sessionSpeed'), + sessionApiDuration: t('contextIndicator.sessionApiDuration'), + sessionSpeedUnit: t('contextIndicator.sessionSpeedUnit'), + sessionScopeNote: t('contextIndicator.sessionScopeNote'), }), [t]) + // Derived per render rather than memoized on `usage` alone: the session it belongs to lives in + // a ref, so the guard has to run against the current sessionId every time. + const displayUsage = usageSessionIdRef.current === sessionId ? usage : null + const sessionStats = useMemo(() => { + if (!displayUsage) return null + const metrics = deriveSessionUsageMetrics(displayUsage) + // A session with nothing spent yet has no honest answer for any of these rows; showing an + // empty block (or a 0 tok/s) would read as a measurement rather than an absence. + if (metrics.totalTokens === 0) return null + return { + totalTokens: metrics.totalTokens, + cacheHitRate: metrics.cacheHitRate, + tokensPerSecond: metrics.tokensPerSecond, + apiDurationMs: displayUsage.totalAPIDuration, + } + }, [displayUsage]) + const detailsBody = ( = { 'contextIndicator.updatedNow': 'たった今更新', 'contextIndicator.updatedMinutes': '{count} 分前に更新', 'contextIndicator.estimate': '推定', + 'contextIndicator.sessionUsage': 'このセッション', + 'contextIndicator.sessionTotalTokens': '合計トークン', + 'contextIndicator.sessionCacheHit': 'キャッシュヒット', + 'contextIndicator.sessionSpeed': '生成速度', + 'contextIndicator.sessionApiDuration': 'API 時間', + 'contextIndicator.sessionSpeedUnit': 'tok/s', + 'contextIndicator.sessionScopeNote': 'サブエージェントを除く', 'chat.navigate': '移動', 'chat.select': '選択', 'chat.dismiss': '閉じる', diff --git a/desktop/src/i18n/locales/kr.ts b/desktop/src/i18n/locales/kr.ts index 0f3ca623..20f20ab4 100644 --- a/desktop/src/i18n/locales/kr.ts +++ b/desktop/src/i18n/locales/kr.ts @@ -2586,6 +2586,13 @@ export const kr: Record = { 'contextIndicator.updatedNow': '방금 업데이트됨', 'contextIndicator.updatedMinutes': '{count}분 전 업데이트됨', 'contextIndicator.estimate': '추정', + 'contextIndicator.sessionUsage': '이 세션', + 'contextIndicator.sessionTotalTokens': '총 토큰', + 'contextIndicator.sessionCacheHit': '캐시 적중', + 'contextIndicator.sessionSpeed': '생성 속도', + 'contextIndicator.sessionApiDuration': 'API 시간', + 'contextIndicator.sessionSpeedUnit': 'tok/s', + 'contextIndicator.sessionScopeNote': '하위 에이전트 제외', 'chat.navigate': '이동', 'chat.select': '선택', 'chat.dismiss': '닫기', diff --git a/desktop/src/i18n/locales/zh-TW.ts b/desktop/src/i18n/locales/zh-TW.ts index 4e05f3ae..541f4320 100644 --- a/desktop/src/i18n/locales/zh-TW.ts +++ b/desktop/src/i18n/locales/zh-TW.ts @@ -2585,6 +2585,13 @@ export const zh: Record = { 'contextIndicator.updatedNow': '剛剛更新', 'contextIndicator.updatedMinutes': '{count} 分鐘前更新', 'contextIndicator.estimate': '估算', + 'contextIndicator.sessionUsage': '此次工作階段', + 'contextIndicator.sessionTotalTokens': '總 token', + 'contextIndicator.sessionCacheHit': '快取命中', + 'contextIndicator.sessionSpeed': '生成速度', + 'contextIndicator.sessionApiDuration': 'API 耗時', + 'contextIndicator.sessionSpeedUnit': 'tok/s', + 'contextIndicator.sessionScopeNote': '不含子代理用量', 'chat.navigate': '導航', 'chat.select': '選擇', 'chat.dismiss': '關閉', diff --git a/desktop/src/i18n/locales/zh.ts b/desktop/src/i18n/locales/zh.ts index 9c1a92ea..c7757a18 100644 --- a/desktop/src/i18n/locales/zh.ts +++ b/desktop/src/i18n/locales/zh.ts @@ -2584,6 +2584,13 @@ export const zh: Record = { 'contextIndicator.updatedNow': '刚刚更新', 'contextIndicator.updatedMinutes': '{count} 分钟前更新', 'contextIndicator.estimate': '估算', + 'contextIndicator.sessionUsage': '此次会话', + 'contextIndicator.sessionTotalTokens': '总 token', + 'contextIndicator.sessionCacheHit': '缓存命中', + 'contextIndicator.sessionSpeed': '生成速度', + 'contextIndicator.sessionApiDuration': 'API 耗时', + 'contextIndicator.sessionSpeedUnit': 'tok/s', + 'contextIndicator.sessionScopeNote': '不含子代理用量', 'chat.navigate': '导航', 'chat.select': '选择', 'chat.dismiss': '关闭', diff --git a/desktop/src/lib/sessionUsageMetrics.test.ts b/desktop/src/lib/sessionUsageMetrics.test.ts new file mode 100644 index 00000000..40315841 --- /dev/null +++ b/desktop/src/lib/sessionUsageMetrics.test.ts @@ -0,0 +1,137 @@ +import { describe, expect, it } from 'vitest' +import { + deriveSessionUsageMetrics, + formatCacheHitRate, + formatCompactTokens, + formatTokensPerSecond, +} from './sessionUsageMetrics' + +function usage(overrides: Partial[0]> = {}) { + return { + totalInputTokens: 0, + totalOutputTokens: 0, + totalCacheReadInputTokens: 0, + totalCacheCreationInputTokens: 0, + ...overrides, + } +} + +describe('deriveSessionUsageMetrics', () => { + it('counts each of the four buckets exactly once', () => { + const metrics = deriveSessionUsageMetrics(usage({ + totalInputTokens: 1_000, + totalOutputTokens: 200, + totalCacheReadInputTokens: 8_000, + totalCacheCreationInputTokens: 500, + })) + + // The buckets are disjoint, so the total is a plain sum — if a provider ever reported + // cache reads inside input_tokens this would double-count them. + expect(metrics.totalTokens).toBe(9_700) + expect(metrics.promptTokens).toBe(9_500) + }) + + it('measures cache hits against the prompt side, never against output', () => { + const metrics = deriveSessionUsageMetrics(usage({ + totalInputTokens: 1_000, + totalOutputTokens: 9_000, + totalCacheReadInputTokens: 9_000, + })) + + // 9000 / (1000 + 9000) — a denominator that included output would report 82% here and + // let a chatty reply make the cache look worse than it is. + expect(metrics.cacheHitRate).toBeCloseTo(0.9, 10) + }) + + it('withholds a cache hit rate until prompt tokens exist', () => { + expect(deriveSessionUsageMetrics(usage({ totalOutputTokens: 500 })).cacheHitRate).toBeNull() + }) + + it('derives tokens per second from the decode span only', () => { + const metrics = deriveSessionUsageMetrics(usage({ + totalOutputTokens: 1_000, + totalDecodeDuration: 5_000, + })) + + expect(metrics.tokensPerSecond).toBe(200) + }) + + it('withholds tokens per second when no decode span was reported', () => { + // Transcript-sourced usage has no generation timing. Falling back to wall clock would + // divide by a span that includes tool execution and invent a rate. + const metrics = deriveSessionUsageMetrics(usage({ + totalOutputTokens: 1_000, + totalDecodeDuration: 0, + })) + + expect(metrics.tokensPerSecond).toBeNull() + }) + + it('treats missing and non-finite fields as zero rather than NaN', () => { + const metrics = deriveSessionUsageMetrics({ + totalInputTokens: Number.NaN, + totalOutputTokens: 100, + totalCacheReadInputTokens: undefined as unknown as number, + totalCacheCreationInputTokens: -5, + totalDecodeDuration: undefined, + }) + + expect(metrics.totalTokens).toBe(100) + expect(metrics.cacheHitRate).toBeNull() + expect(metrics.tokensPerSecond).toBeNull() + }) +}) + +describe('formatCacheHitRate', () => { + it.each([ + [0, '0%'], + [0.5, '50.0%'], + [0.982, '98.2%'], + [1, '100%'], + ])('renders %s as %s', (rate, expected) => { + expect(formatCacheHitRate(rate)).toBe(expected) + }) + + it('never rounds a partial hit up to a flat 100%', () => { + // 0.9996 * 100 = 99.96 -> toFixed(1) would print "100.0%", which claims a perfect cache. + expect(formatCacheHitRate(0.9996)).toBe('99.96%') + }) + + it('floors rates that round to 100.00 at two decimals', () => { + expect(formatCacheHitRate(0.999_999)).toBe('99.99%') + }) + + it('clamps nonsense to a displayable value', () => { + expect(formatCacheHitRate(Number.NaN)).toBe('0%') + expect(formatCacheHitRate(-1)).toBe('0%') + }) +}) + +describe('formatTokensPerSecond', () => { + it('keeps a decimal only where it carries information', () => { + expect(formatTokensPerSecond(9.44)).toBe('9.4') + expect(formatTokensPerSecond(42.6)).toBe('43') + expect(formatTokensPerSecond(1_234.9)).toBe('1235') + }) + + it('renders an unavailable rate as a placeholder, not zero', () => { + expect(formatTokensPerSecond(0)).toBe('--') + expect(formatTokensPerSecond(Number.NaN)).toBe('--') + }) +}) + +describe('formatCompactTokens', () => { + it.each([ + [812, '812'], + [9_500, '9.5K'], + [375_372, '375K'], + [8_100_000, '8.1M'], + ])('renders %s as %s', (value, expected) => { + expect(formatCompactTokens(value)).toBe(expected) + }) + + it('promotes a value that would round into a four-digit smaller unit', () => { + // 999_949/1000 rounds to "1000" at zero decimals; showing "1000K" reads as a bug. + expect(formatCompactTokens(999_949)).toBe('1.0M') + }) +}) diff --git a/desktop/src/lib/sessionUsageMetrics.ts b/desktop/src/lib/sessionUsageMetrics.ts new file mode 100644 index 00000000..54873a2e --- /dev/null +++ b/desktop/src/lib/sessionUsageMetrics.ts @@ -0,0 +1,97 @@ +/** + * Session-level token accounting for the context panel. + * + * The four buckets the CLI reports are disjoint: `input_tokens` never includes cached tokens, so + * summing them counts each token exactly once. (Providers whose wire format folds cache hits into + * the prompt total are adapted on the way in — see `src/server/proxy/transform/usage.ts`.) That + * invariant is the reason this file can add first and ask questions later; a source that ever + * reports inclusive input would silently inflate both the total and the cache hit rate. + */ + +export type SessionUsageLike = { + totalInputTokens: number + totalOutputTokens: number + totalCacheReadInputTokens: number + totalCacheCreationInputTokens: number + totalDecodeDuration?: number +} + +export type SessionUsageMetrics = { + /** Every token the session moved, counting a cached token once. */ + totalTokens: number + /** Prompt-side tokens only: the denominator a cache hit rate is meaningful against. */ + promptTokens: number + cachedTokens: number + /** `null` when the session has sent no prompt tokens yet. */ + cacheHitRate: number | null + /** `null` when no decode span was reported — see below. */ + tokensPerSecond: number | null +} + +function finite(value: number | undefined): number { + return typeof value === 'number' && Number.isFinite(value) && value > 0 ? value : 0 +} + +/** + * Derives the panel's headline numbers. + * + * `tokensPerSecond` divides output tokens by the time the model actually spent emitting them, so + * tool execution and prefill wait are excluded. A caller that only has a transcript (no decode + * spans) gets `null` rather than a rate computed against wall clock: dividing by a span that + * includes 40 seconds of `Bash` would report a speed the model never ran at. + */ +export function deriveSessionUsageMetrics(usage: SessionUsageLike): SessionUsageMetrics { + const input = finite(usage.totalInputTokens) + const output = finite(usage.totalOutputTokens) + const cacheRead = finite(usage.totalCacheReadInputTokens) + const cacheWrite = finite(usage.totalCacheCreationInputTokens) + const decodeMs = finite(usage.totalDecodeDuration) + + const promptTokens = input + cacheRead + cacheWrite + return { + totalTokens: promptTokens + output, + promptTokens, + cachedTokens: cacheRead, + cacheHitRate: promptTokens > 0 ? cacheRead / promptTokens : null, + tokensPerSecond: decodeMs > 0 && output > 0 ? output / (decodeMs / 1000) : null, + } +} + +/** + * Formats a cache hit rate without ever rounding a partial hit up to a flat 100%. + * + * A session at 99.96% is *not* fully cached, and printing "100%" would tell the user something + * false about both their bill and their prompt stability. Widening the precision is the honest + * fix; only a rate that is exactly 1 renders as 100%. + */ +export function formatCacheHitRate(rate: number): string { + if (!Number.isFinite(rate) || rate <= 0) return '0%' + if (rate >= 1) return '100%' + const percent = rate * 100 + const oneDecimal = percent.toFixed(1) + if (oneDecimal !== '100.0') return `${oneDecimal}%` + const twoDecimals = percent.toFixed(2) + // 99.995% and up still rounds to 100.00; floor it so the maximum shown below + // a true hit is visibly below a true hit. + return twoDecimals === '100.00' ? '99.99%' : `${twoDecimals}%` +} + +/** `100`, `42`, `9.4` — one decimal only while the number is small enough to need it. */ +export function formatTokensPerSecond(value: number): string { + if (!Number.isFinite(value) || value <= 0) return '--' + return value >= 10 ? `${Math.round(value)}` : `${value.toFixed(1)}` +} + +/** `1.2M`, `375K`, `812` — compact enough for a stat row, never a lie about magnitude. */ +export function formatCompactTokens(value: number): string { + if (!Number.isFinite(value) || value <= 0) return '0' + if (value < 1_000) return `${Math.round(value)}` + const thousands = value / 1_000 + const decimals = thousands >= 100 ? 0 : 1 + // Rounding can push a value just under the next unit up to a full thousand of the smaller one + // (999_949 reads as "1000K"); promote it so the row never shows four digits of a smaller unit. + if (Number(thousands.toFixed(decimals)) >= 1_000) { + return `${(value / 1_000_000).toFixed(1)}M` + } + return `${thousands.toFixed(decimals)}K` +} diff --git a/desktop/src/stores/chatStore.test.ts b/desktop/src/stores/chatStore.test.ts index 230696d0..1a70fe34 100644 --- a/desktop/src/stores/chatStore.test.ts +++ b/desktop/src/stores/chatStore.test.ts @@ -2871,6 +2871,46 @@ describe('chatStore history mapping', () => { ])) }) + it('counts a multi-block reply once when restoring token usage from history', async () => { + // Three lines sharing a `usageKey` are one reply's content blocks. Summing per line would + // report 3x; this is the same inflation the server-side transcript readers dedupe away. + const blockLine = (usageKey: string) => ({ + id: `line-${usageKey}`, + type: 'assistant' as const, + timestamp: '2026-08-31T00:00:00.000Z', + content: [{ type: 'text', text: 'block' }], + usage: { input_tokens: 100, output_tokens: 250, cache_read_input_tokens: 1_000 }, + usageKey, + }) + const distinctReply = { + id: 'line-second-reply', + type: 'assistant' as const, + timestamp: '2026-08-31T00:01:00.000Z', + content: [{ type: 'text', text: 'second' }], + usage: { input_tokens: 10, output_tokens: 70 }, + usageKey: 'msg_second\0req_second', + } + vi.mocked(sessionsApi.getMessages).mockResolvedValueOnce({ + messages: [ + blockLine('msg_first\0req_first'), + blockLine('msg_first\0req_first'), + blockLine('msg_first\0req_first'), + distinctReply, + ] as never, + }) + useChatStore.setState({ + sessions: { [TEST_SESSION_ID]: makeSession({ messages: [] }) }, + }) + + await useChatStore.getState().loadHistory(TEST_SESSION_ID) + + expect(useChatStore.getState().sessions[TEST_SESSION_ID]?.tokenUsage).toEqual({ + input_tokens: 110, + output_tokens: 320, + cache_read_tokens: 1_000, + }) + }) + it('does not replace newer live token usage with a stale cold snapshot', async () => { let resolveHistory!: (value: { messages: MessageEntry[] }) => void vi.mocked(sessionsApi.getMessages).mockReturnValueOnce(new Promise((resolve) => { diff --git a/desktop/src/stores/chatStore.ts b/desktop/src/stores/chatStore.ts index 98f5610e..e42d07c3 100644 --- a/desktop/src/stores/chatStore.ts +++ b/desktop/src/stores/chatStore.ts @@ -2072,10 +2072,19 @@ function summarizeTokenUsageFromHistory(messages: MessageEntry[]): TokenUsage | let outputTokens = 0 let cacheReadTokens = 0 let cacheCreationTokens = 0 + // A reply with thinking + text + a dozen tool_use blocks arrives as fourteen lines that each + // repeat the whole `usage` object. Summing per line is the 2.2x inflation the transcript + // readers carry; the server stamps `usageKey` so this only has to dedupe on it. Lines with + // no key are always counted, matching the transcript readers. + const countedUsageKeys = new Set() for (const message of messages) { const usage = message.usage if (!usage) continue + if (message.usageKey) { + if (countedUsageKeys.has(message.usageKey)) continue + countedUsageKeys.add(message.usageKey) + } inputTokens += readUsageToken(usage.input_tokens) outputTokens += readUsageToken(usage.output_tokens) cacheReadTokens += readUsageToken(usage.cache_read_input_tokens) diff --git a/desktop/src/types/chat.ts b/desktop/src/types/chat.ts index 9d2c7383..392267b0 100644 --- a/desktop/src/types/chat.ts +++ b/desktop/src/types/chat.ts @@ -126,7 +126,7 @@ export type ServerMessage = turnActive: boolean } | { type: 'user_message_replay'; content: string } - | { type: 'message_complete'; usage: TokenUsage } + | { type: 'message_complete'; usage: TokenUsage; timing?: TurnTiming } /** `complete` marks a whole thinking block; without it `text` is a stream fragment. */ | { type: 'thinking'; text: string; complete?: boolean } | { type: 'status'; state: ChatState; verb?: string; attemptStart?: boolean } @@ -179,6 +179,14 @@ export type TokenUsage = { cache_creation_tokens?: number } +/** Mirrors the server's `TurnTiming`: milliseconds, `decode_ms` excludes prefill and tools. */ +export type TurnTiming = { + duration_ms: number + duration_api_ms: number + ttft_ms: number + decode_ms: number +} + export type ChatState = 'idle' | 'thinking' | 'compacting' | 'tool_executing' | 'streaming' | 'permission_pending' export type ApiRetryState = { diff --git a/desktop/src/types/session.ts b/desktop/src/types/session.ts index 0df7aa89..4738697f 100644 --- a/desktop/src/types/session.ts +++ b/desktop/src/types/session.ts @@ -51,6 +51,12 @@ export type MessageEntry = { timestamp: string model?: string usage?: MessageUsage + /** + * Identity of the API response this `usage` belongs to, when it has one. One assistant reply + * is persisted as several lines that each repeat the whole `usage` object, so anything that + * totals usage must count each key once. Absent means the line carries no id — count it. + */ + usageKey?: string parentUuid?: string parentToolUseId?: string isSidechain?: boolean diff --git a/src/QueryEngine.ts b/src/QueryEngine.ts index d71e5780..946ebfb9 100644 --- a/src/QueryEngine.ts +++ b/src/QueryEngine.ts @@ -3,6 +3,7 @@ import type { ContentBlockParam } from '@anthropic-ai/sdk/resources/messages.mjs import { randomUUID } from 'crypto' import last from 'lodash-es/last.js' import { + addToTotalGenerationDuration, getSessionId, isSessionPersistenceDisabled, } from 'src/bootstrap/state.js' @@ -192,6 +193,11 @@ export class QueryEngine { private abortController: AbortController private permissionDenials: SDKPermissionDenial[] private totalUsage: NonNullableUsage + // Generation timing for this turn, summed over every API request it made. `decodeMs` + // excludes prefill and tool execution, so it is the denominator a tokens/sec reading + // needs; `ttftMs` is kept for the request-to-first-token wait it deliberately omits. + private totalDecodeMs = 0 + private totalTtftMs = 0 private hasHandledOrphanedPermission = false private readFileState: FileStateCache // Turn-scoped skill discovery tracking (feeds was_discovered on @@ -645,6 +651,11 @@ export class QueryEngine { is_error: false, duration_ms: Date.now() - startTime, duration_api_ms: getTotalAPIDuration(), + // Generation-only timings for this turn. `duration_api_ms` covers the whole request + // including prefill, so a tokens/sec reading built from it understates fast models on + // long contexts; decode_ms is the span tokens were actually being emitted over. + ttft_ms: this.totalTtftMs, + decode_ms: this.totalDecodeMs, num_turns: messages.length - 1, result: resultText ?? '', stop_reason: null, @@ -682,6 +693,9 @@ export class QueryEngine { // Track current message usage (reset on each message_start) let currentMessageUsage: NonNullableUsage = EMPTY_USAGE + // Same scope as currentMessageUsage: an attempt that dies before message_stop must + // discard its timings too, otherwise a retried request bills prefill time twice. + let currentMessageTtftMs = 0 let turnCount = 1 let hasAcknowledgedInitialMessages = false // Track structured output from StructuredOutput tool calls @@ -819,6 +833,7 @@ export class QueryEngine { currentMessageUsage, message.event.message.usage, ) + currentMessageTtftMs = message.ttftMs ?? 0 } if (message.event.type === 'message_delta') { currentMessageUsage = updateUsage( @@ -839,6 +854,14 @@ export class QueryEngine { this.totalUsage, currentMessageUsage, ) + this.totalDecodeMs += message.decodeMs ?? 0 + this.totalTtftMs += currentMessageTtftMs + // Session-scoped twin of the turn totals above: survives across turns so the + // usage snapshot can report generation speed for the whole conversation. + addToTotalGenerationDuration( + message.decodeMs ?? 0, + currentMessageTtftMs, + ) } if (includePartialMessages) { diff --git a/src/bootstrap/state.ts b/src/bootstrap/state.ts index 5ed51af8..5148f858 100644 --- a/src/bootstrap/state.ts +++ b/src/bootstrap/state.ts @@ -52,6 +52,10 @@ type State = { totalAPIDuration: number totalAPIDurationWithoutRetries: number totalToolDuration: number + // Generation-only timing: the span from the first emitted delta to the end of each API + // response, and the prefill wait that precedes it. See QueryEngine's per-turn accumulators. + totalDecodeDuration: number + totalTtftDuration: number turnHookDurationMs: number turnToolDurationMs: number turnClassifierDurationMs: number @@ -285,6 +289,8 @@ function getInitialState(): State { totalAPIDuration: 0, totalAPIDurationWithoutRetries: 0, totalToolDuration: 0, + totalDecodeDuration: 0, + totalTtftDuration: 0, turnHookDurationMs: 0, turnToolDurationMs: 0, turnClassifierDurationMs: 0, @@ -548,10 +554,28 @@ export function addToTotalDurationState( STATE.totalAPIDurationWithoutRetries += durationWithoutRetries } +export function addToTotalGenerationDuration( + decodeDuration: number, + ttftDuration: number, +): void { + STATE.totalDecodeDuration += decodeDuration + STATE.totalTtftDuration += ttftDuration +} + +export function getTotalDecodeDuration(): number { + return STATE.totalDecodeDuration +} + +export function getTotalTtftDuration(): number { + return STATE.totalTtftDuration +} + export function resetTotalDurationStateAndCost_FOR_TESTS_ONLY(): void { STATE.totalAPIDuration = 0 STATE.totalAPIDurationWithoutRetries = 0 STATE.totalCostUSD = 0 + STATE.totalDecodeDuration = 0 + STATE.totalTtftDuration = 0 } export function addToTotalCostState( @@ -866,6 +890,8 @@ export function resetCostState(): void { STATE.totalAPIDuration = 0 STATE.totalAPIDurationWithoutRetries = 0 STATE.totalToolDuration = 0 + STATE.totalDecodeDuration = 0 + STATE.totalTtftDuration = 0 STATE.startTime = Date.now() STATE.totalLinesAdded = 0 STATE.totalLinesRemoved = 0 @@ -882,6 +908,8 @@ export function setCostStateForRestore({ totalCostUSD, totalAPIDuration, totalAPIDurationWithoutRetries, + totalDecodeDuration, + totalTtftDuration, totalToolDuration, totalLinesAdded, totalLinesRemoved, @@ -891,6 +919,8 @@ export function setCostStateForRestore({ totalCostUSD: number totalAPIDuration: number totalAPIDurationWithoutRetries: number + totalDecodeDuration: number + totalTtftDuration: number totalToolDuration: number totalLinesAdded: number totalLinesRemoved: number @@ -900,6 +930,8 @@ export function setCostStateForRestore({ STATE.totalCostUSD = totalCostUSD STATE.totalAPIDuration = totalAPIDuration STATE.totalAPIDurationWithoutRetries = totalAPIDurationWithoutRetries + STATE.totalDecodeDuration = totalDecodeDuration + STATE.totalTtftDuration = totalTtftDuration STATE.totalToolDuration = totalToolDuration STATE.totalLinesAdded = totalLinesAdded STATE.totalLinesRemoved = totalLinesRemoved diff --git a/src/cost-tracker.ts b/src/cost-tracker.ts index 218f8985..b5b91521 100644 --- a/src/cost-tracker.ts +++ b/src/cost-tracker.ts @@ -13,11 +13,13 @@ import { getTotalCacheCreationInputTokens, getTotalCacheReadInputTokens, getTotalCostUSD, + getTotalDecodeDuration, getTotalDuration, getTotalInputTokens, getTotalLinesAdded, getTotalLinesRemoved, getTotalOutputTokens, + getTotalTtftDuration, getTotalToolDuration, getTotalWebSearchRequests, getUsageForModel, @@ -73,6 +75,10 @@ export type SessionUsageSnapshot = { costDisplay: string hasUnknownModelCost: boolean totalAPIDuration: number + // Time the model spent emitting tokens, excluding prefill and tool execution. Zero when + // no streamed response reported a decode span (non-streaming fallback, aborted turn). + totalDecodeDuration: number + totalTtftDuration: number totalDuration: number totalLinesAdded: number totalLinesRemoved: number @@ -100,6 +106,8 @@ type StoredCostState = { totalCostUSD: number totalAPIDuration: number totalAPIDurationWithoutRetries: number + totalDecodeDuration: number + totalTtftDuration: number totalToolDuration: number totalLinesAdded: number totalLinesRemoved: number @@ -142,6 +150,8 @@ export function getStoredSessionCosts( totalAPIDuration: projectConfig.lastAPIDuration ?? 0, totalAPIDurationWithoutRetries: projectConfig.lastAPIDurationWithoutRetries ?? 0, + totalDecodeDuration: projectConfig.lastDecodeDuration ?? 0, + totalTtftDuration: projectConfig.lastTtftDuration ?? 0, totalToolDuration: projectConfig.lastToolDuration ?? 0, totalLinesAdded: projectConfig.lastLinesAdded ?? 0, totalLinesRemoved: projectConfig.lastLinesRemoved ?? 0, @@ -174,6 +184,8 @@ export function saveCurrentSessionCosts(fpsMetrics?: FpsMetrics): void { lastCost: getTotalCostUSD(), lastAPIDuration: getTotalAPIDuration(), lastAPIDurationWithoutRetries: getTotalAPIDurationWithoutRetries(), + lastDecodeDuration: getTotalDecodeDuration(), + lastTtftDuration: getTotalTtftDuration(), lastToolDuration: getTotalToolDuration(), lastDuration: getTotalDuration(), lastLinesAdded: getTotalLinesAdded(), @@ -277,6 +289,8 @@ export function getSessionUsageSnapshot(): SessionUsageSnapshot { costDisplay: formatCost(getTotalCostUSD()), hasUnknownModelCost: hasUnknownModelCost(), totalAPIDuration: getTotalAPIDuration(), + totalDecodeDuration: getTotalDecodeDuration(), + totalTtftDuration: getTotalTtftDuration(), totalDuration: getTotalDuration(), totalLinesAdded: getTotalLinesAdded(), totalLinesRemoved: getTotalLinesRemoved(), diff --git a/src/server/__tests__/session-inspection-usage-only.test.ts b/src/server/__tests__/session-inspection-usage-only.test.ts new file mode 100644 index 00000000..421c6729 --- /dev/null +++ b/src/server/__tests__/session-inspection-usage-only.test.ts @@ -0,0 +1,157 @@ +import { afterEach, beforeEach, describe, expect, it } from 'bun:test' +import * as fs from 'node:fs/promises' +import * as os from 'node:os' +import * as path from 'node:path' +import { handleSessionsApi } from '../api/sessions.js' +import { conversationService } from '../services/conversationService.js' +import { __resetWebSocketHandlerStateForTests } from '../ws/handler.js' + +/** + * `usageOnly` exists so the context panel can poll a live session's totals without paying for + * the full inspection — which additionally scans every skill directory on disk, asks the CLI + * for MCP status, and re-reads the whole transcript to cross-check usage. Those three are fine + * once; they are not fine every few seconds. These tests pin both the payload and, more + * importantly, the set of CLI controls the cheap path is allowed to issue. + */ + +const SESSION_ID = 'session-usage-only' + +let tempRoot: string +let workDir: string +let requestedSubtypes: string[] +let original: { + hasSession: typeof conversationService.hasSession + getSessionWorkDir: typeof conversationService.getSessionWorkDir + getSessionPermissionMode: typeof conversationService.getSessionPermissionMode + getSessionInitMessage: typeof conversationService.getSessionInitMessage + getRecentSdkMessages: typeof conversationService.getRecentSdkMessages + requestControl: typeof conversationService.requestControl +} + +const usageSnapshot = { + totalCostUSD: 0.5, + costDisplay: '$0.50', + hasUnknownModelCost: false, + totalAPIDuration: 42_000, + totalDecodeDuration: 12_000, + totalTtftDuration: 3_000, + totalDuration: 600, + totalLinesAdded: 0, + totalLinesRemoved: 0, + totalInputTokens: 1_000, + totalOutputTokens: 2_400, + totalCacheReadInputTokens: 9_000, + totalCacheCreationInputTokens: 0, + totalWebSearchRequests: 0, + models: [], +} + +async function inspect(query: string): Promise> { + const url = new URL(`http://localhost/api/sessions/${SESSION_ID}/inspection${query}`) + const response = await handleSessionsApi( + new Request(url, { method: 'GET' }), + url, + ['api', 'sessions', SESSION_ID, 'inspection'], + ) + expect(response.status).toBe(200) + return await response.json() as Record +} + +beforeEach(async () => { + tempRoot = await fs.mkdtemp(path.join(os.tmpdir(), 'cc-haha-usage-only-')) + workDir = path.join(tempRoot, 'project') + await fs.mkdir(workDir, { recursive: true }) + __resetWebSocketHandlerStateForTests() + + requestedSubtypes = [] + original = { + hasSession: conversationService.hasSession, + getSessionWorkDir: conversationService.getSessionWorkDir, + getSessionPermissionMode: conversationService.getSessionPermissionMode, + getSessionInitMessage: conversationService.getSessionInitMessage, + getRecentSdkMessages: conversationService.getRecentSdkMessages, + requestControl: conversationService.requestControl, + } + + conversationService.hasSession = ((id: string) => + id === SESSION_ID) as typeof conversationService.hasSession + conversationService.getSessionWorkDir = (() => + workDir) as typeof conversationService.getSessionWorkDir + conversationService.getSessionPermissionMode = (() => + 'default') as typeof conversationService.getSessionPermissionMode + conversationService.getSessionInitMessage = (() => ({ + type: 'system', + subtype: 'init', + model: 'claude-opus-4-7', + cwd: workDir, + tools: [], + mcp_servers: [], + slash_commands: [], + })) as typeof conversationService.getSessionInitMessage + conversationService.getRecentSdkMessages = (() => + []) as typeof conversationService.getRecentSdkMessages + conversationService.requestControl = (async ( + _sessionId: string, + request: { subtype: string }, + ) => { + requestedSubtypes.push(request.subtype) + return request.subtype === 'get_session_usage' ? usageSnapshot : {} + }) as typeof conversationService.requestControl +}) + +afterEach(async () => { + conversationService.hasSession = original.hasSession + conversationService.getSessionWorkDir = original.getSessionWorkDir + conversationService.getSessionPermissionMode = original.getSessionPermissionMode + conversationService.getSessionInitMessage = original.getSessionInitMessage + conversationService.getRecentSdkMessages = original.getRecentSdkMessages + conversationService.requestControl = original.requestControl + __resetWebSocketHandlerStateForTests() + await fs.rm(tempRoot, { recursive: true, force: true }) +}) + +describe('session inspection: usageOnly', () => { + it('returns running totals from a single get_session_usage control', async () => { + const body = await inspect('?includeContext=0&usageOnly=1') + + expect(requestedSubtypes).toEqual(['get_session_usage']) + expect(body.usage).toEqual({ ...usageSnapshot, source: 'current_process' }) + }) + + it('skips MCP status, unlike the full inspection', async () => { + await inspect('?includeContext=0&usageOnly=1') + + expect(requestedSubtypes).not.toContain('mcp_status') + expect(requestedSubtypes).not.toContain('get_context_usage') + }) + + it('does not report context, so a poll cannot be mistaken for a context refresh', async () => { + const body = await inspect('?includeContext=0&usageOnly=1') + + expect('context' in body).toBe(false) + expect('contextEstimate' in body).toBe(false) + }) + + it('still asks for the expensive controls on a full inspection', async () => { + // The negative control for the tests above: if the cheap path were achieved by gutting the + // full one, every one of these assertions would pass while the inspector lost its data. + await inspect('?includeContext=1') + + expect(requestedSubtypes).toContain('get_session_usage') + expect(requestedSubtypes).toContain('get_context_usage') + expect(requestedSubtypes).toContain('mcp_status') + }) + + it('reports a control failure as an error instead of falling back to a transcript re-read', async () => { + conversationService.requestControl = (async () => { + throw new Error('CLI control timed out') + }) as typeof conversationService.requestControl + + const body = await inspect('?includeContext=0&usageOnly=1') + + // Falling back would mean re-reading the whole JSONL on every tick, which is the cost this + // mode exists to avoid; the panel keeps its last good numbers and retries instead. + expect(body.usage).toBeUndefined() + expect((body.errors as Record)?.usage).toContain('CLI control timed out') + }) +}) diff --git a/src/server/__tests__/sessions.test.ts b/src/server/__tests__/sessions.test.ts index 1aaaa08a..ae9a4d57 100644 --- a/src/server/__tests__/sessions.test.ts +++ b/src/server/__tests__/sessions.test.ts @@ -3587,6 +3587,99 @@ describe('Sessions API', () => { expect(inspection.status.permissionMode).toBe('bypassPermissions') }) + it('counts a multi-block assistant reply once when rebuilding transcript usage', async () => { + const workDir = await fs.mkdtemp(path.join(tmpDir, 'api-session-usage-dedup-')) + const sessionId = '11111111-2222-3333-4444-555555555555' + const projectDir = '-tmp-api-session-usage-dedup' + const messageId = 'msg_shared_reply' + const replyUsage = { + input_tokens: 100, + output_tokens: 250, + cache_read_input_tokens: 1_000, + cache_creation_input_tokens: 20, + } + // Claude Code writes one JSONL line per content block of a reply and repeats the complete + // `usage` object on every one. Three lines here stand for one reply with thinking + text + + // tool_use; summing them raw is the 2.2x inflation `usageAccounting.ts` documents. + const blockLine = () => ({ + parentUuid: null, + isSidechain: false, + type: 'assistant', + message: { + model: 'claude-opus-4-7', + id: messageId, + type: 'message', + role: 'assistant', + content: [{ type: 'text', text: 'block' }], + usage: replyUsage, + }, + uuid: crypto.randomUUID(), + timestamp: '2026-01-01T00:02:00.000Z', + sessionId, + cwd: workDir, + }) + await writeSessionFile(projectDir, sessionId, [ + makeSessionMetaEntry(workDir), + makeUserEntry('go', crypto.randomUUID()), + blockLine(), + blockLine(), + blockLine(), + ]) + + const res = await fetch(`${baseUrl}/api/sessions/${sessionId}/inspection?includeContext=0`) + expect(res.status).toBe(200) + const body = await res.json() as { + usage?: { + totalInputTokens: number + totalOutputTokens: number + totalCacheReadInputTokens: number + totalCacheCreationInputTokens: number + } + } + + expect(body.usage?.totalInputTokens).toBe(100) + expect(body.usage?.totalOutputTokens).toBe(250) + expect(body.usage?.totalCacheReadInputTokens).toBe(1_000) + expect(body.usage?.totalCacheCreationInputTokens).toBe(20) + }) + + it('still totals separate assistant replies separately after dedup', async () => { + // The negative control for the test above: a dedup key that collapsed too much would make + // every reply after the first free, which is a far worse error than the inflation it fixes. + const workDir = await fs.mkdtemp(path.join(tmpDir, 'api-session-usage-distinct-')) + const sessionId = '22222222-3333-4444-5555-666666666666' + const projectDir = '-tmp-api-session-usage-distinct' + const reply = (messageId: string, outputTokens: number) => ({ + parentUuid: null, + isSidechain: false, + type: 'assistant', + message: { + model: 'claude-opus-4-7', + id: messageId, + type: 'message', + role: 'assistant', + content: [{ type: 'text', text: 'reply' }], + usage: { input_tokens: 10, output_tokens: outputTokens }, + }, + uuid: crypto.randomUUID(), + timestamp: '2026-01-01T00:02:00.000Z', + sessionId, + cwd: workDir, + }) + await writeSessionFile(projectDir, sessionId, [ + makeSessionMetaEntry(workDir), + makeUserEntry('go', crypto.randomUUID()), + reply('msg_first', 300), + reply('msg_second', 70), + ]) + + const res = await fetch(`${baseUrl}/api/sessions/${sessionId}/inspection?includeContext=0`) + const body = await res.json() as { usage?: { totalInputTokens: number; totalOutputTokens: number } } + + expect(body.usage?.totalOutputTokens).toBe(370) + expect(body.usage?.totalInputTokens).toBe(20) + }) + it('GET /api/sessions/repository-context should return branch launch metadata', async () => { const workDir = await createCleanGitRepo(tmpDir) const res = await fetch( diff --git a/src/server/__tests__/translateCliMessage.timing.test.ts b/src/server/__tests__/translateCliMessage.timing.test.ts new file mode 100644 index 00000000..908a5628 --- /dev/null +++ b/src/server/__tests__/translateCliMessage.timing.test.ts @@ -0,0 +1,91 @@ +import { describe, expect, it } from 'bun:test' +import { translateCliMessage } from '../ws/handler.js' + +/** + * The CLI's `result` message has always carried `duration_ms` / `duration_api_ms`, and now + * `decode_ms` / `ttft_ms` alongside them. The translation used to drop all four, which is why + * nothing downstream could report how fast a session was generating. These pin the forwarding, + * including the "absent means unknown" rule that keeps a client from dividing by zero. + */ +function resultMessages(overrides: Record) { + return translateCliMessage( + { + type: 'result', + subtype: 'success', + is_error: false, + duration_ms: 0, + duration_api_ms: 0, + usage: { input_tokens: 10, output_tokens: 20 }, + ...overrides, + }, + 'session-timing', + ) as Array<{ type: string; usage?: unknown; timing?: Record }> +} + +describe('translateCliMessage: result timing', () => { + it('forwards generation timings onto message_complete', () => { + const [message] = resultMessages({ + duration_ms: 12_000, + duration_api_ms: 9_000, + decode_ms: 7_500, + ttft_ms: 1_200, + }) + + expect(message?.type).toBe('message_complete') + expect(message?.timing).toEqual({ + duration_ms: 12_000, + duration_api_ms: 9_000, + ttft_ms: 1_200, + decode_ms: 7_500, + }) + // The token buckets must keep flowing untouched — timing rides alongside, not instead. + expect(message?.usage).toEqual({ input_tokens: 10, output_tokens: 20 }) + }) + + it('omits timing entirely when the CLI reported none', () => { + const [message] = resultMessages({}) + + expect(message?.type).toBe('message_complete') + // Absent rather than zero: a zero decode span would be read as "instant" and turn into an + // infinite tokens/sec, whereas absent lets the client withhold the figure. + expect(message?.timing).toBeUndefined() + expect('timing' in (message ?? {})).toBe(false) + }) + + it('keeps a partial timing report instead of discarding it', () => { + // An older CLI reports wall clock only; the remaining fields default to 0 so the shape + // stays stable for consumers that read a single field. + const [message] = resultMessages({ duration_ms: 5_000 }) + + expect(message?.timing).toEqual({ + duration_ms: 5_000, + duration_api_ms: 0, + ttft_ms: 0, + decode_ms: 0, + }) + }) + + it('ignores non-numeric timing values rather than emitting NaN', () => { + const [message] = resultMessages({ + duration_ms: 'soon', + decode_ms: null, + ttft_ms: Number.NaN, + duration_api_ms: Number.POSITIVE_INFINITY, + }) + + expect(message?.timing).toBeUndefined() + }) + + it('carries timing on an errored result too', () => { + const messages = resultMessages({ + is_error: true, + result: 'boom', + duration_ms: 3_000, + decode_ms: 2_000, + }) + + const complete = messages.find((message) => message.type === 'message_complete') + // Tokens were generated and billed before the failure; the timing is as real as the usage. + expect(complete?.timing?.decode_ms).toBe(2_000) + }) +}) diff --git a/src/server/api/sessions.ts b/src/server/api/sessions.ts index 78ab7369..ac5274ad 100644 --- a/src/server/api/sessions.ts +++ b/src/server/api/sessions.ts @@ -68,6 +68,13 @@ import { PET_SESSION_LIMIT } from '../petAccessPolicy.js' const DEFAULT_GIT_INFO_COMMAND_TIMEOUT_MS = 3_000 +/** + * Budget for the polling `get_session_usage` control. Shorter than the inspection's basic + * control timeout because the caller retries on its own cadence: a slow answer is worth less + * than a stale one that blocks the next poll. + */ +const USAGE_ONLY_CONTROL_TIMEOUT_MS = 2_500 + const workspaceService = new WorkspaceService( async (sessionId) => ( conversationService.getSessionWorkDir(sessionId) || @@ -987,6 +994,10 @@ async function getSessionSlashCommands(sessionId: string): Promise { async function getSessionInspection(req: Request, sessionId: string, url: URL): Promise { const includeContext = url.searchParams.get('includeContext') !== '0' const contextOnly = includeContext && url.searchParams.get('contextOnly') === '1' + // Lightweight polling mode for the context panel: one `get_session_usage` control and + // nothing else. The full inspection also scans the skills directory and re-reads the whole + // transcript to cross-check usage, which is far too much work to repeat every few seconds. + const usageOnly = !includeContext && url.searchParams.get('usageOnly') === '1' let transcriptSnapshot: Awaited> | undefined const getTranscriptSnapshot = async () => { if (transcriptSnapshot !== undefined) return transcriptSnapshot @@ -1011,17 +1022,21 @@ async function getSessionInspection(req: Request, sessionId: string, url: URL): [...conversationService.getRecentSdkMessages(sessionId)] .reverse() .find((message) => message?.type === 'system' && message.subtype === 'init') - const transcriptMetadata = !active || !initMessage + const transcriptMetadata = !usageOnly && (!active || !initMessage) ? (await getTranscriptSnapshot())?.metadata ?? null : null const cachedSlashCommands = getSlashCommands(sessionId) const hasCliSlashCommands = cachedSlashCommands.length > 0 - const skillSlashCommands = await listSkillSlashCommands(workDir, { - includeCompiledIn: !hasCliSlashCommands, - }) - const fallbackSlashCommands = hasCliSlashCommands - ? mergeSessionSlashCommands(cachedSlashCommands, skillSlashCommands) - : skillSlashCommands + // `listSkillSlashCommands` walks every skill directory on disk with no cache. The usage + // poll does not need a command count, so it must not pay for one. + const fallbackSlashCommands = usageOnly + ? [] + : hasCliSlashCommands + ? mergeSessionSlashCommands( + cachedSlashCommands, + await listSkillSlashCommands(workDir, { includeCompiledIn: false }), + ) + : await listSkillSlashCommands(workDir, { includeCompiledIn: true }) const slashCommandCount = Array.isArray(initMessage?.slash_commands) ? initMessage.slash_commands.length : fallbackSlashCommands.length @@ -1063,6 +1078,28 @@ async function getSessionInspection(req: Request, sessionId: string, url: URL): } const errors: Record = {} + if (usageOnly) { + // No `mcp_status`, no skills scan, and deliberately no transcript cross-check: the + // transcript re-read is what made this endpoint too expensive to poll. The CLI's own + // running totals are the authoritative numbers for a live session anyway. + try { + response.usage = { + ...(await conversationService.requestControl( + sessionId, + { subtype: 'get_session_usage' }, + USAGE_ONLY_CONTROL_TIMEOUT_MS, + req.signal, + )), + source: 'current_process', + } + } catch (error) { + throwIfRequestAborted(req) + errors.usage = error instanceof Error ? error.message : String(error) + } + response.errors = errors + return Response.json(response) + } + if (contextOnly) { try { response.context = await conversationService.requestControl( diff --git a/src/server/services/sessionService.ts b/src/server/services/sessionService.ts index 0147f679..2e076a4b 100644 --- a/src/server/services/sessionService.ts +++ b/src/server/services/sessionService.ts @@ -69,7 +69,11 @@ import type { } from './localIndex/sessionIndex.js' import type { LocalIndexStatus } from './localIndex/types.js' import { diagnosticsService } from './diagnosticsService.js' -import { isForkInheritedUsageRecord } from '../../utils/usageAccounting.js' +import { + isBillableUsageRecord, + isForkInheritedUsageRecord, + usageRecordKey, +} from '../../utils/usageAccounting.js' import { ProjectSessionHistory, type ProjectHistoryOptions, @@ -214,6 +218,15 @@ export type MessageEntry = { timestamp: string model?: string usage?: MessageUsage + /** + * Identity of the API response `usage` belongs to, when it has one. + * + * A single assistant reply is persisted as one line per content block, each repeating the + * whole `usage` object, so any consumer that totals usage must count a given key once. + * Computed here (rather than by each consumer) so the rule lives in one place; absent when + * the line carries no message id, which by the same convention means "always count it". + */ + usageKey?: string parentUuid?: string parentToolUseId?: string isSidechain?: boolean @@ -257,6 +270,8 @@ export type TranscriptUsageSnapshot = { costDisplay: string hasUnknownModelCost: boolean totalAPIDuration: number + totalDecodeDuration: number + totalTtftDuration: number totalDuration: number totalLinesAdded: number totalLinesRemoved: number @@ -378,6 +393,35 @@ type TranscriptContextAccumulator = { transcriptHasMediaInput: boolean } +/** + * Whether this line's `usage` is the first sighting of its reply. + * + * Claude Code writes one JSONL line per content block of an assistant message and repeats the + * complete `usage` object on every one — a reply with thinking, text and 12 tool_use blocks is + * 14 lines carrying the same numbers. Summing raw lines overstated real transcripts by 2.2x, + * which is why `stats.ts` and the activity index both deduplicate; the inspector paths had + * inherited only the fork check and so reported inflated totals to the context panel. + * + * Rules (and the key shape) come from `usageAccounting.ts` so every reader of a transcript + * agrees about what one session cost. + */ +function claimUsageRecord(entry: RawEntry, countedKeys: Set): boolean { + const record = entry as unknown as Record + const identity = { + version: record.version, + sessionId: record.sessionId, + requestId: record.requestId, + messageId: entry.message?.id, + forkedFrom: record.forkedFrom, + } + if (!isBillableUsageRecord(identity)) return false + const key = usageRecordKey(identity) + if (key === null) return true + if (countedKeys.has(key)) return false + countedKeys.add(key) + return true +} + function createTranscriptContextAccumulator(): TranscriptContextAccumulator { return { latestModel: null, @@ -1727,6 +1771,14 @@ export class SessionService { const usage = isForkInheritedUsageRecord(entry) ? undefined : normalizeMessageUsage(msg.usage) + const usageKey = usage + ? usageRecordKey({ + version: entry.version, + sessionId: entry.sessionId, + requestId: entry.requestId, + messageId: entry.message?.id, + }) ?? undefined + : undefined return { id: entry.uuid || crypto.randomUUID(), @@ -1736,6 +1788,7 @@ export class SessionService { timestamp: entry.timestamp || new Date().toISOString(), model: msg.model, ...(usage ? { usage } : {}), + ...(usageKey ? { usageKey } : {}), parentUuid: entry.parentUuid ?? undefined, parentToolUseId, isSidechain: entry.isSidechain, @@ -2883,9 +2936,13 @@ export class SessionService { let firstUsageAt: number | null = null let lastUsageAt: number | null = null + const countedUsageKeys = new Set() + for (const entry of entries) { currentRuntimeHint = this.applyRuntimeContextMetadata(currentRuntimeHint, entry) - if (isForkInheritedUsageRecord(entry)) continue + // Fork-inherited lines and the repeated usage objects of a multi-block reply are the + // same class of over-count; `claimUsageRecord` rejects both. + if (!claimUsageRecord(entry, countedUsageKeys)) continue const usage = entry.message?.usage const model = entry.message?.model if (!usage || typeof model !== 'string') continue @@ -3016,6 +3073,7 @@ export class SessionService { let lastUsageAt: number | null = null const contextState = createTranscriptContextAccumulator() + const countedUsageKeys = new Set() await this.streamJsonlFile(found.filePath, (entry) => { if (typeof entry.message?.model === 'string') { @@ -3098,9 +3156,9 @@ export class SessionService { ? usage.server_tool_use.web_search_requests : 0 - // Inherited fork history still describes the current context, but its API usage belongs to - // the source session and must not be included in this fork's cumulative usage or cost. - if (isForkInheritedUsageRecord(entry)) return + // Fork-inherited lines and the repeated usage objects of a multi-block reply are the + // same class of over-count; `claimUsageRecord` rejects both. + if (!claimUsageRecord(entry, countedUsageKeys)) return if ( inputTokens === 0 && @@ -3200,6 +3258,11 @@ export class SessionService { costDisplay: this.formatCost(totalCostUSD), hasUnknownModelCost, totalAPIDuration: 0, + // Generation timings live only in the CLI process (and the resume snapshot it + // writes to project config); a transcript has no per-response span to rebuild + // them from, so callers must treat 0 as "unknown" rather than "instant". + totalDecodeDuration: 0, + totalTtftDuration: 0, totalDuration: firstUsageAt !== null && lastUsageAt !== null ? Math.max(0, Math.round((lastUsageAt - firstUsageAt) / 1000)) diff --git a/src/server/ws/events.ts b/src/server/ws/events.ts index 9b9ddf5e..cc3fc8d6 100644 --- a/src/server/ws/events.ts +++ b/src/server/ws/events.ts @@ -100,7 +100,7 @@ export type ServerMessage = turnActive: boolean } | { type: 'user_message_replay'; content: string } - | { type: 'message_complete'; usage: TokenUsage } + | { type: 'message_complete'; usage: TokenUsage; timing?: TurnTiming } /** * `text` is a fragment when the CLI streams `thinking_delta`, and a whole block when * it hands over a finished `thinking` block. The client has to concatenate the first @@ -160,6 +160,23 @@ export type TokenUsage = { cache_creation_tokens?: number } +/** + * Generation timings for one turn, in milliseconds. + * + * `duration_ms` is wall clock and therefore includes tool execution; `duration_api_ms` covers + * only the API requests but includes prefill. `decode_ms` is the span over which the model was + * actually emitting tokens — it excludes both — and is the right denominator for tokens/sec. + * `ttft_ms` is carried so a client can explain the gap between `duration_api_ms` and `decode_ms`. + * + * Absent when the turn produced no timed stream; never treat a missing value as zero seconds. + */ +export type TurnTiming = { + duration_ms: number + duration_api_ms: number + ttft_ms: number + decode_ms: number +} + export type ChatState = 'idle' | 'thinking' | 'compacting' | 'tool_executing' | 'streaming' | 'permission_pending' // 与 CLI 的 streaming_fallback cause 对齐；unknown 兜底未来新增的 cause 值， diff --git a/src/server/ws/handler.ts b/src/server/ws/handler.ts index fffa1bd0..fa22d165 100644 --- a/src/server/ws/handler.ts +++ b/src/server/ws/handler.ts @@ -13,6 +13,7 @@ import type { PermissionMode, ServerMessage, TokenUsage, + TurnTiming, } from './events.js' import { RUNTIME_CONFIG_APPLIED_EVENT } from './events.js' import * as os from 'node:os' @@ -493,6 +494,31 @@ function usageNumber(value: unknown): number { return typeof value === 'number' && Number.isFinite(value) ? value : 0 } +/** + * Generation timings the CLI reports on its `result` message. + * + * These used to be dropped here, which is why nothing downstream could say how fast tokens were + * being produced. `decode_ms` is the one that matters: it spans only the time the model spent + * emitting tokens, so `output_tokens / decode_ms` is a rate rather than a number diluted by + * prefill and tool execution. All four are 0/absent together when the turn produced no timed + * stream (non-streaming fallback, or a CLI too old to report them). + */ +function translateCliTiming(cliMsg: Record): TurnTiming | undefined { + const durationMs = usageNumber(cliMsg.duration_ms) + const durationApiMs = usageNumber(cliMsg.duration_api_ms) + const decodeMs = usageNumber(cliMsg.decode_ms) + const ttftMs = usageNumber(cliMsg.ttft_ms) + if (durationMs === 0 && durationApiMs === 0 && decodeMs === 0 && ttftMs === 0) { + return undefined + } + return { + duration_ms: durationMs, + duration_api_ms: durationApiMs, + ttft_ms: ttftMs, + decode_ms: decodeMs, + } +} + function translateCliUsage(usage: unknown): TokenUsage { const record = usage && typeof usage === 'object' ? usage as Record @@ -3235,6 +3261,7 @@ export function translateCliMessage(cliMsg: any, sessionId: string): ServerMessa case 'result': { // 对话结果（成功或错误） const usage = translateCliUsage(cliMsg.usage) + const timing = translateCliTiming(cliMsg) // Buffered assistant blocks can arrive as a batch after all raw events // for one provider message. Keep deduplication active across the entire // batch, then clear it only at the terminal result boundary. @@ -3243,11 +3270,13 @@ export function translateCliMessage(cliMsg: any, sessionId: string): ServerMessa if (cliMsg.is_error) { // If the user requested stop, this "error" is just the interrupt // result — don't show it as an error in the chat UI. + // Timing survives an interrupt: the tokens really were generated and paid for, + // and a cancelled turn is exactly when a client wants to know what it cost. if ( interruptedTurnResultMessages.get(cliMsg) === sessionId || sessionStopRequested.has(sessionId) ) { - return [{ type: 'message_complete', usage }] + return [{ type: 'message_complete', usage, ...(timing ? { timing } : {}) }] } const resultMessage = @@ -3257,7 +3286,7 @@ export function translateCliMessage(cliMsg: any, sessionId: string): ServerMessa : 'Unknown error') if (isDuplicateOfLastApiError(streamState.lastApiError, resultMessage)) { streamState.lastApiError = undefined - return [{ type: 'message_complete', usage }] + return [{ type: 'message_complete', usage, ...(timing ? { timing } : {}) }] } // 错误和完成消息都发送 return [ @@ -3266,12 +3295,12 @@ export function translateCliMessage(cliMsg: any, sessionId: string): ServerMessa message: resultMessage, code: classifyRuntimeErrorCode(resultMessage, 'CLI_ERROR'), }, - { type: 'message_complete', usage }, + { type: 'message_complete', usage, ...(timing ? { timing } : {}) }, ] } streamState.lastApiError = undefined - return [{ type: 'message_complete', usage }] + return [{ type: 'message_complete', usage, ...(timing ? { timing } : {}) }] } case 'system': { diff --git a/src/services/api/claude.ts b/src/services/api/claude.ts index e0059ba6..6cc16bcd 100644 --- a/src/services/api/claude.ts +++ b/src/services/api/claude.ts @@ -237,6 +237,7 @@ import { StreamWatchdogTimeoutError, createStreamWatchdogState, } from "./streamWatchdog.js"; +import { StreamDecodeSpan } from "./streamDecodeSpan.js"; import { jsonStringify } from "../../utils/slowOperations.js"; import { isBetaTracingEnabled, @@ -1957,6 +1958,11 @@ async function* queryModel( deferToolUseCommit: true, }); let ttftMs = 0; + // Decode span for this request: first generated delta -> message_stop. Deliberately excludes + // the prefill/TTFT phase, so output_tokens / decodeMs is real generation speed rather than a + // number diluted by prompt processing. Tool execution happens between API requests, so it + // never lands inside this span either. + const decodeSpan = new StreamDecodeSpan(); let partialMessage: BetaMessage | undefined = undefined; const contentBlocks: (BetaContentBlock | ConnectorTextBlock)[] = []; let usage: NonNullableUsage = EMPTY_USAGE; @@ -2059,6 +2065,7 @@ async function* queryModel( // reset state newMessages.length = 0; ttftMs = 0; + decodeSpan.reset(); partialMessage = undefined; contentBlocks.length = 0; usage = EMPTY_USAGE; @@ -2265,6 +2272,8 @@ async function* queryModel( resetStreamIdleTimer(); const now = Date.now(); + decodeSpan.record(receivedFirstContentDelta, now); + // Detect and log streaming stalls (only after first event to avoid counting TTFB) if (lastEventTime !== null) { const timeSinceLastEvent = now - lastEventTime; @@ -2660,6 +2669,11 @@ async function* queryModel( type: "stream_event", event: part, ...(part.type === "message_start" ? { ttftMs } : undefined), + // message_stop is the last event of the stream, so `now` closes the decode span. + // Absent when the span never opened (see StreamDecodeSpan). + ...(part.type === "message_stop" + ? { decodeMs: decodeSpan.elapsedMs(now) } + : undefined), }; } // Clear the idle timeout watchdog now that the stream loop has exited diff --git a/src/services/api/streamDecodeSpan.test.ts b/src/services/api/streamDecodeSpan.test.ts new file mode 100644 index 00000000..18d5f121 --- /dev/null +++ b/src/services/api/streamDecodeSpan.test.ts @@ -0,0 +1,63 @@ +import { describe, expect, test } from 'bun:test' +import { StreamDecodeSpan } from './streamDecodeSpan.js' + +describe('StreamDecodeSpan', () => { + test('measures from the first generated delta, not from request start', () => { + const span = new StreamDecodeSpan() + + // 2s of prefill: message_start and bookkeeping arrive, no token has been generated yet. + span.record(false, 1_000) + span.record(false, 1_200) + span.record(false, 2_000) + expect(span.elapsedMs(2_000)).toBe(0) + + // First real token at 2s; generation runs until the stream closes at 7s. + span.record(true, 2_000) + span.record(false, 5_000) + expect(span.elapsedMs(7_000)).toBe(5_000) + }) + + test('does not reopen the span on later content deltas', () => { + const span = new StreamDecodeSpan() + + span.record(true, 1_000) + // The watchdog flag only fires once, but a caller that passed it twice must not restart + // the clock — that would report a speed for the last token alone. + span.record(true, 4_000) + span.record(true, 6_000) + + expect(span.elapsedMs(9_000)).toBe(8_000) + }) + + test('reports nothing for a stream that never generated a token', () => { + const span = new StreamDecodeSpan() + + span.record(false, 1_000) + span.record(false, 9_000) + + // A request that produced no content has no rate to report. Returning the wait would let a + // caller divide output tokens by a prefill-only span. + expect(span.elapsedMs(9_000)).toBe(0) + }) + + test('reset clears the span for a retried attempt', () => { + const span = new StreamDecodeSpan() + span.record(true, 1_000) + expect(span.elapsedMs(4_000)).toBe(3_000) + + span.reset() + + // The second attempt's prefill must not be counted as generation time from the first. + span.record(false, 10_000) + expect(span.elapsedMs(10_000)).toBe(0) + span.record(true, 12_000) + expect(span.elapsedMs(15_000)).toBe(3_000) + }) + + test('never returns a negative span when the clock steps backwards', () => { + const span = new StreamDecodeSpan() + span.record(true, 5_000) + + expect(span.elapsedMs(4_000)).toBe(0) + }) +}) diff --git a/src/services/api/streamDecodeSpan.ts b/src/services/api/streamDecodeSpan.ts new file mode 100644 index 00000000..5eb5ccc2 --- /dev/null +++ b/src/services/api/streamDecodeSpan.ts @@ -0,0 +1,38 @@ +/** + * Tracks the span over which a single API response was emitting tokens. + * + * Tokens/sec is only meaningful as `output_tokens / decode_ms` when the denominator excludes the + * prefill wait and every tool round-trip. So the span opens at the first *generated* delta rather + * than at request start, and it closes when the stream terminates — the same measurement the + * session projections make host-side in DeepSeek Harness. + * + * A stream that ends without `message_stop` reports 0, meaning "unknown", not "instant": the + * response was truncated, and a partial span would both understate the rate the model was + * actually running at and invite a caller to divide by a number that describes nothing. + */ +export class StreamDecodeSpan { + private firstContentDeltaAt: number | null = null + + /** Call at the top of each attempt — a retried request starts a fresh span. */ + reset(): void { + this.firstContentDeltaAt = null + } + + /** + * Record one stream event. + * + * `isFirstContentDelta` is the watchdog's transition flag, which is exactly "the first token + * was generated"; the span needs no inspection of its own. + */ + record(isFirstContentDelta: boolean, now: number): void { + if (isFirstContentDelta && this.firstContentDeltaAt === null) { + this.firstContentDeltaAt = now + } + } + + /** Milliseconds since the first generated delta, or 0 when no span ever opened. */ + elapsedMs(now: number): number { + if (this.firstContentDeltaAt === null) return 0 + return Math.max(0, now - this.firstContentDeltaAt) + } +} diff --git a/src/utils/config.ts b/src/utils/config.ts index 8f275aec..d22bacb3 100644 --- a/src/utils/config.ts +++ b/src/utils/config.ts @@ -79,6 +79,8 @@ export type ProjectConfig = { mcpServers?: Record lastAPIDuration?: number lastAPIDurationWithoutRetries?: number + lastDecodeDuration?: number + lastTtftDuration?: number lastToolDuration?: number lastCost?: number lastDuration?: number