bvandeusen/FabledScribe
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 50 Wiki Activity

Fix duplicate message bug and add generation timing instrumentation

Browse Source 
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 <noreply@anthropic.com>
This commit is contained in:
Bryan Van Deusen
2026-02-18 18:18:46 -05:00
parent fbce540638
commit 765e99bb24
6 changed files with 112 additions and 3 deletions
Download Patch File Download Diff File Expand all files Collapse all files
frontend/src/components/ChatMessage.vue
+47 -1
View File
@@ -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;
});
</script>
<template>
@@ -66,6 +86,12 @@ const roleLabel = computed(() => {
</div>
</div>
<span v-if="formattedTime" class="message-timestamp">{{ formattedTime }}</span>
<div v-if="timingParts.length" class="message-timing">
<span class="timing-icon">⏱</span>
<span v-for="(part, i) in timingParts" :key="i" class="timing-part">
<span v-if="i > 0" class="timing-sep">·</span>{{ part }}
</span>
</div>
</div>
</div>
</template>
@@ -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;
}
</style>
frontend/src/stores/chat.ts
+2
View File
@@ -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);
frontend/src/types/chat.ts
+9
View File
@@ -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<string, unknown>;
@@ -14,6 +22,7 @@ export interface Message {
context_note_id: number | null;
tool_calls?: ToolCallRecord[] | null;
created_at: string;
timing?: GenerationTiming;
}
export interface SendMessageResponse {
frontend/src/views/ChatView.vue
+1 -1
View File
@@ -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());
src/fabledassistant/services/generation_task.py
+33 -1
View File
@@ -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)
src/fabledassistant/services/logging.py
+20
View File
@@ -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,