feat(search): per-phase timing instrumentation for the query pipeline

The eval harness already measures search-pipeline latency per phase,
but the *product* query() tool has no timing visibility. That leaves
production latency opaque:

 - Is BM25 the tail, or vector search?
 - How much Promise.all overlap do concurrent searches actually save?
 - Does symbol_lookup dominate when per-symbol Cypher round-trips pile up?

None of this is answerable from the outside, which blocks the
latency-quality Pareto work tracked in #546 / #553.

Changes:

* New PhaseTimer class at src/core/search/phase-timer.ts.
  Supports three APIs:
    - start(phase) / stop() for sequential phases (per issue spec)
    - mark(phase, durationMs) for pre-measured durations
    - time(phase, promise) to wrap a promise inside Promise.all

  The issue's original spec was sequential-only, which doesn't work
  for BM25 + vector inside Promise.all — the second start() would
  auto-stop the first and only one phase would get timed. The mark()
  and time() variants resolve that without changing the sequential
  API for the other phases.

* local-backend.ts query() instrumented across seven phase markers:
    bm25, vector   (concurrent via timer.time inside Promise.all)
    merge          (RRF reciprocal-rank-fusion)
    symbol_lookup  (per-symbol process + cohesion + content Cypher)
    ranking        (in-memory priority sort)
    formatting     (response object construction + dedup)
    wall           (end-to-end; separate mark so callers can compare
                   sum(phases) vs wall and see Promise.all savings)

* logQueryTiming() helper next to logQueryError(), same console-based
  pattern (repo has no structured logger). Emits
    GitNexus [query:timing] query="..." totalMs=N phases={...}
  to stdout — greppable prefix, JSON-parseable payload, no new deps.

* timing: Record<string, number> added as a top-level field on the
  query() response. Strict superset of the previous shape — existing
  tests only assert field presence, so no regression. Other MCP tools
  use the same top-level-metadata convention (status, row_count,
  warning) rather than a nested _meta wrapper.

Tests:

 - 6 new unit tests for PhaseTimer covering start/stop, implicit
   stop-on-start, additive mark(), Promise.all-safe time(),
   negative/NaN rejection, and totalMs auto-stop.
 - 3 new assertions on the existing query integration test verifying
   timing.wall is a non-negative number and at least one of
   bm25/vector fired.

Verification:
  npx vitest run test/unit/phase-timer.test.ts       -> 6 pass
  npx vitest run test/unit/calltool-dispatch.test.ts -> 65 pass
  npx vitest run test/integration/local-backend-calltool.test.ts -> 18 pass
  npm run test:unit                                   -> 3777 pass
    (4 pre-existing env failures unchanged: skip-git-cli needs
     built dist/, git-utils tmpdir on Windows worktree)
  npx tsc --noEmit                                    -> clean

Scope declined for v1:

 - In-process histogram aggregation — the log line is enough for
   external tooling
 - Pareto curve generation — issue asks to enable it, not generate it
 - Sub-phases of symbol_lookup (process vs cohesion vs content) —
   issue lists them under one bucket; can split later if demand surfaces

Closes #553

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<string, number> = 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<T>(phase: string, promise: Promise<T>): Promise<T> {
+    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<string, number> {
+    this.stop();
+    const out: Record<string, number> = {};
+    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;
+  }
+}

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<string, number>): 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<string, { score: number; data: any }>();
 
     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.',

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 () => {

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<void>((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);
+  });
+});