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,