Files
coder/coderd/x/chatd/chatloop/compaction_internal_test.go
T
4b7494be72 feat: harden chat generation runtime instrumentation for billing (#27451)
Closes CODAGT-835

## Summary

`chat_messages.runtime_ms` becomes 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_ms` is 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:

- Assistant generation steps, in top-level and sub-agent chats
(sub-agents are ordinary chats on the same generation path).
- Compaction summarization calls, persisted on the compaction assistant
message (**new**).
- Interrupted attempts: the message-part episode's lifetime is persisted
on the partial assistant message committed by `FinishInterruption`, so
partial generation time survives interruption (**new**; measured via a
new `Buffer.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):

- **Local tool execution.** Tool wall time includes idle waits, most
importantly `wait_agent` polling 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.
- **Failed model calls whose output is discarded** (retried attempts,
terminal errors, content-filter refusals). They persist no content, so
they bill nothing; billing errs toward undercounting. Notably a
stream-silence timeout can burn 10 idle minutes before a retry, which
should not be billable "active generation". If product later wants
failed attempts billed, that needs a place to persist runtime on error
turns (`FinishError` inserts no rows today) and is a deliberate
follow-up, not instrumentation drift.
- **Ancillary calls that produce no chat messages** (title generation,
advisor, turn summaries) and all idle/parked time (`requires_action`,
queueing).

