diff --git a/CHANGELOG.md b/CHANGELOG.md index 7b11f3a..9950399 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/src/core/diagnostics/performance.ts b/src/core/diagnostics/performance.ts index d1ffc5d..ff2105f 100644 --- a/src/core/diagnostics/performance.ts +++ b/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(label: string, fn: () => Promise): 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(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`); +} diff --git a/src/features/chat/controllers/input-controller.ts b/src/features/chat/controllers/input-controller.ts index 6fdfd80..673ff59 100644 --- a/src/features/chat/controllers/input-controller.ts +++ b/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; diff --git a/src/features/chat/tabs/tab-manager.ts b/src/features/chat/tabs/tab-manager.ts index 6137342..fcb548b 100644 --- a/src/features/chat/tabs/tab-manager.ts +++ b/src/features/chat/tabs/tab-manager.ts @@ -94,6 +94,17 @@ export class TabManager implements TabManagerInterface { conversationId?: string | null, tabId?: TabId, options: CreateTabOptions = {}, + ): Promise { + return measureAsync( + this.isRestoringState ? 'tab.restore' : 'tab.create', + () => this.createTabInner(conversationId, tabId, options), + ); + } + + private async createTabInner( + conversationId?: string | null, + tabId?: TabId, + options: CreateTabOptions = {}, ): Promise { 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 { + return measureAsync('tab.switchTo', () => this.switchToTabInner(tabId)); + } + + private async switchToTabInner(tabId: TabId): Promise { const tab = this.tabs.get(tabId); if (!tab) { return; diff --git a/src/qoder/runtime/persistent-turn-stream.ts b/src/qoder/runtime/persistent-turn-stream.ts index fff9132..71b038f 100644 --- a/src/qoder/runtime/persistent-turn-stream.ts +++ b/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); diff --git a/src/qoder/runtime/qoder-chat-runtime.ts b/src/qoder/runtime/qoder-chat-runtime.ts index bc6fc3b..08fd7b8 100644 --- a/src/qoder/runtime/qoder-chat-runtime.ts +++ b/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 | 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; diff --git a/src/qoder/services/qoder-title-generation-service.ts b/src/qoder/services/qoder-title-generation-service.ts index 262082a..9818169 100644 --- a/src/qoder/services/qoder-title-generation-service.ts +++ b/src/qoder/services/qoder-title-generation-service.ts @@ -1,3 +1,4 @@ +import { measureAsync } from '../../core/diagnostics/performance'; import type { TitleGenerationCallback, TitleGenerationResult, @@ -36,7 +37,7 @@ 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: [], @@ -44,7 +45,7 @@ export class QoderTitleGenerationService { thinking: { disabled: true }, persistSession: false, abortController, - }, prompt); + }, prompt)); const title = this.parseTitle(result.text); if (title) { diff --git a/tests/unit/core/diagnostics/performance.test.ts b/tests/unit/core/diagnostics/performance.test.ts index 3769f78..b8e66bb 100644 --- a/tests/unit/core/diagnostics/performance.test.ts +++ b/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$/); + }); +}); diff --git a/tests/unit/qoder/runtime/perf-instrumentation.test.ts b/tests/unit/qoder/runtime/perf-instrumentation.test.ts new file mode 100644 index 0000000..8575aee --- /dev/null +++ b/tests/unit/qoder/runtime/perf-instrumentation.test.ts @@ -0,0 +1,113 @@ +import * as sdkModule from '@qoder-ai/qoder-agent-sdk'; + +import type QoderianPlugin from '@/main'; +import type { McpServerManager } from '@/qoder/mcp/mcp-server-manager'; +import { QoderChatRuntime } from '@/qoder/runtime/qoder-chat-runtime'; +import { QoderTitleGenerationService } from '@/qoder/services/qoder-title-generation-service'; + +const sdkMock = sdkModule as unknown as { + setMockMessages: (messages: any[], options?: { appendResult?: boolean }) => void; + resetMockMessages: () => void; + query: typeof sdkModule.query; +}; + +type MockMcpServerManager = jest.Mocked; + +/** Extracts the label from a `[qoderian perf] label: 12.3ms` console line. */ +function perfLabel(line: string): string { + return line.replace(/^\[qoderian perf\] (\S+): .*$/, '$1'); +} + +describe('first-turn perf instrumentation', () => { + let mockPlugin: Partial; + let mockMcpManager: MockMcpServerManager; + let service: QoderChatRuntime; + let infoSpy: jest.SpyInstance; + let perfLines: string[]; + + beforeEach(() => { + jest.clearAllMocks(); + sdkMock.resetMockMessages(); + perfLines = []; + infoSpy = jest.spyOn(console, 'info').mockImplementation((...args: unknown[]) => { + const first = typeof args[0] === 'string' ? args[0] : ''; + if (first.startsWith('[qoderian perf] ')) perfLines.push(first); + }); + + mockPlugin = { + app: { + vault: { adapter: { basePath: '/mock/vault/path' } }, + }, + settings: { + model: 'qoder-3-5-sonnet', + permissionMode: 'ask' as const, + loadUserQoderSettings: false, + qoderCliPath: '/usr/local/bin/qoder', + }, + getResolvedQoderCliPath: jest.fn().mockReturnValue('/usr/local/bin/qoder'), + pluginManager: { + getPluginsKey: jest.fn().mockReturnValue(''), + }, + } as unknown as QoderianPlugin; + + mockMcpManager = { + loadServers: jest.fn().mockResolvedValue(undefined), + getAllDisallowedMcpTools: jest.fn().mockReturnValue([]), + getActiveServers: jest.fn().mockReturnValue({}), + getDisallowedMcpTools: jest.fn().mockReturnValue([]), + extractMentions: jest.fn().mockReturnValue(new Set()), + transformMentions: jest.fn().mockImplementation((text: string) => text), + } as unknown as MockMcpServerManager; + + service = new QoderChatRuntime(mockPlugin as QoderianPlugin, { + mcpManager: mockMcpManager, + pluginManager: (mockPlugin as any).pluginManager, + agentCatalog: { applySessionAgents: () => {} }, + }); + }); + + afterEach(() => { + infoSpy.mockRestore(); + }); + + it('logs each runtime stage of a fresh persistent-query turn', async () => { + // Message shape of a brand-new session: init, then the assistant reply. + sdkMock.setMockMessages([ + { type: 'system', subtype: 'init', session_id: 'perf-test-session' }, + { type: 'assistant', message: { content: [{ type: 'text', text: 'First reply!' }] } }, + ]); + + const turn = service.prepareTurn({ text: 'hello' }); + const chunks: any[] = []; + for await (const chunk of service.query(turn)) { + chunks.push(chunk); + } + expect(chunks.some(c => c.type === 'text')).toBe(true); + + const labels = perfLines.map(perfLabel); + expect(labels).toContain('runtime.spawnPersistentQuery'); + expect(labels).toContain('runtime.cliFirstMessage'); + expect(labels).toContain('runtime.applyDynamicUpdates'); + expect(labels).toContain('turn.enqueueToFirstChunk'); + + // The spawn log precedes the first response chunk timing. + expect(labels.indexOf('runtime.spawnPersistentQuery')) + .toBeLessThan(labels.indexOf('turn.enqueueToFirstChunk')); + + for (const line of perfLines) { + expect(line).toMatch(/^\[qoderian perf\] \S+: \d+(\.\d+)?ms$/); + } + }); + + it('logs the title-generation cold-start query separately', async () => { + sdkMock.setMockMessages([ + { type: 'system', subtype: 'init', session_id: 'title-session' }, + { type: 'assistant', message: { content: [{ type: 'text', text: 'A Nice Title' }] } }, + ]); + + const titleService = new QoderTitleGenerationService(mockPlugin as any); + await titleService.generateTitle('conv-1', 'How do I set up a project?', jest.fn()); + + expect(perfLines.map(perfLabel)).toContain('title.coldStartQuery'); + }); +});