diff --git a/gitnexus/src/core/search/phase-timer.ts b/gitnexus/src/core/search/phase-timer.ts new file mode 100644 index 000000000..3a6fd745a --- /dev/null +++ b/gitnexus/src/core/search/phase-timer.ts @@ -0,0 +1,108 @@ +/** + * Per-phase wall-clock timing for the search pipeline and similar + * multi-stage flows. Designed to be called from query() with minimal + * ceremony and negligible overhead (< 0.1 ms per phase recorded). + * + * ### Sequential usage + * + * ```ts + * const t = new PhaseTimer(); + * t.start('bm25'); await bm25Search(...); t.stop(); + * t.start('merge'); doMerge(); t.stop(); + * const phases = t.summary(); // { bm25: 42, merge: 3 } + * ``` + * + * ### Concurrent usage (Promise.all) + * + * `start`/`stop` assume a single active phase at a time, which is wrong + * for concurrent work inside `Promise.all` — the second `start` would + * auto-stop the first and only one of the two would get timed. Use + * {@link PhaseTimer.time} to wrap each concurrent promise instead: + * + * ```ts + * const [a, b] = await Promise.all([ + * t.time('bm25', bm25Search(...)), + * t.time('vector', semanticSearch(...)), + * ]); + * ``` + * + * ### Pre-measured durations + * + * ```ts + * t.mark('inherited', 12.5); + * ``` + */ +export class PhaseTimer { + private phases: Map = new Map(); + private current: string | null = null; + private t0 = 0; + + /** Start a new phase. Implicitly stops the previous one, if any. */ + start(phase: string): void { + this.stop(); + this.current = phase; + this.t0 = performance.now(); + } + + /** Stop the current phase. No-op if no phase is active. */ + stop(): void { + if (this.current !== null) { + const elapsed = performance.now() - this.t0; + this.phases.set(this.current, (this.phases.get(this.current) ?? 0) + elapsed); + this.current = null; + } + } + + /** + * Record a pre-measured duration without touching the active phase. + * Use for concurrent operations inside `Promise.all` where + * `start`/`stop` would step on each other, or for durations imported + * from sub-systems. Additive across repeated calls with the same + * phase name. Ignores negative / non-finite inputs. + */ + mark(phase: string, durationMs: number): void { + if (!Number.isFinite(durationMs) || durationMs < 0) return; + this.phases.set(phase, (this.phases.get(phase) ?? 0) + durationMs); + } + + /** + * Wrap a promise with automatic timing. Records wall time via + * {@link PhaseTimer.mark} regardless of which other phases are + * active — safe to use inside `Promise.all`. + */ + async time(phase: string, promise: Promise): Promise { + const t0 = performance.now(); + try { + return await promise; + } finally { + this.mark(phase, performance.now() - t0); + } + } + + /** + * Snapshot of accumulated durations rounded to 0.1 ms. Stops the + * current phase if one is still running. + */ + summary(): Record { + this.stop(); + const out: Record = {}; + for (const [k, v] of this.phases) out[k] = Math.round(v * 10) / 10; + return out; + } + + /** + * Sum of every recorded phase duration. + * + * Note: for phases recorded via {@link PhaseTimer.time} or + * {@link PhaseTimer.mark} this is the *sum*, not the wall time — + * concurrent work overlaps and the sum can exceed the end-to-end + * wall time. Record wall time separately with `mark('wall', …)` if + * that distinction matters. + */ + totalMs(): number { + this.stop(); + let t = 0; + for (const v of this.phases.values()) t += v; + return Math.round(t * 10) / 10; + } +} diff --git a/gitnexus/src/mcp/local/local-backend.ts b/gitnexus/src/mcp/local/local-backend.ts index ea0529540..2ca0a16e6 100644 --- a/gitnexus/src/mcp/local/local-backend.ts +++ b/gitnexus/src/mcp/local/local-backend.ts @@ -30,6 +30,7 @@ import { import { GroupService, type GroupToolPort } from '../../core/group/service.js'; import { collectBestChunks } from '../../core/embeddings/types.js'; import { EMBEDDING_TABLE_NAME, EMBEDDING_INDEX_NAME } from '../../core/lbug/schema.js'; +import { PhaseTimer } from '../../core/search/phase-timer.js'; // AI context generation is CLI-only (gitnexus analyze) // import { generateAIContextFiles } from '../../cli/ai-context.js'; @@ -156,6 +157,20 @@ function logQueryError(context: string, err: unknown): void { console.error(`GitNexus [${context}]: ${msg}`); } +/** + * Structured per-query latency log for production aggregation (#553). The + * `GitNexus [query:timing] …` prefix makes lines trivially greppable from + * stdout; the `phases` payload is JSON so log-scraping pipelines can parse + * it without custom format knowledge. + */ +function logQueryTiming(query: string, phases: Record): void { + const totalMs = phases.wall ?? Object.values(phases).reduce((a, b) => a + b, 0); + const truncated = query.length > 80 ? `${query.slice(0, 80)}…` : query; + console.log( + `GitNexus [query:timing] query=${JSON.stringify(truncated)} totalMs=${totalMs} phases=${JSON.stringify(phases)}`, + ); +} + export interface CodebaseContext { projectName: string; stats: { @@ -534,17 +549,29 @@ export class LocalBackend { const includeContent = params.include_content ?? false; const searchQuery = params.query.trim(); - // Step 1: Run hybrid search to get matching symbols + // Per-phase timing instrumentation (#553). Records wall time for each + // observable sub-step of the search pipeline so production latency can + // be aggregated offline for Pareto analysis and bottleneck detection. + // Overhead is <0.1 ms per phase; the timer is passive and never alters + // query behaviour. + const timer = new PhaseTimer(); + const wallStart = performance.now(); + + // Step 1: Run hybrid search to get matching symbols. BM25 and vector + // search run concurrently via Promise.all — use `timer.time()` for + // each so both get independent wall-time records without fighting + // over a single `current` phase slot. const searchLimit = processLimit * maxSymbolsPerProcess; // fetch enough raw results const [bm25SearchResult, semanticResults] = await Promise.all([ - this.bm25Search(repo, searchQuery, searchLimit), - this.semanticSearch(repo, searchQuery, searchLimit), + timer.time('bm25', this.bm25Search(repo, searchQuery, searchLimit)), + timer.time('vector', this.semanticSearch(repo, searchQuery, searchLimit)), ]); const bm25Results = bm25SearchResult.results; const ftsUsed = bm25SearchResult.ftsUsed; // Merge via reciprocal rank fusion + timer.start('merge'); const scoreMap = new Map(); for (let i = 0; i < bm25Results.length; i++) { @@ -574,8 +601,10 @@ export class LocalBackend { const merged = Array.from(scoreMap.entries()) .sort((a, b) => b[1].score - a[1].score) .slice(0, searchLimit); + timer.stop(); // merge // Step 2: For each match with a nodeId, trace to process(es) + timer.start('symbol_lookup'); const processMap = new Map< string, { @@ -708,7 +737,10 @@ export class LocalBackend { } } + timer.stop(); // symbol_lookup + // Step 3: Rank processes by aggregate score + internal cohesion boost + timer.start('ranking'); const rankedProcesses = Array.from(processMap.values()) .map((p) => ({ ...p, @@ -716,8 +748,10 @@ export class LocalBackend { })) .sort((a, b) => b.priority - a.priority) .slice(0, processLimit); + timer.stop(); // ranking // Step 4: Build response + timer.start('formatting'); const processes = rankedProcesses.map((p) => ({ id: p.id, summary: p.heuristicLabel || p.label, @@ -741,11 +775,20 @@ export class LocalBackend { seen.add(s.id); return true; }); + timer.stop(); // formatting + + // End-to-end wall time — deliberately a separate mark so callers can + // compare sum(phases) vs wall to see how much Promise.all concurrency + // saved. Must come before summary() so it's included. + timer.mark('wall', performance.now() - wallStart); + const timing = timer.summary(); + logQueryTiming(searchQuery, timing); return { processes, process_symbols: dedupedSymbols, definitions: definitions.slice(0, 20), // cap standalone definitions + timing, ...(!ftsUsed && { warning: 'FTS extension unavailable - keyword search degraded. Run: gitnexus analyze --force to rebuild indexes.', diff --git a/gitnexus/test/integration/local-backend-calltool.test.ts b/gitnexus/test/integration/local-backend-calltool.test.ts index 55e4110f3..b14106619 100644 --- a/gitnexus/test/integration/local-backend-calltool.test.ts +++ b/gitnexus/test/integration/local-backend-calltool.test.ts @@ -104,6 +104,14 @@ withTestLbugDB( (result.process_symbols?.length || 0) + (result.definitions?.length || 0); expect(totalResults).toBeGreaterThanOrEqual(1); + + // #553: query response carries per-phase timing metadata. + expect(result.timing).toBeDefined(); + expect(typeof result.timing.wall).toBe('number'); + expect(result.timing.wall).toBeGreaterThanOrEqual(0); + // At least one of the search phases must have fired for any + // non-error response — bm25 and/or vector always runs. + expect(result.timing.bm25 ?? result.timing.vector).toBeGreaterThanOrEqual(0); }); it('unknown tool throws', async () => { diff --git a/gitnexus/test/unit/phase-timer.test.ts b/gitnexus/test/unit/phase-timer.test.ts new file mode 100644 index 000000000..f606ffa7d --- /dev/null +++ b/gitnexus/test/unit/phase-timer.test.ts @@ -0,0 +1,76 @@ +import { describe, it, expect } from 'vitest'; +import { PhaseTimer } from '../../src/core/search/phase-timer.js'; + +const sleep = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms)); + +describe('PhaseTimer', () => { + it('start/stop records a single phase', async () => { + const t = new PhaseTimer(); + t.start('bm25'); + await sleep(20); + t.stop(); + + const phases = t.summary(); + expect(phases.bm25).toBeGreaterThanOrEqual(15); // allow a bit of scheduler slack + expect(Object.keys(phases)).toEqual(['bm25']); + }); + + it('start implicitly stops the previous phase', async () => { + const t = new PhaseTimer(); + t.start('a'); + await sleep(10); + t.start('b'); // auto-stops 'a' + await sleep(10); + t.stop(); + + const phases = t.summary(); + expect(phases.a).toBeGreaterThanOrEqual(5); + expect(phases.b).toBeGreaterThanOrEqual(5); + }); + + it('mark accumulates additive durations for the same phase', () => { + const t = new PhaseTimer(); + t.mark('x', 5); + t.mark('x', 3); + t.mark('y', 7); + + const phases = t.summary(); + expect(phases.x).toBe(8); + expect(phases.y).toBe(7); + }); + + it('time() records concurrent promises independently (Promise.all safe)', async () => { + const t = new PhaseTimer(); + await Promise.all([t.time('a', sleep(30)), t.time('b', sleep(80))]); + + const phases = t.summary(); + // Both phases recorded independently despite overlapping in time. + expect(phases.a).toBeGreaterThanOrEqual(25); + expect(phases.a).toBeLessThan(80); + expect(phases.b).toBeGreaterThanOrEqual(75); + }); + + it('mark rejects negative or non-finite durations', () => { + const t = new PhaseTimer(); + t.mark('x', -1); + t.mark('x', Number.NaN); + t.mark('x', Number.POSITIVE_INFINITY); + + const phases = t.summary(); + expect(phases.x).toBeUndefined(); + }); + + it('totalMs sums all phases and implicitly stops the active one', async () => { + const t = new PhaseTimer(); + t.mark('a', 10); + t.mark('b', 15); + t.start('c'); + await sleep(20); + // Call totalMs without stopping — it should stop 'c' implicitly. + const total = t.totalMs(); + + expect(total).toBeGreaterThanOrEqual(40); // 10 + 15 + ~20 + const phases = t.summary(); + expect(phases.c).toBeGreaterThanOrEqual(15); + }); +});