feat: harden chat generation runtime instrumentation for billing#27451
feat: harden chat generation runtime instrumentation for billing#27451jaaydenh wants to merge 4 commits into
Conversation
chat_messages.runtime_ms is the billing source of truth for Coder Agents runtime, but it was built for debugging. Define the billable metric as the wall-clock duration of the model invocation that produced the persisted message content, and close the paths that dropped it: - Compaction summarization calls now record runtime on the compaction assistant message. - Interrupted attempts persist their episode's lifetime as runtime_ms on the partial assistant message committed by FinishInterruption. - Tool execution batches deliberately record no runtime: tool wall time includes idle waits such as wait_agent polling a sub-agent chat that already bills its own model invocations. - Failed model calls whose output is discarded bill nothing. Document the definition on chat_messages.runtime_ms (COMMENT ON COLUMN), PersistedStep.Runtime, the chatd architecture doc, and the Spend Management docs page. No new index: the existing idx_chat_messages_created_at already serves the hourly runtime range scan. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Docs previewCheck off each page once it's been reviewed. If a page changes in a later push, its checkbox clears automatically so it gets a fresh look. Pages not yet wired into the docs navigation aren't listed here. |
Tool execution publishes assistant-role file parts for attachments, so an interrupt landing between a tool batch and its commit could produce a file-only partial assistant message and attract the batch's episode span as runtime_ms. Gate the runtime attachment on the suffix containing model-streamed assistant content (text, reasoning, tool calls, sources). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…ation-time-instrumentation
|
/coder-agents-review model:moonshotai/kimi-k3 thinking:xhigh |
|
Chat: Review posted | View chat Review history
deep-review v0.9.0 | Round 1 | Last posted: Round 1, 8 findings (1 P2, 2 P3, 2 Nit, 3 Note), COMMENT. Review Finding inventoryFinding inventory - PR #27451Findings
Contested and acknowledgedNone this round. Round logRound 1Netero first pass (P3-and-below floor: one Note on the interrupt measurement window) then a 17-member panel (Bisky, Hisoka, Mafu-san, Mafuuu, Pariston, Gon, Leorio, Ging-Go, Komugi, Takumi, Meruem, Ryosuke, Knuckle, Melody, Chopper + wildcards Knov, Zoro). 1 P2, 3 P3, 4 Note, 2 Nit. Ging-Go, Leorio, Takumi, Knuckle reported no findings (all recorded positive verifications). Dominant convergent finding CRF-1 (7 reviewers, 2 at P2): interrupt path measures a wider window than the documented billable definition; orchestrator verified the CreateEpisode/stepStart ordering against the code. Reviewed against 9ce3664..f122655. About deep-reviewCRF = Coder Review Finding (P0-P4, Nit, Note)
|
There was a problem hiding this comment.
This is careful, honest instrumentation work. It turns runtime_ms from a debug field into a defined billing metric and documents that definition in four places that actually agree (the COMMENT ON COLUMN, the generated ChatMessage.RuntimeMs doc, PersistedStep.Runtime, and the docs page). It fixes a genuinely vacuous test (chatd_test.go previously read .Int64 without checking .Valid, so it passed on NULL). The anti-double-count exclusion of local tool time is real and structural, not just documented: the modelStreamedAssistant gate keeps an interrupted tool batch from attracting wall time, and it is tested. The migration is catalog-only (COMMENT ON COLUMN, no table rewrite), and the deliberate no-index decision is correct for an hour-wide created_at scan. Change is proportional and test-heavy (261 test lines to 114 production).
Severity count: 1 P2, 3 P3, 4 Note, 2 Nit. No P0/P1, so this is a COMMENT rather than a change request, but the P2 is worth resolving before this becomes the billing source of truth.
The one thing seven reviewers circled: the interrupt path measures a different span than the definition it bills against (CRF-1). Completed steps measure stream-open to stream-consumed; interrupted turns bill the whole episode lifetime, which starts at CreateEpisode (inside beginGenerationAttempt, after a DB transaction and before prompt preparation). I verified the ordering against the code. The result is a systematic over-count on interrupted turns, largest near the context limit where prompt prep is most expensive, which inverts the PR's own stated bias toward under-counting. Either narrow the billed span to the model-invocation window or narrow the documented definition to say interrupted partials bill episode lifetime; right now the code contradicts a definition it states in four places. As Hisoka put it: "I came for a double-count and found one boundary that lies."
Two items that need a human, not code:
-
CI: the PR ships with a red Flake Check (run 89211805277) that was not visibly run down. Prior project knowledge records the chatd Flake Check as a package-wide ~20m timeout under high
-count, and this PR adds five new tests to that same package, so "it's the known flake" is both the likely explanation and this PR's own contribution to it. Please run the failed job down and link the infra-timeout evidence or fix it, rather than merging on the assumption a red check is noise. (CRF-4) -
Product decision: billing compaction (system-initiated summarization) runtime is a decision about what the customer pays for, made here via instrumentation. It is defensible and documented, but worth a human ratifying that compaction time is billable rather than inheriting it silently. (CRF-6)
Ging-Go, Leorio, Takumi, and Knuckle each finished with no findings and recorded positive verifications (cross-goroutine timing holds under -race, the docs and error text match the code, the schema debt is clean).
coderd/x/chatd/message_conversion.go:204
P3 [CRF-3] No test pins the zero-runtime exclusion: a step with Runtime == 0 (a local tool-execution batch, the double-count exclusion the PR exists to define) is never asserted to persist RuntimeMs NULL on the assistant row. (Bisky)
Both assistantMessage (if step.Runtime > 0) and buildCompactionMessages (if input.compaction.Runtime > 0, line 323) guard the write, and both false branches are untested. TestBuildCommitStepMessages_LocalToolResultsBecomeToolMessages and TestBuildCompactionMessages_CompressedSummaryToolCallAndResult only ever pass 1500ms and assert Valid: true on the assistant row; the NULL checks they do carry are on other roles, not a zero-runtime assistant.
Bisky: "Drop either guard in a future refactor (e.g. always set RuntimeMs and let a zero-duration tool batch write runtime_ms = 0) and no test fails, yet the hourly billing sum now folds in rows the definition says must not count." One line to pin: reuse the LocalToolResults fixture with Runtime: 0 and assert require.False(t, got.Messages[0].RuntimeMs.Valid).
🤖
🤖 This review was automatically generated with Coder Agents.
| contentVersion: chatprompt.CurrentContentVersion, | ||
| logger: s.opts.Logger, | ||
| interruptedAt: s.opts.Clock.Now("chatworker", "interrupt"), | ||
| attemptRuntime: s.opts.MessagePartBuffer.EpisodeDuration(key), |
There was a problem hiding this comment.
P2 [CRF-1] Interrupted turns bill EpisodeDuration (CreateEpisode..CloseEpisode), a wider window than the documented billable definition, so interrupted turns over-count. (Hisoka P2, Ryosuke P2, Meruem P3, Mafuuu P3, Pariston P3, Melody P3, Knov P3)
The billable definition, stated on chat_messages.runtime_ms (migration 000551) and PersistedStep.Runtime, is "just before the provider stream is opened until it is fully consumed." Completed steps honor it exactly: stepStart := opts.Clock.Now() sits immediately before guardedStream and after prepareMessagesForRequest (chatloop.go:410, :390).
The interrupt path measures something else. attemptRuntime comes from EpisodeDuration, whose start createdAt is stamped in CreateEpisode, called inside beginGenerationAttempt after the RecordGenerationAttempt transaction commits and before GenerateAssistant runs prompt preparation. I verified this ordering against the code. Ryosuke: "for a turn interrupted mid-stream, runtime_ms is prompt-prep + debug-setup + partial-stream; the same turn allowed to complete would persist stream-only." closedAt is whichever of the generation goroutine's deferred close or the interrupt task's CloseEpisode wins the race, adding a scheduling-dependent tail.
Consequence: the billing source of truth over-counts on exactly the turns this PR adds coverage for, and the overcount scales with context size (prompt prep is largest near the context limit, where long turns are most likely to be interrupted). This inverts the PR's own stated bias toward under-counting. Magnitude is bounded and no reviewer benchmarked it, which is why this lands at P2 rather than P1, but the direction and the boundary mismatch are certain from the code.
Two clean resolutions: (a) give the interrupt path the model-invocation span (stamp the stream-open instant into the episode and bill from there to closedAt), or (b) narrow the documented definition to state that interrupted partials bill episode lifetime, so the four doc sites stop contradicting the code. Either closes the gap; the current state has the definition asserting one window while one writer uses another.
🤖
| s.logSkippedPart(buffered, "empty buffered assistant part type") | ||
| return | ||
| } | ||
| if part.Type != codersdk.ChatMessagePartTypeFile { |
There was a problem hiding this comment.
P3 [CRF-2] The modelStreamedAssistant billing gate encodes a load-bearing but unenforced invariant: "tool execution publishes only File assistant parts," with no guard test. (Meruem P3, Chopper Note, Mafu-san Note, Melody Note, Knov Note, Zoro Note)
The gate sets modelStreamedAssistant = true for every assistant part whose type is not File, on the premise that local tool execution's only assistant-role output is attachment file parts (publishToolAttachments, chatloop.go:1540). Melody enumerated the other side and confirmed it holds today: processStepStream publishes assistant text/reasoning/tool-call/source, tool results are role tool, and the only assistant File source is attachments.
But nothing mechanically protects it. Chopper traced the consequence: "If a future tool publishes a non-file assistant part (a status line, a synthetic text note), an interrupted tool-only batch would flip modelStreamedAssistant to true and attract EpisodeDuration as billable runtime, silently overcounting the exact tool wall time this PR set out to exclude." The drift would be invisible because no test asserts "a non-file assistant tool part must not be billed."
This is the safety half of the metric and it currently rests on a comment. Cheapest durable fix: a guard test that a non-file assistant part on the tool path does not attract runtime, and/or tag stream-origin on the buffered Part rather than inferring model origin from the absence of the File type. Rated alongside Bisky's untested-exclusion finding (CRF-3): both are missing coverage for a billing-critical exclusion.
🤖
| contentVersion: chatprompt.CurrentContentVersion, | ||
| logger: s.opts.Logger, | ||
| interruptedAt: s.opts.Clock.Now("chatworker", "interrupt"), | ||
| attemptRuntime: s.opts.MessagePartBuffer.EpisodeDuration(key), |
There was a problem hiding this comment.
Note [CRF-5] A race can drop interrupted-turn runtime entirely (undercount). (Komugi)
StartInterrupt calls CloseEpisode, which implicitly creates the episode when it does not exist yet, leaving createdAt zero. beginGenerationAttempt records the attempt in a committed DB transaction and only then calls CreateEpisode (generation.go:842-861), so an interrupt that reaches CloseEpisode in that window closes an implicitly-created episode; EpisodeDuration then returns 0 because createdAt.IsZero(), and no runtime_ms is persisted. The same happens if the episode was GC'd (15s after a normal close) before a late interrupt.
Safe in the common case: interruption targets active streaming, so parts already exist. The outcome is scheduling-dependent but bounded to undercounting on a rare turn, which matches the PR's stated "errs toward undercounting" stance, so no change is required. Noting it so the behavior is on record and not rediscovered as a billing discrepancy.
🤖
| // covering LLM streaming, tool execution, and retries. | ||
| // Zero indicates the duration was not measured (e.g. | ||
| // interrupted steps). | ||
| // Runtime is the wall-clock duration of the model invocation |
There was a problem hiding this comment.
Note [CRF-7] The billable runtime_ms definition is stated in four sites that can drift. (Gon)
The same definition lives in the migration COMMENT ON COLUMN (surfaced as the generated ChatMessage.RuntimeMs doc), PersistedStep.Runtime, and the docs page, with CompactionResult.Runtime pointing back at PersistedStep.Runtime (the right pattern). Nothing enforces the copies stay in sync, so a future change to the definition must touch all of them. The DB column comment is the natural source of truth if you want to designate one. Worth knowing rather than fixing.
🤖
| require.True(t, last.ContextLimit.Valid) | ||
| require.Equal(t, int64(4096), last.ContextLimit.Int64) | ||
| require.True(t, last.RuntimeMs.Valid) | ||
| require.GreaterOrEqual(t, last.RuntimeMs.Int64, int64(0)) |
There was a problem hiding this comment.
Note [CRF-8] require.GreaterOrEqual(t, last.RuntimeMs.Int64, int64(0)) is vacuous. (Komugi, Bisky)
RuntimeMs.Int64 is Runtime.Milliseconds() of a wall-clock span, which is never negative, so this assertion cannot fail regardless of behavior. The real guard is the require.True(t, last.RuntimeMs.Valid) this PR added just above it, which is the fix. Not harmful, but the line gives false confidence that a runtime magnitude is being checked; consider dropping it or asserting a meaningful lower bound.
🤖
| publishCompactionError(config, "failed to generate compaction summary") | ||
| return CompactionResult{}, err | ||
| } | ||
| runtime := clock.Since(summaryStart) |
There was a problem hiding this comment.
Nit [CRF-9] Local variable runtime shadows the stdlib runtime package name. (Gon)
The stdlib runtime package is not imported in this file today, so nothing breaks, but naming a local after a well-known package is a trap: any future runtime. reference in this scope would silently bind to the time.Duration. Rename to summaryRuntime to match the CompactionResult.Runtime field it feeds.
🤖
|
|
||
| assistantMsg := baseMessage(database.ChatMessageRoleAssistant, database.ChatMessageVisibilityUser, input.modelConfigID, contentVersion, assistantContent) | ||
| if input.compaction.Runtime > 0 { | ||
| assistantMsg.RuntimeMs = sql.NullInt64{Int64: input.compaction.Runtime.Milliseconds(), Valid: true} |
There was a problem hiding this comment.
Nit [CRF-10] The new RuntimeMs conversions open-code the guard-and-wrap instead of the existing nullInt64IfNonZero helper used for every other nullable numeric field in the same function. (Zoro)
stepMessage already converts its nullable int64 fields through nullInt64IfNonZero (message_conversion.go:186-191, helper at :226). The compaction site (+324) and interrupt site (+629) instead write sql.NullInt64{Int64: ..., Valid: true} behind a > 0 guard. Durations are never negative, so nullInt64IfNonZero(d.Milliseconds()) is equivalent and drops the surrounding if. Zoro: move the pre-existing step.Runtime conversion (:204-206) to the helper in the same pass so all four RuntimeMs writes read like the token fields above them.
🤖
Closes CODAGT-835
Summary
chat_messages.runtime_msbecomes the billing source of truth for Coder Agents runtime (summed hourly by #27312), but it was built for debugging: the June refactor (#26270) silently stopped recording tool-step runtime, compaction was never measured, and interrupted turns lost their partial runtime entirely. This PR defines the billable metric, closes the paths that dropped it, and documents the definition where the data lives.The billable definition
runtime_msis the wall-clock duration of the model invocation that produced the persisted message content, measured from just before the provider stream opens until it is fully consumed.What counts:
FinishInterruption, so partial generation time survives interruption (new; measured via a newBuffer.EpisodeDuration, which works even though the generation goroutine and the interrupt task are different tasks).What deliberately does not count (each is documented in code and docs):
wait_agentpolling a sub-agent chat that already bills its own model invocations; billing the batch would double count, and excluding one tool from a concurrent batch's wall time is ill-defined. Pre-refactor instrumentation did include tool time; this makes the exclusion an explicit product definition instead of a silent regression.FinishErrorinserts no rows today) and is a deliberate follow-up, not instrumentation drift.requires_action, queueing).The definition is documented as
COMMENT ON COLUMN chat_messages.runtime_ms(migration 000551, surfacing as a Go doc comment onChatMessage.RuntimeMs), onchatloop.PersistedStep.Runtime, in the chatd architecture doc, and in the Spend Management docs page.Index for the hourly scan
None needed:
GetTotalChatMessageRuntimeMsInRange(#27312) filters an hour-widecreated_atrange, which the existingidx_chat_messages_created_atb-tree already serves; the residualruntime_ms IS NOT NULLfilter applies to one hour of rows. A partial index would add permanent write amplification for a query that runs once an hour.Note
Migration 000551 is also claimed by #27312; whichever merges second renumbers via
fix_migration_numbers.sh.Tests
RuntimeMs.Validon the committed assistant row (it previously read.Int64without checking.Valid, so it passed on NULL).messagepartbuffer.EpisodeDurationunit coverage.Blocks: CODAGT-843 (B3), CODAGT-838 (D8).