chore: log where each answer's time goes — rewrite, search, first token, total
Some checks failed
Forgejo Docker Build / Root app tests (push) Successful in 54s
Forgejo Docker Build / Build Docker image (push) Successful in 6s
Forgejo Docker Build / End-to-end (browser) (push) Failing after 18s

Numbers only, one line per streamed question, so "is the chat slow?" can be
answered from the log instead of from a feeling. Nothing about the request
is logged beyond the counts.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Dv6sqaY6Vq3ChZHMem3cnU
This commit is contained in:
Daniel 2026-09-13 05:51:04 +02:00
parent d94dc0e357
commit 9c2b067745

View file

@ -423,6 +423,7 @@ router.post('/clinical-assistant/chat/stream', async function(req, res) {
var toolset = assistantToolset(prepared);
if (prepared.delegateVision) sendEvent('status', { message: 'Looking at your image…' });
var firstTokenAt = 0;
var ai = await callAIStream(prepared.messages, assistantGenerationOptions({
model: prepared.chatModel || undefined,
temperature: 0.15,
@ -430,8 +431,13 @@ router.post('/clinical-assistant/chat/stream', async function(req, res) {
maxTokens: 2600,
images: toolset.images
}), function(delta) {
if (!firstTokenAt) firstTokenAt = Date.now();
sendEvent('token', { token: delta });
});
var t = prepared.timing || {};
console.info('[clinical-assistant] timing ms: rewrite=' + (t.rewriteMs || 0) + ' search=' + (t.searchMs || 0) +
' first_token=' + (firstTokenAt ? firstTokenAt - started : 0) + ' total=' + (Date.now() - started) +
' sources=' + (prepared.sources || []).length + ' model=' + (ai.model || prepared.chatModel || ''));
ai = await visionTool.dispatch(ai, {
images: prepared.images, visionModel: prepared.visionModel, callAI: callAI,
messages: prepared.messages,
@ -573,15 +579,22 @@ async function prepareAssistantChat(body) {
var includeContext = body.includeContext !== false;
var showSources = await showSourcesEnabled();
// Phase timings, numbers only, so "is it slow?" can be answered from the
// log rather than from a feeling: how long the rewrite took, how long the
// library search took, and (in the stream route) when the first token came.
var timing = { rewriteMs: 0, searchMs: 0 };
var phase = Date.now();
var searchQuery = await rewriteSearchQuery(message, history, chatModel).catch(function(e) {
console.warn('[clinical-assistant] query rewrite skipped:', e.message);
return message;
});
timing.rewriteMs = Date.now() - phase; phase = Date.now();
var searchResponse = await semanticSearch(searchQuery, {
limit: searchLimit,
includeContext: includeContext,
contextChars: contextChars
});
timing.searchMs = Date.now() - phase;
// Retrieval is text-only. The multimodal path called nc_multimodal_search
// against a second hardcoded collection with an embedding service that was
// never deployed, so it only ever logged "multimodal search skipped".
@ -592,7 +605,7 @@ async function prepareAssistantChat(body) {
var sources = dedupeSources(rawResults).slice(0, searchLimit);
if (sources.length === 0) {
return { direct: {
return { timing: timing, direct: {
success: true,
answer: 'I could not find a clear match for that question. Please try a more specific clinical term, diagnosis, medication, age group, or textbook topic.',
sources: [],
@ -603,6 +616,7 @@ async function prepareAssistantChat(body) {
var context = formatSourcesForPrompt(sources);
return {
timing: timing,
message: message,
showSources: showSources,
images: images,