feat(store): track per-tool latency and end-to-end turn time

Alexey Panfilov · claude · Alexey Panfilov · commit 077d15dab83d · 2026-04-20T18:00:04.000+02:00
Add tool_call_log table (tool_name, latency_ms, success, error_text per
invocation) and turn_latency_ms column on usage_log (backfilled on the
final LLM call of each turn). Both SQLite and Postgres with idempotent
migrations.

Co-Authored-By: Claude Sonnet 4.6 &lt;noreply@anthropic.com&gt;
diff --git a/internal/agent/agent.go b/internal/agent/agent.go
@@ -118,6 +118,7 @@ func (a *Agent) TTSEnabled() bool {
 // Process runs the agentic loop. onToolCall is called before each tool execution (may be nil).
 func (a *Agent) Process(ctx context.Context, chatID int64, userMsg llm.Message, onToolCall func(toolName string)) (string, error) {
 	tr := newRequestTrace()
+	turnStart := time.Now()
 	queryText := messageText(userMsg)
 
 	// Store user message; embed it if semantic store + MCP embeddings are both available.
@@ -204,6 +205,7 @@ func (a *Agent) Process(ctx context.Context, chatID int64, userMsg llm.Message,
 			// Link the last usage_log row to this assistant message so analytics
 			// can pair cost/tokens with the actual reply the user saw.
 			a.backfillAssistantMsgID(ctx, lastUsageID, asstID)
+			a.backfillTurnLatency(lastUsageID, time.Since(turnStart))
 			// Cache only pure direct responses (first iteration, no tool calls).
 			if i == 0 {
 				a.cache.Set(chatID, queryEmb, resp.Content)
@@ -231,6 +233,7 @@ func (a *Agent) Process(ctx context.Context, chatID int64, userMsg llm.Message,
 // Tool-calling iterations remain synchronous. onChunk receives the accumulated text so far.
 func (a *Agent) ProcessStream(ctx context.Context, chatID int64, userMsg llm.Message, onToolCall func(string), onChunk func(accumulated string)) (string, error) {
 	tr := newRequestTrace()
+	turnStart := time.Now()
 	queryText := messageText(userMsg)
 
 	endEmbed := tr.begin("embed")
@@ -343,6 +346,7 @@ func (a *Agent) ProcessStream(ctx context.Context, chatID int64, userMsg llm.Mes
 		if len(toolCalls) == 0 {
 			asstID := a.store.AddMessage(chatID, llm.Message{Role: "assistant", Content: accumulated})
 			a.backfillAssistantMsgID(ctx, lastUsageID, asstID)
+			a.backfillTurnLatency(lastUsageID, time.Since(turnStart))
 			if i == 0 {
 				a.cache.Set(chatID, queryEmb, accumulated)
 			}
@@ -381,6 +385,13 @@ func (a *Agent) executeToolCalls(ctx context.Context, chatID int64, toolCalls []
 	results := make([]toolResult, len(toolCalls))
 	var wg sync.WaitGroup
 
+	meta, _ := llm.TurnMetaFrom(ctx)
+	var userMsgID *int64
+	if meta.UserMessageID != 0 {
+		id := meta.UserMessageID
+		userMsgID = &id
+	}
+
 	for i, tc := range toolCalls {
 		if onToolCall != nil {
 			onToolCall(tc.Name)
@@ -390,8 +401,12 @@ func (a *Agent) executeToolCalls(ctx context.Context, chatID int64, toolCalls []
 		wg.Add(1)
 		go func(idx int, tc llm.ToolCall) {
 			defer wg.Done()
+			toolStart := time.Now()
 			result, err := a.callTool(ctx, tc.Name, tc.Arguments)
+			elapsed := time.Since(toolStart)
+			errText := ""
 			if err != nil {
+				errText = err.Error()
 				a.logger.Warn("tool call failed", "tool", tc.Name, "err", err)
 				result = fmt.Sprintf("Error: %s", err.Error())
 			}
@@ -401,7 +416,19 @@ func (a *Agent) executeToolCalls(ctx context.Context, chatID int64, toolCalls []
 					result = summarized
 				}
 			}
-			a.logger.Info("tool result", "tool", tc.Name, "result_len", len(result))
+			a.logger.Info("tool result", "tool", tc.Name, "latency_ms", elapsed.Milliseconds(), "result_len", len(result))
+			if tcs, ok := a.store.(llm.ToolCallStore); ok {
+				writeCtx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
+				_ = tcs.PutToolCall(writeCtx, llm.ToolCallLog{
+					ChatID:    meta.ChatID,
+					UserMsgID: userMsgID,
+					ToolName:  tc.Name,
+					LatencyMs: int(elapsed.Milliseconds()),
+					Success:   err == nil,
+					ErrorText: errText,
+				})
+				cancel()
+			}
 			results[idx] = toolResult{tc: tc, result: result}
 		}(i, tc)
 	}
@@ -580,6 +607,23 @@ func (a *Agent) backfillAssistantMsgID(ctx context.Context, usageID, asstID int6
 	_ = ctx
 }
 
+// backfillTurnLatency records the end-to-end turn duration on the final usage_log row.
+// Best-effort: no-ops silently when the store doesn't support it or usageID is 0.
+func (a *Agent) backfillTurnLatency(usageID int64, elapsed time.Duration) {
+	if usageID == 0 {
+		return
+	}
+	us, ok := a.store.(llm.UsageStore)
+	if !ok {
+		return
+	}
+	writeCtx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
+	defer cancel()
+	if err := us.UpdateTurnLatencyMs(writeCtx, usageID, int(elapsed.Milliseconds())); err != nil {
+		a.logger.Warn("backfill turn_latency_ms failed", "err", err)
+	}
+}
+
 // storeUserMessage saves the user message. If the store and MCP client both support
 // embeddings, it also computes and stores the embedding for semantic history retrieval.
 // Returns the embedding (may be nil) and the inserted row's id (0 if the backend
diff --git a/internal/llm/usage.go b/internal/llm/usage.go
@@ -23,6 +23,7 @@ type UsageLog struct {
 	ReasoningTokens    int // for thinking-enabled models: tokens spent on internal reasoning (billed as completion but semantically distinct)
 	Cost               float64 // USD, authoritative per-request cost reported by the provider (OpenRouter's usage.cost). 0 when the provider doesn't surface this.
 	LatencyMs          int
+	TurnLatencyMs      int    // end-to-end turn time (user msg → final reply); only set on the last call of the turn
 	Success            bool
 	ErrorClass         string // "" / "rate_limit" / "5xx" / "network" / "timeout" / "other"
 	RequestID          string // provider's request id (e.g. OpenRouter gen-xxxxx) — useful for cross-referencing with provider dashboards
@@ -31,11 +32,29 @@ type UsageLog struct {
 	AssistantMessageID *int64 // FK to messages.id; NULL except on the final successful call of a turn
 }
 
+// ToolCallLog is a single MCP/built-in tool invocation record.
+type ToolCallLog struct {
+	ID        int64
+	Ts        time.Time
+	ChatID    int64
+	UserMsgID *int64 // FK to messages.id; matches the turn's user message
+	ToolName  string
+	LatencyMs int
+	Success   bool
+	ErrorText string
+}
+
+// ToolCallStore persists per-tool-call timing records.
+type ToolCallStore interface {
+	PutToolCall(ctx context.Context, t ToolCallLog) error
+}
+
 // UsageStore persists UsageLog records and exposes aggregation queries used
 // by the admin UI.
 type UsageStore interface {
 	PutUsage(ctx context.Context, u UsageLog) (int64, error)
 	UpdateAssistantMessageID(ctx context.Context, usageID, msgID int64) error
+	UpdateTurnLatencyMs(ctx context.Context, usageID int64, ms int) error
 
 	// Aggregations
 	UsageTotals(ctx context.Context, since time.Time) (UsageTotals, error)
diff --git a/internal/store/postgres.go b/internal/store/postgres.go
@@ -96,9 +96,21 @@ func (p *Postgres) migrate(ctx context.Context) error {
 			assistant_message_id BIGINT
 		)`,
 		`ALTER TABLE usage_log ADD COLUMN IF NOT EXISTS cost_usd DOUBLE PRECISION NOT NULL DEFAULT 0`,
+		`ALTER TABLE usage_log ADD COLUMN IF NOT EXISTS turn_latency_ms INTEGER NOT NULL DEFAULT 0`,
 		`CREATE INDEX IF NOT EXISTS idx_usage_ts_model ON usage_log(ts, model_id)`,
 		`CREATE INDEX IF NOT EXISTS idx_usage_chat_ts  ON usage_log(chat_id, ts)`,
 		`CREATE INDEX IF NOT EXISTS idx_usage_user_msg ON usage_log(user_message_id)`,
+		`CREATE TABLE IF NOT EXISTS tool_call_log (
+			id          BIGSERIAL PRIMARY KEY,
+			ts          TIMESTAMPTZ NOT NULL DEFAULT NOW(),
+			chat_id     BIGINT      NOT NULL DEFAULT 0,
+			user_msg_id BIGINT,
+			tool_name   TEXT        NOT NULL,
+			latency_ms  INTEGER     NOT NULL DEFAULT 0,
+			success     BOOLEAN     NOT NULL DEFAULT TRUE,
+			error_text  TEXT        NOT NULL DEFAULT ''
+		)`,
+		`CREATE INDEX IF NOT EXISTS idx_tool_call_chat_ts ON tool_call_log(chat_id, ts)`,
 	}
 	for _, s := range stmts {
 		if _, err := p.pool.Exec(ctx, s); err != nil {
@@ -652,13 +664,13 @@ func (p *Postgres) PutUsage(ctx context.Context, u llm.UsageLog) (int64, error)
 		INSERT INTO usage_log (
 			provider, model_id, role, chat_id,
 			prompt_tokens, completion_tokens, cached_prompt_tokens, reasoning_tokens,
-			cost_usd, latency_ms, success, error_class, request_id, tool_call_count,
+			cost_usd, latency_ms, turn_latency_ms, success, error_class, request_id, tool_call_count,
 			user_message_id, assistant_message_id
-		) VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16)
+		) VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17)
 		RETURNING id`,
 		u.Provider, u.ModelID, u.Role, u.ChatID,
 		u.PromptTokens, u.CompletionTokens, u.CachedPromptTokens, u.ReasoningTokens,
-		u.Cost, u.LatencyMs, u.Success, u.ErrorClass, u.RequestID, u.ToolCallCount,
+		u.Cost, u.LatencyMs, u.TurnLatencyMs, u.Success, u.ErrorClass, u.RequestID, u.ToolCallCount,
 		u.UserMessageID, u.AssistantMessageID,
 	).Scan(&id)
 	if err != nil {
@@ -676,6 +688,26 @@ func (p *Postgres) UpdateAssistantMessageID(ctx context.Context, usageID, msgID
 	return nil
 }
 
+func (p *Postgres) UpdateTurnLatencyMs(ctx context.Context, usageID int64, ms int) error {
+	_, err := p.pool.Exec(ctx,
+		`UPDATE usage_log SET turn_latency_ms = $1 WHERE id = $2`, ms, usageID)
+	if err != nil {
+		return fmt.Errorf("update usage turn_latency_ms: %w", err)
+	}
+	return nil
+}
+
+func (p *Postgres) PutToolCall(ctx context.Context, t llm.ToolCallLog) error {
+	_, err := p.pool.Exec(ctx, `
+		INSERT INTO tool_call_log (chat_id, user_msg_id, tool_name, latency_ms, success, error_text)
+		VALUES ($1, $2, $3, $4, $5, $6)`,
+		t.ChatID, t.UserMsgID, t.ToolName, t.LatencyMs, t.Success, t.ErrorText)
+	if err != nil {
+		return fmt.Errorf("put tool call: %w", err)
+	}
+	return nil
+}
+
 func (p *Postgres) UsageTotals(ctx context.Context, since time.Time) (llm.UsageTotals, error) {
 	var t llm.UsageTotals
 	err := p.pool.QueryRow(ctx, `
diff --git a/internal/store/sqlite.go b/internal/store/sqlite.go
@@ -66,6 +66,7 @@ CREATE TABLE IF NOT EXISTS usage_log (
     reasoning_tokens     INTEGER NOT NULL DEFAULT 0,
     cost_usd             REAL    NOT NULL DEFAULT 0,
     latency_ms           INTEGER NOT NULL DEFAULT 0,
+    turn_latency_ms      INTEGER NOT NULL DEFAULT 0,
     success              INTEGER NOT NULL DEFAULT 1,
     error_class          TEXT    NOT NULL DEFAULT '',
     request_id           TEXT    NOT NULL DEFAULT '',
@@ -76,6 +77,18 @@ CREATE TABLE IF NOT EXISTS usage_log (
 CREATE INDEX IF NOT EXISTS idx_usage_ts_model ON usage_log(ts, model_id);
 CREATE INDEX IF NOT EXISTS idx_usage_chat_ts  ON usage_log(chat_id, ts);
 CREATE INDEX IF NOT EXISTS idx_usage_user_msg ON usage_log(user_message_id);
+
+CREATE TABLE IF NOT EXISTS tool_call_log (
+    id           INTEGER PRIMARY KEY AUTOINCREMENT,
+    ts           DATETIME NOT NULL DEFAULT CURRENT_TIMESTAMP,
+    chat_id      INTEGER NOT NULL DEFAULT 0,
+    user_msg_id  INTEGER,
+    tool_name    TEXT    NOT NULL,
+    latency_ms   INTEGER NOT NULL DEFAULT 0,
+    success      INTEGER NOT NULL DEFAULT 1,
+    error_text   TEXT    NOT NULL DEFAULT ''
+);
+CREATE INDEX IF NOT EXISTS idx_tool_call_chat_ts ON tool_call_log(chat_id, ts);
 `
 
 const (
@@ -97,10 +110,11 @@ func NewSQLite(path string) (*SQLite, error) {
 		return nil, fmt.Errorf("init schema: %w", err)
 	}
 	// Migrations for existing databases
-	db.Exec(`ALTER TABLE messages ADD COLUMN parts TEXT`)                              //nolint:errcheck
-	db.Exec(`ALTER TABLE messages ADD COLUMN embedding BLOB`)                          //nolint:errcheck
-	db.Exec(`ALTER TABLE model_capabilities ADD COLUMN score REAL NOT NULL DEFAULT 0`) //nolint:errcheck
-	db.Exec(`ALTER TABLE usage_log ADD COLUMN cost_usd REAL NOT NULL DEFAULT 0`)       //nolint:errcheck
+	db.Exec(`ALTER TABLE messages ADD COLUMN parts TEXT`)                                        //nolint:errcheck
+	db.Exec(`ALTER TABLE messages ADD COLUMN embedding BLOB`)                                    //nolint:errcheck
+	db.Exec(`ALTER TABLE model_capabilities ADD COLUMN score REAL NOT NULL DEFAULT 0`)           //nolint:errcheck
+	db.Exec(`ALTER TABLE usage_log ADD COLUMN cost_usd REAL NOT NULL DEFAULT 0`)                 //nolint:errcheck
+	db.Exec(`ALTER TABLE usage_log ADD COLUMN turn_latency_ms INTEGER NOT NULL DEFAULT 0`)       //nolint:errcheck
 	return &SQLite{db: db}, nil
 }
 
@@ -720,12 +734,12 @@ func (s *SQLite) PutUsage(ctx context.Context, u llm.UsageLog) (int64, error) {
 		INSERT INTO usage_log (
 			provider, model_id, role, chat_id,
 			prompt_tokens, completion_tokens, cached_prompt_tokens, reasoning_tokens,
-			cost_usd, latency_ms, success, error_class, request_id, tool_call_count,
+			cost_usd, latency_ms, turn_latency_ms, success, error_class, request_id, tool_call_count,
 			user_message_id, assistant_message_id
-		) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)`,
+		) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)`,
 		u.Provider, u.ModelID, u.Role, u.ChatID,
 		u.PromptTokens, u.CompletionTokens, u.CachedPromptTokens, u.ReasoningTokens,
-		u.Cost, u.LatencyMs, boolToInt(u.Success), u.ErrorClass, u.RequestID, u.ToolCallCount,
+		u.Cost, u.LatencyMs, u.TurnLatencyMs, boolToInt(u.Success), u.ErrorClass, u.RequestID, u.ToolCallCount,
 		nullableInt64(u.UserMessageID), nullableInt64(u.AssistantMessageID))
 	if err != nil {
 		return 0, fmt.Errorf("put usage: %w", err)
@@ -742,6 +756,26 @@ func (s *SQLite) UpdateAssistantMessageID(ctx context.Context, usageID, msgID in
 	return nil
 }
 
+func (s *SQLite) UpdateTurnLatencyMs(ctx context.Context, usageID int64, ms int) error {
+	_, err := s.db.ExecContext(ctx,
+		`UPDATE usage_log SET turn_latency_ms = ? WHERE id = ?`, ms, usageID)
+	if err != nil {
+		return fmt.Errorf("update usage turn_latency_ms: %w", err)
+	}
+	return nil
+}
+
+func (s *SQLite) PutToolCall(ctx context.Context, t llm.ToolCallLog) error {
+	_, err := s.db.ExecContext(ctx, `
+		INSERT INTO tool_call_log (chat_id, user_msg_id, tool_name, latency_ms, success, error_text)
+		VALUES (?, ?, ?, ?, ?, ?)`,
+		t.ChatID, nullableInt64(t.UserMsgID), t.ToolName, t.LatencyMs, boolToInt(t.Success), t.ErrorText)
+	if err != nil {
+		return fmt.Errorf("put tool call: %w", err)
+	}
+	return nil
+}
+
 func (s *SQLite) UsageTotals(ctx context.Context, since time.Time) (llm.UsageTotals, error) {
 	var t llm.UsageTotals
 	err := s.db.QueryRowContext(ctx, `
