1 commit

Author	SHA1	Message	Date
azizur100389	ac148612ab	feat(search): per-phase timing instrumentation for the query pipeline (#953) ... * 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 * fix(search): route query:timing log to stderr to preserve stdio MCP contract CI (#953) failed the `query: JSON appears on stdout, not stderr` e2e test in test/integration/cli-e2e.test.ts with: SyntaxError: Unexpected token 'G', "GitNexus [..." is not valid JSON Root cause: my initial logQueryTiming() in 63fbdc4 used console.log, which writes to stdout. The MCP stdio transport uses stdout exclusively for JSON-RPC responses (#324), and the CLI e2e test guards that contract by asserting stdout parses as JSON on every tool invocation. The "GitNexus [query:timing] ..." line was interleaving with the response JSON and breaking the parse. Fix: route logQueryTiming through console.error instead. stderr is the correct channel for human-readable diagnostics and it is what the sibling logQueryError already uses for the same reason. The log line format is otherwise unchanged -- still greppable, still JSON-parseable payload. Verification (local, with dist built): npx vitest run test/integration/cli-e2e.test.ts -t "query: JSON" -> now passes (was failing across ubuntu/windows/macos in CI) npx tsc --noEmit -> clean Two unrelated pre-existing failures on non-git directory handling remain (same on upstream/main). Closes the CI regression introduced in 63fbdc4.	2026-04-18 16:30:07 +01:00