Fix: correct chat pipeline timing display (#21655)

internal/common/timer.go

@@ -135,16 +135,20 @@ func (t *Timer) MarshalJSON() ([]byte, error) {
 	return json.Marshal(t.Report())
 }
 
-// Markdown renders the Timer as a "## Time elapsed:" block matching
+// Markdown renders the Timer as a "## Time elapsed:" block.
 func (t *Timer) Markdown() string {
 	r := t.Report()
 	var b strings.Builder
 	b.WriteString("\n## Time elapsed:\n")
 	b.WriteString(fmt.Sprintf("  - Total: %.1fms\n", r.TotalMs))
+	var measuredMs float64
 	for _, p := range allPhases {
 		ms := r.PhasesMs[string(p)]
+		measuredMs += ms
 		b.WriteString(fmt.Sprintf("  - %s: %.1fms\n", displayName(p), ms))
 	}
+	// Nested or concurrent spans can exceed wall-clock time.
+	b.WriteString(fmt.Sprintf("  - Other: %.1fms\n", max(0, r.TotalMs-measuredMs)))
 	b.WriteString("\n")
 	return b.String()
 }

internal/common/timer_test.go

@@ -19,6 +19,7 @@ package common
 import (
 	"encoding/json"
 	"regexp"
+	"strconv"
 	"strings"
 	"sync"
 	"testing"
@@ -177,6 +178,8 @@ func TestTimer_Report(t *testing.T) {
 func TestTimer_Markdown(t *testing.T) {
 	tm := NewTimer()
 	tm.Start()
+	// Include preparation time outside the named phases.
+	tm.start = tm.start.Add(-10 * time.Millisecond)
 	tm.Enter(PhaseCheckLLM)
 	time.Sleep(2 * time.Millisecond)
 	tm.Exit(PhaseCheckLLM)
@@ -193,8 +196,8 @@ func TestTimer_Markdown(t *testing.T) {
 	if !strings.HasPrefix(md, "\n## Time elapsed:") {
 		t.Errorf("Markdown missing header: %q", md)
 	}
-	// Should contain all 6 phase labels
-	for _, label := range []string{"Check LLM", "Check Langfuse tracer", "Bind models", "Query refinement(LLM)", "Retrieval", "Generate answer", "Total"} {
+	// Should contain all phase labels and the unmeasured time.
+	for _, label := range []string{"Check LLM", "Check Langfuse tracer", "Bind models", "Query refinement(LLM)", "Retrieval", "Generate answer", "Other", "Total"} {
 		if !strings.Contains(md, label+":") {
 			t.Errorf("Markdown missing label %q: %q", label, md)
 		}
@@ -202,14 +205,27 @@ func TestTimer_Markdown(t *testing.T) {
 	// Phase durations should be numeric with "ms" suffix.
 	mdRE := regexp.MustCompile(`(?m)^\s*-\s+([A-Za-z ()\.]+):\s+([0-9.]+)ms$`)
 	matches := mdRE.FindAllStringSubmatch(md, -1)
-	if len(matches) < 7 {
-		t.Errorf("expected 7 phase lines, found %d in:\n%s", len(matches), md)
+	if len(matches) != 8 {
+		t.Errorf("expected 8 timing lines, found %d in:\n%s", len(matches), md)
 	}
-	// Total should be the sum-ish of the three measured phases.
-	totalRE := regexp.MustCompile(`Total:\s+([0-9.]+)ms`)
-	totalMatch := totalRE.FindStringSubmatch(md)
-	if len(totalMatch) < 2 {
-		t.Fatalf("Markdown missing Total line: %q", md)
+	var total, sum float64
+	for _, match := range matches {
+		ms, err := strconv.ParseFloat(match[2], 64)
+		if err != nil {
+			t.Fatalf("invalid timing %q: %v", match[2], err)
+		}
+		if match[1] == "Total" {
+			total = ms
+		} else {
+			sum += ms
+		}
+		if match[1] == "Other" && ms < 10 {
+			t.Errorf("Other = %.1fms, want at least 10ms of preparation time", ms)
+		}
+	}
+	// Each of the eight displayed values is rounded to 0.1ms.
+	if diff := total - sum; diff < -0.401 || diff > 0.401 {
+		t.Errorf("timing lines sum to %.1fms, want Total %.1fms within rounding precision", sum, total)
 	}
 }
 

internal/service/chat_pipeline.go

@@ -1285,6 +1285,7 @@ func (s *ChatPipelineService) AsyncChat(
 				})
 				return
 			}
+			timer.Exit(common.PhaseGenerateAnswer)
 
 			// Flush remaining state matching Python's final flush order
 			// (dialog_service.py:1601-1612): think_buffer → marker → answer_buffer → pending_after_close
@@ -1333,7 +1334,6 @@ func (s *ChatPipelineService) AsyncChat(
 			final := s.decorateAnswer(ctx, visibleAnswer, kbinfos, prompt, questions, usedTokenCount, timer, embModel, chat.VectorSimilarityWeight, quote, nil, langfuseTraceID, llmModelConfig, chat.TenantID, kbTenantIDStrings(kbs), len(knowledges) > 0)
 			final.Final = true
 			final.AudioBinary = nil
-			timer.Exit(common.PhaseGenerateAnswer)
 			send(final)
 		} else {
 			// Non-streaming: get the answer synchronously.
@@ -1350,6 +1350,7 @@ func (s *ChatPipelineService) AsyncChat(
 					answer = *resp.Answer
 				}
 			}
+			timer.Exit(common.PhaseGenerateAnswer)
 
 			if err != nil {
 				out <- AsyncChatResult{
@@ -1371,7 +1372,6 @@ func (s *ChatPipelineService) AsyncChat(
 			// Synthesize TTS for the full answer (non-stream, one-shot).
 			final := s.decorateAnswer(ctx, answer, kbinfos, prompt, questions, usedTokenCount, timer, embModel, chat.VectorSimilarityWeight, quote, ttsModel, langfuseTraceID, llmModelConfig, chat.TenantID, kbTenantIDStrings(kbs), len(knowledges) > 0)
 			final.Final = true
-			timer.Exit(common.PhaseGenerateAnswer)
 			out <- final
 		}
 		common.Info("AsyncChat completed", zap.String("chat_id", chat.ID))
@@ -3054,7 +3054,7 @@ func (s *ChatPipelineService) decorateAnswer(
 	finishChatTs := time.Now()
 
 	// Build timing stats.
-	// P1: emit Timer.Markdown() (6 phase lines + Total) and then the
+	// P1: emit Timer.Markdown() (phase lines, Other, and Total) and then the
 	// token-count / token-speed lines that the existing OpenAI endpoint
 	// already exposes. Total wall-clock is rounded to ms.
 	totalMs := timer.Total().Seconds() * 1000