From 765e99bb248faea20bf4b9e66e1c5ffc42a60fa2 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 18 Feb 2026 18:18:46 -0500 Subject: [PATCH] Fix duplicate message bug and add generation timing instrumentation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Bug fix: - ChatView.vue onMounted now skips fetchConversation when the conversation is already loaded in the store (same guard that the convId watcher uses). This prevents duplicate assistant messages when navigating from the dashboard inline chat to /chat/:id after streaming completes. Generation timing: - logging.py: add log_generation() — persists per-generation timing breakdown to app_logs (category=usage, action=generation) including model, total_ms, intent_ms, ttft_ms, generation_ms, and per-tool timings. Queryable via existing admin log viewer. - generation_task.py: collect wall-clock timestamps at every pipeline stage: intent classification, per-tool execution (both intent-routed and native), time-to-first-token (measured from generation start to first content chunk), LLM streaming round duration. Logs via log_generation() and includes timing in the SSE 'done' event payload. - types/chat.ts: add GenerationTiming interface; add optional timing field to Message. - chat.ts: capture timing from done event and attach to assistant message. - ChatMessage.vue: show timing footer on assistant messages with breakdown: "⏱ 4.2s total · first token 0.8s · analyzed 0.3s · created event 0.4s · generated 3.5s". Visible this session; persisted to app_logs for cross-session benchmarking. Co-Authored-By: Claude Sonnet 4.6 --- frontend/src/components/ChatMessage.vue | 48 ++++++++++++++++++- frontend/src/stores/chat.ts | 2 + frontend/src/types/chat.ts | 9 ++++ frontend/src/views/ChatView.vue | 2 +- .../services/generation_task.py | 34 ++++++++++++- src/fabledassistant/services/logging.py | 20 ++++++++ 6 files changed, 112 insertions(+), 3 deletions(-) diff --git a/frontend/src/components/ChatMessage.vue b/frontend/src/components/ChatMessage.vue index 78b7afe..9e0bb19 100644 --- a/frontend/src/components/ChatMessage.vue +++ b/frontend/src/components/ChatMessage.vue @@ -3,7 +3,7 @@ import { computed } from "vue"; import { renderMarkdown } from "@/utils/markdown"; import { useSettingsStore } from "@/stores/settings"; import ToolCallCard from "@/components/ToolCallCard.vue"; -import type { Message } from "@/types/chat"; +import type { GenerationTiming, Message } from "@/types/chat"; const settingsStore = useSettingsStore(); @@ -34,6 +34,26 @@ const roleLabel = computed(() => { return props.message.role; } }); + +function formatMs(ms: number | null | undefined): string { + if (ms == null) return ""; + if (ms < 1000) return `${ms}ms`; + return `${(ms / 1000).toFixed(1)}s`; +} + +const timingParts = computed((): string[] => { + const t = props.message.timing; + if (!t) return []; + const parts: string[] = []; + if (t.total_ms != null) parts.push(`${formatMs(t.total_ms)} total`); + if (t.ttft_ms != null) parts.push(`first token ${formatMs(t.ttft_ms)}`); + if (t.intent_ms != null) parts.push(`analyzed ${formatMs(t.intent_ms)}`); + for (const tool of t.tools ?? []) { + parts.push(`${tool.name.replace(/_/g, " ")} ${formatMs(tool.ms)}`); + } + if (t.generation_ms != null) parts.push(`generated ${formatMs(t.generation_ms)}`); + return parts; +}); @@ -193,4 +219,24 @@ const roleLabel = computed(() => { margin-top: 0.15rem; padding: 0 0.5rem; } +.message-timing { + display: flex; + flex-wrap: wrap; + align-items: center; + gap: 0.2rem; + padding: 0.1rem 0.5rem 0; + font-size: 0.68rem; + color: var(--color-text-muted); + opacity: 0.7; +} +.timing-icon { + font-size: 0.65rem; +} +.timing-part { + white-space: nowrap; +} +.timing-sep { + margin-right: 0.2rem; + opacity: 0.5; +} diff --git a/frontend/src/stores/chat.ts b/frontend/src/stores/chat.ts index 66dfc11..c5529e8 100644 --- a/frontend/src/stores/chat.ts +++ b/frontend/src/stores/chat.ts @@ -12,6 +12,7 @@ import type { Conversation, ConversationDetail, ContextMeta, + GenerationTiming, Message, OllamaStatus, SendMessageResponse, @@ -206,6 +207,7 @@ export const useChatStore = defineStore("chat", () => { ? [...streamingToolCalls.value] : null, created_at: new Date().toISOString(), + timing: event.data.timing as GenerationTiming | undefined, }; if (currentConversation.value?.id === convId) { currentConversation.value.messages.push(assistantMsg); diff --git a/frontend/src/types/chat.ts b/frontend/src/types/chat.ts index beb15f9..0f560c3 100644 --- a/frontend/src/types/chat.ts +++ b/frontend/src/types/chat.ts @@ -1,3 +1,11 @@ +export interface GenerationTiming { + total_ms: number; + intent_ms: number | null; + ttft_ms: number | null; + generation_ms: number | null; + tools: Array<{ name: string; ms: number }>; +} + export interface ToolCallRecord { function: string; arguments: Record; @@ -14,6 +22,7 @@ export interface Message { context_note_id: number | null; tool_calls?: ToolCallRecord[] | null; created_at: string; + timing?: GenerationTiming; } export interface SendMessageResponse { diff --git a/frontend/src/views/ChatView.vue b/frontend/src/views/ChatView.vue index 512e3f7..268e4a6 100644 --- a/frontend/src/views/ChatView.vue +++ b/frontend/src/views/ChatView.vue @@ -71,7 +71,7 @@ const inputPlaceholder = computed(() => { onMounted(async () => { document.addEventListener("keydown", onGlobalKeydown); await store.fetchConversations(); - if (convId.value) { + if (convId.value && store.currentConversation?.id !== convId.value) { await store.fetchConversation(convId.value); } nextTick(() => inputEl.value?.focus()); diff --git a/src/fabledassistant/services/generation_task.py b/src/fabledassistant/services/generation_task.py index ed6710f..780300b 100644 --- a/src/fabledassistant/services/generation_task.py +++ b/src/fabledassistant/services/generation_task.py @@ -19,6 +19,7 @@ from fabledassistant.services.generation_buffer import GenerationBuffer, Generat from fabledassistant.services.llm import ChatChunk, generate_completion, stream_chat, stream_chat_with_tools from fabledassistant.services.chat import update_conversation_title from fabledassistant.services.intent import classify_intent +from fabledassistant.services.logging import log_generation from fabledassistant.services.settings import get_setting from fabledassistant.services.tools import get_tools_for_user, execute_tool @@ -112,6 +113,15 @@ async def run_generation( # Emit context event buf.append_event("context", {"context": context_meta}) + t_start = time.monotonic() + timing: dict = { + "intent_ms": None, + "tools": [], + "ttft_ms": None, + "generation_ms": None, + "total_ms": None, + } + last_flush = time.monotonic() all_tool_calls: list[dict] = [] @@ -142,7 +152,9 @@ async def run_generation( if m.get("role") in ("user", "assistant") and m.get("content") ][-6:] buf.append_event("status", {"status": "Analyzing your request..."}) + t_intent = time.monotonic() intent = await classify_intent(user_content, tools, intent_model, history=intent_history) + timing["intent_ms"] = int((time.monotonic() - t_intent) * 1000) if intent.should_execute: logger.info( "Intent router detected tool (confidence=%s): %s(%s)", @@ -155,7 +167,9 @@ async def run_generation( ) if intent.should_execute: buf.append_event("status", {"status": f"{_TOOL_LABELS.get(intent.tool_name, 'Working')}..."}) + t_tool = time.monotonic() result = await execute_tool(user_id, intent.tool_name, intent.arguments) + timing["tools"].append({"name": intent.tool_name, "ms": int((time.monotonic() - t_tool) * 1000)}) logger.info("Intent-routed tool %s result: success=%s", intent.tool_name, result.get("success")) tool_record = { @@ -182,12 +196,15 @@ async def run_generation( continue # Next round: LLM streams response incorporating result buf.append_event("status", {"status": "Generating response..." if _round == 0 else "Composing response..."}) + t_stream = time.monotonic() async for chunk in stream_chat_with_tools(messages, model, tools=tools): if buf.cancel_event.is_set(): cancelled = True break if chunk.type == "content": + if timing["ttft_ms"] is None: + timing["ttft_ms"] = int((time.monotonic() - t_start) * 1000) buf.content_so_far += chunk.content # Filter out "[TOOL_CALLS]" marker from streaming output clean = _TOOL_CALL_MARKER.sub("", chunk.content) @@ -213,7 +230,9 @@ async def run_generation( logger.info("Executing tool: %s(%s)", tool_name, json.dumps(arguments)[:200]) buf.append_event("status", {"status": f"{_TOOL_LABELS.get(tool_name, 'Working')}..."}) + t_tool = time.monotonic() result = await execute_tool(user_id, tool_name, arguments) + timing["tools"].append({"name": tool_name, "ms": int((time.monotonic() - t_tool) * 1000)}) logger.info("Tool %s result: success=%s", tool_name, result.get("success")) tool_record = { @@ -228,6 +247,8 @@ async def run_generation( # Emit tool_call SSE event buf.append_event("tool_call", {"tool_call": tool_record}) + timing["generation_ms"] = int((time.monotonic() - t_stream) * 1000) + if cancelled: logger.info("Generation cancelled for conv %d", conv_id) break @@ -298,9 +319,20 @@ async def run_generation( fallback += "..." await update_conversation_title(user_id, conv_id, fallback) + timing["total_ms"] = int((time.monotonic() - t_start) * 1000) + logger.info( + "Generation timing for conv %d: total=%dms ttft=%s intent=%s tools=%s generation=%s", + conv_id, timing["total_ms"], timing["ttft_ms"], timing["intent_ms"], + [(t["name"], t["ms"]) for t in timing["tools"]], timing["generation_ms"], + ) + try: + await log_generation(user_id, conv_id, model, timing) + except Exception: + logger.warning("Failed to persist generation timing for conv %d", conv_id, exc_info=True) + buf.state = GenerationState.COMPLETED buf.finished_at = time.monotonic() - buf.append_event("done", {"done": True, "message_id": msg_id}) + buf.append_event("done", {"done": True, "message_id": msg_id, "timing": timing}) except Exception as e: logger.exception("Error in generation task for conversation %d", conv_id) diff --git a/src/fabledassistant/services/logging.py b/src/fabledassistant/services/logging.py index df8dac3..e7a07c0 100644 --- a/src/fabledassistant/services/logging.py +++ b/src/fabledassistant/services/logging.py @@ -59,6 +59,26 @@ async def log_usage( await session.commit() +async def log_generation( + user_id: int, + conv_id: int, + model: str, + timing: dict, +) -> None: + """Persist per-generation timing breakdown to app_logs for benchmarking.""" + async with async_session() as session: + log = AppLog( + category="usage", + user_id=user_id, + action="generation", + endpoint=f"/chat/conversations/{conv_id}", + duration_ms=timing.get("total_ms"), + details=json.dumps({"model": model, **timing}), + ) + session.add(log) + await session.commit() + + async def log_error( user_id: int | None = None, username: str | None = None,