Repository navigation
fix: count each API response once in speed and token metrics - #622
Conversation
…ent blocks A response is logged as one record per content block (thinking / text / tool_use) sharing a message id, so summing usage over every record counted one response once per block. Main transcripts repeat the same usage on each record; subagent transcripts repeat the input and zero the output until it settles. Across 41 real sessions this inflated output tokens 2.47x and input tokens 2.92x, over-reporting throughput by the same factor (408.2 t/s against a true 154.7 t/s on a 39 MB session). Count a message id's usage once, from its last record, which is the one carrying the response's final usage in both shapes. Earlier records keep contributing their intervals, so the active duration is unchanged. requestCount now counts responses rather than records. Records without a message id cannot be grouped and keep the previous one-record-per-request behaviour, so older transcripts are unaffected. The token widgets share this duplication through collectTokenMetricRecord; left for a separate change.
The token metrics carried the same duplication as the speed metrics: a response
is logged once per content block with its usage repeated on every record, and
collectTokenMetricRecord accumulated each one.
Its stop_reason guard is meant to skip intermediate streaming entries, but those
do not exist in main transcripts - Claude Code writes the records after the
response settled, so 4474 of 4477 records already carry the final truthy
stop_reason and the guard never fires. README.md has promised the deduped result
since v2.2.9 ("Streaming duplicate JSONL entries are deduped so token widgets do
not overcount").
Count a message id once instead, replacing an earlier record's share when a later
one arrives, since the record written last holds the response's final usage. That
map is reset together with the totals it describes, so no share can outlive them.
Entries without a message id keep the previous behaviour.
Across the 42 main transcripts this removes 2.79x of output tokens, 2.90x of
input tokens and 2.53x of cached tokens, while contextLength is untouched.
Merged from the jason/beta4-local-fixes Trellis build (compat-repair base): bounded stdin reads in shared hooks (sirmalloc#590), research dispatch may write the task research dir (sirmalloc#634), scoped archive commits (sirmalloc#622, sirmalloc#630), list filter traversal (sirmalloc#631), remove-subtask link check (sirmalloc#632), hooks.local.json ignore (sirmalloc#633).
|
In case it's useful: this looks like the same double-count tracked in #549, and a few other open PRs are working on it too: #591 and #595 cover both the token totals and the speed widgets like this one, #725 covers the token totals, #735 the speed widgets, and #587 includes its own version alongside its cost widgets. Comparing notes could make it easier to get one version landed. |
|
Small readability thought on |
…rds cover With a speed window set, fix/speed-metrics-transcripts keeps the share of a record's tokens that matches the share of its interval inside the window, and sirmalloc#622 counts each response once through its last record. Together, a response's share came from its last record's interval alone, which can cover only part of the time the response ran: - A response that runs tools in parallel logs a tool result between its records, so its last record's interval starts at that result and covers only the end of the response. A window holding that end kept all or most of the response's tokens against only part of its time. - A forked subagent's transcript opens with a copy of the response that spawned it. No user record comes before the copy there, so it has no interval, and as the response's last record it kept all of the response's tokens however little of the response the window held. A record's share now comes from its response's time: the union of the intervals of all of the response's records, in the main transcript and its subagent transcripts, including records logged before the window. A record with no interval takes the time of the response's other records, and a response without any interval keeps all its tokens as before. Records without a message id keep their own interval. The active duration is unchanged. Replaying 12 real transcripts at up to 2000 points each, 2.8% of the 30s-window renders with a speed read more than twice what that rule gives (10.6% on one transcript; worst 1349.1 t/s against 73.6), and 0.65% of the 120s-window renders. With this change every render matches it.
Preserve maximum-output accounting and context snapshots from sirmalloc#725 and sirmalloc#735 while deduplicating nonconsecutive message IDs. Keep independent timing intervals and subagent collectors, retain both sets of regression tests, and compute speed window bounds once.
Upstream: weekly limit timers (sirmalloc#768), prompt cache miss widgets (sirmalloc#770), context window size env override (sirmalloc#352, sirmalloc#407), windowed speed fixes (sirmalloc#769, sirmalloc#771), separator/renderer fixes (sirmalloc#773), custom-command styling (sirmalloc#775), clickable cwd links (sirmalloc#744), account email from live credentials (sirmalloc#724), cache timer reported expiry + short toggle (sirmalloc#576, sirmalloc#592), claude-status lock (sirmalloc#635, sirmalloc#772), dedup token metrics (sirmalloc#622, sirmalloc#725, sirmalloc#735). Not adopted: sirmalloc#765 terminal width from COLUMNS with fixed reserve - the fork keeps flexMode/compactThreshold and tmux pane priority. Hand edits outside conflicts: - README.md: kept fork Configure flex separator behavior bullet and older-updates details wrapper; dropped upstream Related Projects additions (claude-eta) - AGENTS.md: kept fork terminal width wording (sirmalloc#765 not adopted) - src/types/FlexMode.ts, src/tui/components/TerminalWidthMenu.tsx, src/tui/components/__tests__/TerminalWidthMenu.test.ts, src/tui/components/TerminalOptionsMenu.tsx, src/tui/components/__tests__/TerminalOptionsMenu.test.ts: restored, fork keeps terminal width settings - src/tui/App.tsx, src/tui/components/index.ts, src/types/index.ts: re-wired terminal width menu and FlexMode export - src/types/StatusJSON.ts: dropped fork duplicate prompt_cache key, upstream schema is a superset - src/utils/terminal.ts: COLUMNS source gated on non-tmux so tmux pane width keeps priority - src/widgets/WeeklyLimitTimer.ts, src/utils/usage-prefetch.ts, src/widgets/__tests__/WeeklyLimitTimer.test.ts: compat fix - fableUsage/fableResetAt -> weeklyFableUsage/weeklyFableResetAt - src/widgets/ApiUsage.tsx: compat fix - Context Bar honors effective context window (override, clamp, 1.0M format); Weekly renders a valid value despite a session error - src/widgets/__tests__/ApiUsage.localModelFallback.test.ts: output tokens no longer counted in context (upstream sirmalloc#730) - src/utils/__tests__/renderer-flex-width.test.ts, src/utils/__tests__/renderer-ansi.test.ts, src/utils/__tests__/gradient.test.ts, src/utils/__tests__/renderer-separator-collapse.test.ts, src/utils/__tests__/config.test.ts, src/tui/__tests__/App.test.ts: fork deviation - fork width model (flexMode, 6-column full reserve, kept settings, Terminal Width menu entry) - src/utils/__tests__/default-colors.test.ts: fork deviation - accept ansi256:/hex: defaults - src/utils/__tests__/usage-prefetch.test.ts: fork deviation - weekly usage comes from the API, fork widget imports from ApiUsage - src/widgets/__tests__/CurrentWorkingDir.test.ts, src/widgets/__tests__/CustomCommand.test.ts: Settings literal gains flexMode/compactThreshold - src/utils/__tests__/context-window.test.ts, src/utils/__tests__/jsonl-metrics.test.ts: restored fork tests upstream dropped - docs/test-retirements.md: ledger for the dev-reload snapshot-path and RemoteControlStatus glyph (sirmalloc#605) tests upstream replaced
Problem
Claude Code logs a single assistant response as one JSONL record per content
block (
thinking/text/tool_use). All of those records share amessage.id, and each repeats that response'susage. Because the records arewritten after the response settles, every one already carries the final usage
and the final
stop_reason.Both metric paths treated a record as a request, so each response was counted
once per block.
Measured over 42 real session transcripts:
outputTokensoutputTokensinputTokenscachedTokensReproduced end-to-end with a real status line (39 MB session, 713 records / 311
responses):
Note
README.mdhas promised the fixed behaviour since v2.2.9 — "Streamingduplicate JSONL entries are deduped so token widgets do not overcount live
Claude Code output" — but the existing guard only skips records whose
stop_reasonisnull, and no such record exists in a main transcript (4474 of4477 carry the final truthy value). This change makes that promise hold.
Fix
Count a
message.idonce, from its last record, which is the one holding theresponse's final usage. Verified on the corpus: in 2823 of 2823 multi-record
groups the last record carries the group's maximum output tokens.
buildSpeedMetrics): the token sum now runs over a set reduced toone request per message id.
accumulateTokenMetricEntry): a later record of the same message idreplaces that id's earlier share instead of adding to it.
Three deliberate non-changes:
[lastUserTimestamp → recordTimestamp]interval andmergeIntervalsunionsthem. Verified across 82 metric sets (41 sessions × {main, subagents} ×
{sessionAverage, 60/300/900s windows}): 0 duration differences.
contextLengthand themostRecent*/ post-compaction tracking are unchanged(they are max-by-timestamp, not sums) — 0 differences on the corpus.
message.idcannot be grouped and keep the previousone-record-per-request behaviour, so older transcripts are unaffected.
SpeedMetrics.requestCountnow counts distinct responses rather than records; ithas no non-test consumer.
Tests
Nine tests added; both fixture helpers gained an optional id field (omitting it
leaves existing fixtures byte-identical, so the 33 pre-existing cases in that file
behave identically).
Eight of the nine fail on
main; the ninth pins the invariant that theper-message-id map is reset together with the totals it describes (a build with a
stale map fails exactly that test and produces negative totals):
Full suite 2367 pass / 0 fail.
bun run lintandbun run buildclean.