The definition is documented as `COMMENT ON COLUMN
chat_messages.runtime_ms` (migration 000551, surfacing as a Go doc
comment on `ChatMessage.RuntimeMs`), on
`chatloop.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-wide `created_at` range, which the existing
`idx_chat_messages_created_at` b-tree already serves; the residual
`runtime_ms IS NOT NULL` filter 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

- End-to-end: the existing full-server generation test now asserts
`RuntimeMs.Valid` on the committed assistant row (it previously read
`.Int64` without checking `.Valid`, so it passed on NULL).
- Interrupted turn: full task-level test (real DB, mock clock) asserting
the partial assistant message persists the attempt's runtime.
- Errored stream: asserts a failed invocation yields no step and no
runtime.
- Tool-using turn: asserts runtime lands on the assistant row only and
tool rows stay NULL.
- Compaction: asserts the summarization call duration is recorded and
lands on the compaction assistant message only.
- `messagepartbuffer.EpisodeDuration` unit coverage.

Blocks: CODAGT-843 (B3), CODAGT-838 (D8).

---------

Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
Co-authored-by: Hugo Dutka <hugo@coder.com>
2026-08-06 16:09:38 +07:00

388 lines
12 KiB
Go

package chatloop
import (
"context"
"encoding/json"
"testing"
"time"
"charm.land/fantasy"
"github.com/google/uuid"
"github.com/sqlc-dev/pqtype"
"github.com/stretchr/testify/require"
"go.uber.org/mock/gomock"
"golang.org/x/xerrors"
"github.com/coder/coder/v2/coderd/database"
"github.com/coder/coder/v2/coderd/database/dbmock"
"github.com/coder/coder/v2/coderd/x/chatd/chatdebug"
"github.com/coder/coder/v2/coderd/x/chatd/chattest"
"github.com/coder/coder/v2/testutil"
"github.com/coder/quartz"
)
func TestStartCompactionDebugRun_DoesNotReportDebugErrors(t *testing.T) {
t.Parallel()
newParentContext := func(chatID uuid.UUID) context.Context {
return chatdebug.ContextWithRun(context.Background(), &chatdebug.RunContext{
RunID: uuid.New(),
ChatID: chatID,
RootChatID: uuid.New(),
ParentChatID: uuid.New(),
ModelConfigID: uuid.New(),
TriggerMessageID: 41,
HistoryTipMessageID: 42,
Kind: chatdebug.KindChatTurn,
Provider: "fake-provider",
Model: "fake-model",
})
}
t.Run("CreateRun", func(t *testing.T) {
t.Parallel()
ctrl := gomock.NewController(t)
db := dbmock.NewMockStore(ctrl)
svc := chatdebug.NewService(db, testutil.Logger(t), nil)
chatID := uuid.New()
reportedErr := make(chan error, 1)
db.EXPECT().InsertChatDebugRun(
gomock.Any(),
gomock.AssignableToTypeOf(database.InsertChatDebugRunParams{}),
).Return(database.ChatDebugRun{}, xerrors.New("insert compaction debug run"))
ctx := newParentContext(chatID)
compactionCtx, finish := startCompactionDebugRun(ctx, CompactionOptions{
DebugSvc: svc,
ChatID: chatID,
OnError: func(err error) {
reportedErr <- err
},
})
require.Same(t, ctx, compactionCtx)
finish(nil)
select {
case err := <-reportedErr:
t.Fatalf("unexpected OnError callback: %v", err)
default:
}
})
t.Run("FinalizeRunAggregatesSummary", func(t *testing.T) {
t.Parallel()
ctrl := gomock.NewController(t)
db := dbmock.NewMockStore(ctrl)
svc := chatdebug.NewService(db, testutil.Logger(t), nil)
chatID := uuid.New()
runID := uuid.New()
usageJSON, err := json.Marshal(fantasy.Usage{InputTokens: 7, OutputTokens: 3})
require.NoError(t, err)
attemptsJSON, err := json.Marshal([]chatdebug.Attempt{{
Status: "completed",
Method: "POST",
Path: "/v1/messages",
}})
require.NoError(t, err)
db.EXPECT().InsertChatDebugRun(
gomock.Any(),
gomock.AssignableToTypeOf(database.InsertChatDebugRunParams{}),
).Return(database.ChatDebugRun{ //nolint:exhaustruct // Test only needs IDs.
ID: runID,
ChatID: chatID,
}, nil)
db.EXPECT().GetChatDebugStepsByRunID(gomock.Any(), runID).Return([]database.ChatDebugStep{{
ID: uuid.New(),
RunID: runID,
ChatID: chatID,
Status: string(chatdebug.StatusCompleted),
Usage: pqtype.NullRawMessage{RawMessage: usageJSON, Valid: true},
Attempts: attemptsJSON,
}}, nil)
db.EXPECT().UpdateChatDebugRun(
gomock.Any(),
gomock.AssignableToTypeOf(database.UpdateChatDebugRunParams{}),
).DoAndReturn(func(_ context.Context, params database.UpdateChatDebugRunParams) (database.ChatDebugRun, error) {
require.Equal(t, chatID, params.ChatID)
require.Equal(t, runID, params.ID)
require.True(t, params.Summary.Valid)
require.JSONEq(t, `{"endpoint_label":"POST /v1/messages","step_count":1,"total_input_tokens":7,"total_output_tokens":3}`,
string(params.Summary.RawMessage))
return database.ChatDebugRun{ID: runID, ChatID: chatID}, nil
})
ctx := newParentContext(chatID)
compactionCtx, finish := startCompactionDebugRun(ctx, CompactionOptions{
DebugSvc: svc,
ChatID: chatID,
})
require.NotSame(t, ctx, compactionCtx)
finish(nil)
})
t.Run("FinalizeRun", func(t *testing.T) {
t.Parallel()
ctrl := gomock.NewController(t)
db := dbmock.NewMockStore(ctrl)
svc := chatdebug.NewService(db, testutil.Logger(t), nil)
chatID := uuid.New()
reportedErr := make(chan error, 1)
runID := uuid.New()
db.EXPECT().InsertChatDebugRun(
gomock.Any(),
gomock.AssignableToTypeOf(database.InsertChatDebugRunParams{}),
).Return(database.ChatDebugRun{ //nolint:exhaustruct // Test only needs IDs.
ID: runID,
ChatID: chatID,
}, nil)
db.EXPECT().GetChatDebugStepsByRunID(gomock.Any(), runID).Return(nil, xerrors.New("aggregate compaction debug run"))
db.EXPECT().UpdateChatDebugRun(
gomock.Any(),
gomock.AssignableToTypeOf(database.UpdateChatDebugRunParams{}),
).Return(database.ChatDebugRun{}, xerrors.New("finalize compaction debug run"))
ctx := newParentContext(chatID)
compactionCtx, finish := startCompactionDebugRun(ctx, CompactionOptions{
DebugSvc: svc,
ChatID: chatID,
OnError: func(err error) {
reportedErr <- err
},
})
require.NotSame(t, ctx, compactionCtx)
finish(nil)
select {
case err := <-reportedErr:
t.Fatalf("unexpected OnError callback: %v", err)
default:
}
})
}
// TestGenerateCompactionSummary_PanicFinalizesAsError verifies that a
// panic originating inside the model call during compaction is
// captured by the deferred debug-run finalizer so the run is recorded
// with StatusError rather than StatusCompleted. Without the recover
// hook the named `err` return is still nil when the defer fires and
// the row silently misclassifies the crash path.
func TestGenerateCompactionSummary_PanicFinalizesAsError(t *testing.T) {
t.Parallel()
ctrl := gomock.NewController(t)
db := dbmock.NewMockStore(ctrl)
svc := chatdebug.NewService(db, testutil.Logger(t), nil)
chatID := uuid.New()
runID := uuid.New()
status := make(chan string, 1)
db.EXPECT().InsertChatDebugRun(
gomock.Any(),
gomock.AssignableToTypeOf(database.InsertChatDebugRunParams{}),
).Return(database.ChatDebugRun{
ID: runID,
ChatID: chatID,
}, nil)
db.EXPECT().GetChatDebugStepsByRunID(gomock.Any(), runID).Return(nil, nil)
db.EXPECT().UpdateChatDebugRun(
gomock.Any(),
gomock.AssignableToTypeOf(database.UpdateChatDebugRunParams{}),
).DoAndReturn(func(_ context.Context, params database.UpdateChatDebugRunParams) (database.ChatDebugRun, error) {
status <- params.Status.String
return database.ChatDebugRun{ID: runID, ChatID: chatID}, nil
})
model := &chattest.FakeModel{
ProviderName: "fake",
GenerateFn: func(_ context.Context, _ fantasy.Call) (*fantasy.Response, error) {
panic("compaction model crash")
},
}
parentCtx := chatdebug.ContextWithRun(context.Background(), &chatdebug.RunContext{
RunID: uuid.New(),
ChatID: chatID,
ModelConfigID: uuid.New(),
TriggerMessageID: 1,
HistoryTipMessageID: 2,
Kind: chatdebug.KindChatTurn,
Provider: "fake",
Model: "fake-model",
})
require.PanicsWithValue(t, "compaction model crash", func() {
_, _ = generateCompactionSummary(parentCtx, model,
[]fantasy.Message{textMessage(fantasy.MessageRoleUser, "hello")},
CompactionOptions{
DebugSvc: svc,
ChatID: chatID,
SummaryPrompt: "summarize",
})
})
select {
case s := <-status:
require.Equal(t, string(chatdebug.StatusError), s,
"panic path must finalize the debug run with StatusError")
case <-time.After(testutil.WaitShort):
t.Fatal("FinalizeRun never reached UpdateChatDebugRun on panic")
}
}
func TestGenerateCompactionSummary_UsesCallerContext(t *testing.T) {
t.Parallel()
type contextKey string
testCtx := context.WithValue(context.Background(), contextKey("key"), "value")
var ctxSeen context.Context
model := &chattest.FakeModel{
ProviderName: "fake",
GenerateFn: func(ctx context.Context, _ fantasy.Call) (*fantasy.Response, error) {
ctxSeen = ctx
return &fantasy.Response{
Content: []fantasy.Content{
fantasy.TextContent{Text: "summary"},
},
}, nil
},
}
summary, err := generateCompactionSummary(testCtx, model,
[]fantasy.Message{textMessage(fantasy.MessageRoleUser, "hello")},
CompactionOptions{SummaryPrompt: "summarize"},
)
require.NoError(t, err)
require.Equal(t, "summary", summary)
require.Same(t, testCtx, ctxSeen)
require.NoError(t, ctxSeen.Err())
_, ok := ctxSeen.Deadline()
require.False(t, ok)
require.Equal(t, "value", ctxSeen.Value(contextKey("key")))
}
// TestGenerateCompaction_ForceBypassesThresholdGates verifies the
// manual-compaction contract: Force runs the summary even when usage
// is below threshold, when usage is zero, and when threshold=100
// disables automatic compaction; without Force those gates return an
// empty result without calling the model.
func TestGenerateCompaction_ForceBypassesThresholdGates(t *testing.T) {
t.Parallel()
newModel := func(calls *int) *chattest.FakeModel {
return &chattest.FakeModel{
ProviderName: "fake",
ModelName: "fake-model",
GenerateFn: func(_ context.Context, _ fantasy.Call) (*fantasy.Response, error) {
*calls++
return &fantasy.Response{
Content: []fantasy.Content{
fantasy.TextContent{Text: "forced summary"},
},
}, nil
},
}
}
messages := []fantasy.Message{textMessage(fantasy.MessageRoleUser, "hello")}
cases := []struct {
name string
opts GenerateCompactionOptions
}{
{
name: "below threshold",
opts: GenerateCompactionOptions{
ThresholdPercent: 70,
ContextLimit: 1000,
StepUsage: fantasy.Usage{InputTokens: 10},
},
},
{
name: "zero usage",
opts: GenerateCompactionOptions{
ThresholdPercent: 70,
ContextLimit: 1000,
},
},
{
name: "threshold disabled",
opts: GenerateCompactionOptions{
ThresholdPercent: 100,
ContextLimit: 1000,
StepUsage: fantasy.Usage{InputTokens: 10},
},
},
}
for _, tc := range cases {
t.Run(tc.name, func(t *testing.T) {
t.Parallel()
// Without Force the gate returns an empty result and
// never calls the model.
calls := 0
opts := tc.opts
opts.Model = newModel(&calls)
opts.Messages = messages
opts.Clock = quartz.NewMock(t)
result, err := GenerateCompaction(context.Background(), opts)
require.NoError(t, err)
require.Empty(t, result.SummaryReport)
require.Zero(t, calls, "gated run must not call the model")
// With Force the summary is generated and labeled manual.
opts.Force = true
opts.Source = CompactionSourceManual
result, err = GenerateCompaction(context.Background(), opts)
require.NoError(t, err)
require.Equal(t, "forced summary", result.SummaryReport)
require.Equal(t, CompactionSourceManual, result.Source)
require.Equal(t, 1, calls, "forced run calls the model once")
})
}
}
// TestGenerateCompaction_DefaultSourceAutomatic verifies an unforced
// over-threshold run reports the automatic source by default.
func TestGenerateCompaction_DefaultSourceAutomatic(t *testing.T) {
t.Parallel()
model := &chattest.FakeModel{
ProviderName: "fake",
ModelName: "fake-model",
GenerateFn: func(_ context.Context, _ fantasy.Call) (*fantasy.Response, error) {
return &fantasy.Response{
Content: []fantasy.Content{
fantasy.TextContent{Text: "auto summary"},
},
}, nil
},
}
result, err := GenerateCompaction(context.Background(), GenerateCompactionOptions{
Model: model,
Messages: []fantasy.Message{textMessage(fantasy.MessageRoleUser, "hello")},
ThresholdPercent: 70,
ContextLimit: 100,
StepUsage: fantasy.Usage{InputTokens: 90},
Clock: quartz.NewMock(t),
})
require.NoError(t, err)
require.Equal(t, "auto summary", result.SummaryReport)
require.Equal(t, CompactionSourceAutomatic, result.Source)
}
// TestGenerateCompaction_RequiresClock verifies a nil clock is
// rejected instead of silently falling back to a real clock; tests
// must supply their own.
func TestGenerateCompaction_RequiresClock(t *testing.T) {
t.Parallel()
_, err := GenerateCompaction(context.Background(), GenerateCompactionOptions{
Model: &chattest.FakeModel{ProviderName: "fake", ModelName: "fake-model"},
})
require.ErrorContains(t, err, "clock is required")
}