perf: add first-turn timing diagnostics for new-tab sessions

CHANGELOG.md

@@ -38,6 +38,12 @@ version with its date and start a fresh empty `[Unreleased]` above it.
   startup instead of repeatedly blocking the interface, so vaults with
   hundreds of sessions no longer stall while Qoderian loads.
 
+- First-message latency diagnostics: sending the first message of a new tab
+  now logs per-stage timings to the developer console (filter by
+  `qoderian perf`), covering tab creation, title generation, runtime startup,
+  CLI cold-start, and the wait for the first response chunk — safe to paste
+  into bug reports about slow first replies.
+
 - The composer permission picker now mirrors New Qoder's three tiers —
   Ask approval, Auto approval, and Full access — and its labels and
   descriptions are localized across all ten supported locales instead of

src/core/diagnostics/performance.ts

@@ -1,10 +1,12 @@
 /**
- * Load-path timing diagnostics.
+ * Load-path and turn-path timing diagnostics.
  *
  * Startup work (session metadata reads, edition migration, index building,
- * tab restore, history hydration) grows with the number of stored sessions,
- * and regressions were invisible until the plugin felt slow. Each stage wraps
- * itself in `measureAsync` and logs its elapsed time; labels are stable phase
+ * tab restore, history hydration) and first-turn work (turn preparation,
+ * persistent-query spawn, CLI cold-start, first response chunk) grow with the
+ * number of stored sessions and external context, and regressions were
+ * invisible until the plugin felt slow. Each stage wraps itself in
+ * `measureAsync`/`measure` or logs via `logElapsed`; labels are stable phase
  * names without user data, so the lines are safe to share in bug reports.
  */
 
@@ -13,7 +15,22 @@ export async function measureAsync<T>(label: string, fn: () => Promise<T>): Prom
   try {
     return await fn();
   } finally {
-    const elapsedMs = Math.round((performance.now() - startedAt) * 10) / 10;
-    console.info(`[qoderian perf] ${label}: ${elapsedMs}ms`);
+    logElapsed(label, startedAt);
   }
 }
+
+/** Synchronous counterpart of `measureAsync` for CPU-bound stages. */
+export function measure<T>(label: string, fn: () => T): T {
+  const startedAt = performance.now();
+  try {
+    return fn();
+  } finally {
+    logElapsed(label, startedAt);
+  }
+}
+
+/** Logs the elapsed time since `startedAt` under a stable perf label. */
+export function logElapsed(label: string, startedAt: number): void {
+  const elapsedMs = Math.round((performance.now() - startedAt) * 10) / 10;
+  console.info(`[qoderian perf] ${label}: ${elapsedMs}ms`);
+}

src/features/chat/controllers/input-controller.ts

@@ -3,6 +3,11 @@ import { Notice } from 'obsidian';
 import { hasErrorContentBlock } from '../../../core/chat/error-blocks';
 import { detectBuiltInCommand } from '../../../core/commands/built-in-commands';
 import type { BrowserSelectionContext, CanvasSelectionContext } from '../../../core/context/types';
+import {
+  logElapsed,
+  measure,
+  measureAsync,
+} from '../../../core/diagnostics/performance';
 import type { EditorSelectionContext } from '../../../core/editor/editor-context';
 import type { ChatRuntime } from '../../../core/runtime/chat-runtime';
 import type { ApprovalCallbackOptions, ChatTurnRequest } from '../../../core/runtime/types';
@@ -277,13 +282,13 @@ export class InputController {
         displayContent: content,
         turnRequest: cloneChatTurnRequest(options.turnRequestOverride),
       }
-      : await this.buildTurnSubmission({
+      : await measureAsync('turn.buildSubmission', () => this.buildTurnSubmission({
         content,
         images: imagesForMessage,
         editorContextOverride: options?.editorContextOverride,
         browserContextOverride: options?.browserContextOverride,
         canvasContextOverride: options?.canvasContextOverride,
-      });
+      }));
     const { displayContent, turnRequest } = turnSubmission;
 
     fileContextManager?.markCurrentNoteSent();
