mirror of
https://github.com/coder/coder.git
synced 2026-09-22 05:05:20 +08:00
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>
388 lines
12 KiB
Go
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")
|
|
}
|