@@ -300,7 +305,7 @@ export class InputController {
     state.hasPendingConversationSave = true;
     renderer.addMessage(userMsg);
 
-    await this.triggerTitleGeneration();
+    await measureAsync('turn.titleGeneration', () => this.triggerTitleGeneration());
 
     const assistantMsg: ChatMessage = {
       id: this.deps.generateId(),
@@ -325,6 +330,9 @@ export class InputController {
       isCompact ? 'qoderian-thinking--compact' : undefined,
     );
     state.responseStartTime = performance.now();
+    // Turn-level timing origin for the [qoderian perf] turn.* diagnostics.
+    const turnStartedAt = state.responseStartTime;
+    let sawFirstRuntimeChunk = false;
 
     let wasInterrupted = false;
     let wasInvalidated = false;
@@ -333,7 +341,7 @@ export class InputController {
 
     // Lazy initialization: ensure service is ready before first query
     if (this.deps.ensureServiceInitialized) {
-      const ready = await this.deps.ensureServiceInitialized();
+      const ready = await measureAsync('turn.serviceInit', () => this.deps.ensureServiceInitialized!());
       if (!ready) {
         new Notice('Failed to initialize agent service. Please try again.');
         streamController.hideThinkingIndicator();
@@ -376,7 +384,7 @@ export class InputController {
     }
 
     try {
-      const preparedTurn = agentService.prepareTurn(turnRequest);
+      const preparedTurn = measure('turn.prepareTurn', () => agentService.prepareTurn(turnRequest));
       userMsg.content = preparedTurn.persistedContent;
       userMsg.currentNote = preparedTurn.isCompact
         ? undefined
@@ -386,6 +394,10 @@ export class InputController {
       // This prevents duplication when rebuilding context for new sessions
       const previousMessages = state.messages.slice(0, -2);
       for await (const chunk of agentService.query(preparedTurn, previousMessages)) {
+        if (!sawFirstRuntimeChunk) {
+          sawFirstRuntimeChunk = true;
+          logElapsed('turn.firstChunk', turnStartedAt);
+        }
         if (state.streamGeneration !== streamGeneration) {
           wasInvalidated = true;
           break;
@@ -416,6 +428,7 @@ export class InputController {
         this.activeStreamingAssistantMessage ?? assistantMsg,
       );
     } finally {
+      logElapsed('turn.total', turnStartedAt);
       const finalAssistantMsg = this.activeStreamingAssistantMessage ?? assistantMsg;
       const turnMetadata = agentService.consumeTurnMetadata();
       userMsg.userMessageId = turnMetadata.userMessageId ?? userMsg.userMessageId;

src/features/chat/tabs/tab-manager.ts

@@ -94,6 +94,17 @@ export class TabManager implements TabManagerInterface {
     conversationId?: string | null,
     tabId?: TabId,
     options: CreateTabOptions = {},
+  ): Promise<TabData | null> {
+    return measureAsync(
+      this.isRestoringState ? 'tab.restore' : 'tab.create',
+      () => this.createTabInner(conversationId, tabId, options),
+    );
+  }
+
+  private async createTabInner(
+    conversationId?: string | null,
+    tabId?: TabId,
+    options: CreateTabOptions = {},
   ): Promise<TabData | null> {
     const maxTabs = this.getMaxTabs();
     if (this.tabs.size >= maxTabs) {
@@ -160,6 +171,10 @@ export class TabManager implements TabManagerInterface {
    * @param tabId The tab to switch to.
    */
   async switchToTab(tabId: TabId): Promise<void> {
+    return measureAsync('tab.switchTo', () => this.switchToTabInner(tabId));
+  }
+
+  private async switchToTabInner(tabId: TabId): Promise<void> {
     const tab = this.tabs.get(tabId);
     if (!tab) {
       return;

src/qoder/runtime/persistent-turn-stream.ts

@@ -1,5 +1,6 @@
 import type { SDKUserMessage } from '@qoder-ai/qoder-agent-sdk';
 
+import { logElapsed } from '../../core/diagnostics/performance';
 import type { StreamChunk } from '../../core/types';
 import type { QoderMessageChannel } from './qoder-message-channel';
 import { isSessionExpiredError } from './session-context';
@@ -26,9 +27,16 @@ export async function* streamPersistentTurn(
     error: null as Error | null,
   };
   const handlerId = `handler-${Date.now()}-${Math.random().toString(36).slice(2)}`;
+  const enqueuedAt = performance.now();
+  let sawFirstChunk = false;
   const handler = createResponseHandler({
     id: handlerId,
     onChunk: chunk => {
+      if (!sawFirstChunk) {
+        sawFirstChunk = true;
+        // Covers CLI cold-start when the persistent Query was just spawned.
+        logElapsed('turn.enqueueToFirstChunk', enqueuedAt);
+      }
       handler.markChunkSeen();
       if (state.resolveChunk) {
         state.resolveChunk(chunk);

src/qoder/runtime/qoder-chat-runtime.ts

@@ -23,6 +23,10 @@ import type {
 import { query as agentQuery } from '@qoder-ai/qoder-agent-sdk';
 import { Notice } from 'obsidian';
 
+import {
+  logElapsed,
+  measureAsync,
+} from '../../core/diagnostics/performance';
 import { getEnhancedPath, getMissingNodeError } from '../../core/env/environment';
 import { getVaultPath } from '../../core/fs/path';
 import type { ChatRuntime } from '../../core/runtime/chat-runtime';
@@ -145,6 +149,8 @@ export class QoderChatRuntime implements ChatRuntime {
   private persistentQuery: Query | null = null;
   private messageChannel: QoderMessageChannel | null = null;
   private queryAbortController: AbortController | null = null;
+  /** Set when the persistent Query is created; used to time CLI cold-start. */
+  private persistentQueryCreatedAt: number | null = null;
   private readonly responseRouter: QoderResponseRouter;
   private responseConsumerRunning = false;
   private responseConsumerPromise: Promise<void> | null = null;
@@ -419,10 +425,13 @@ export class QoderChatRuntime implements ChatRuntime {
       externalContextPaths
     );
 
+    const spawnStartedAt = performance.now();
     this.persistentQuery = agentQuery({
       prompt: this.messageChannel,
       options,
     });
+    logElapsed('runtime.spawnPersistentQuery', spawnStartedAt);
+    this.persistentQueryCreatedAt = performance.now();
 
     if (this.pendingResumeAt === resumeAtMessageId) {
       this.pendingResumeAt = undefined;
@@ -481,6 +490,7 @@ export class QoderChatRuntime implements ChatRuntime {
     this.persistentQuery = null;
     this.messageChannel = null;
     this.queryAbortController = null;
+    this.persistentQueryCreatedAt = null;
     this.responseConsumerRunning = false;
     this.responseConsumerPromise = null;
     this.currentConfig = null;
@@ -628,7 +638,15 @@ export class QoderChatRuntime implements ChatRuntime {
       if (!this.persistentQuery) return;
 
       try {
+        let sawFirstMessage = false;
         for await (const message of this.persistentQuery) {
+          if (!sawFirstMessage) {
+            sawFirstMessage = true;
+            if (this.persistentQueryCreatedAt !== null) {
+              // CLI cold-start: from Query creation to the first runtime message.
+              logElapsed('runtime.cliFirstMessage', this.persistentQueryCreatedAt);
+            }
+          }
           if (this.shuttingDown) break;
 
           await this.responseRouter.route(message);
@@ -946,7 +964,7 @@ export class QoderChatRuntime implements ChatRuntime {
     const savedPreapprovedTools = this.currentPreapprovedTools;
 
     // Apply dynamic updates before sending (Phase 1.6)
-    await this.applyDynamicUpdates(queryOptions);
+    await measureAsync('runtime.applyDynamicUpdates', () => this.applyDynamicUpdates(queryOptions));
 
     // Restore turn pre-approvals in case a dynamic update restarted the Query.
     this.currentPreapprovedTools = savedPreapprovedTools;

src/qoder/services/qoder-title-generation-service.ts

@@ -1,3 +1,4 @@
+import { measureAsync } from '../../core/diagnostics/performance';
 import type {
   TitleGenerationCallback,
   TitleGenerationResult,
@@ -36,15 +37,15 @@ export class QoderTitleGenerationService {
     const prompt = `User's request:\n"""\n${truncatedUser}\n"""\n\nGenerate a title for this conversation:`;
 
     try {
-      const result = await runColdStartQuery({
+      const result = await measureAsync('title.coldStartQuery', () => runColdStartQuery({
         plugin: this.plugin,
         systemPrompt: TITLE_GENERATION_SYSTEM_PROMPT,
         tools: [],
         model: this.resolveTitleModel(),
         thinking: { disabled: true },
         persistSession: false,
         abortController,
-      }, prompt);
+      }, prompt));
 
       const title = this.parseTitle(result.text);
       if (title) {

tests/unit/core/diagnostics/performance.test.ts

@@ -1,4 +1,8 @@
-import { measureAsync } from '@/core/diagnostics/performance';
+import {
+  logElapsed,
+  measure,
+  measureAsync,
+} from '@/core/diagnostics/performance';
 
 describe('measureAsync', () => {
   let infoSpy: jest.SpyInstance;
@@ -37,3 +41,60 @@ describe('measureAsync', () => {
     expect(infoSpy.mock.calls[0][0]).toMatch(/^\[qoderian perf\] stage\.failing: /);
   });
 });
+
+describe('measure', () => {
+  let infoSpy: jest.SpyInstance;
+
+  beforeEach(() => {
+    infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {});
+  });
+
+  afterEach(() => {
+    infoSpy.mockRestore();
+  });
+
+  it('returns the wrapped result unchanged', () => {
+    const result = measure('stage.sync', () => 42);
+    expect(result).toBe(42);
+  });
+
+  it('logs the label with an elapsed-time suffix', () => {
+    measure('stage.sync', () => undefined);
+
+    expect(infoSpy).toHaveBeenCalledTimes(1);
+    expect(infoSpy.mock.calls[0][0]).toMatch(/^\[qoderian perf\] stage\.sync: \d+(\.\d+)?ms$/);
+  });
+
+  it('logs timing and rethrows when the wrapped operation fails', () => {
+    const boom = new Error('boom');
+
+    expect(() =>
+      measure('stage.failing', () => {
+        throw boom;
+      })).toThrow(boom);
+
+    expect(infoSpy).toHaveBeenCalledTimes(1);
+    expect(infoSpy.mock.calls[0][0]).toMatch(/^\[qoderian perf\] stage\.failing: /);
+  });
+});
+
+describe('logElapsed', () => {
+  let infoSpy: jest.SpyInstance;
+
+  beforeEach(() => {
+    infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {});
+  });
+
+  afterEach(() => {
+    infoSpy.mockRestore();
+  });
+
+  it('logs the elapsed time since the given origin', () => {
+    const startedAt = performance.now();
+
+    logElapsed('turn.firstChunk', startedAt);
+
+    expect(infoSpy).toHaveBeenCalledTimes(1);
+    expect(infoSpy.mock.calls[0][0]).toMatch(/^\[qoderian perf\] turn\.firstChunk: \d+(\.\d+)?ms$/);
+  });
+});