mirror of
https://github.com/abhigyanpatwari/GitNexus.git
synced 2026-08-28 05:25:25 +00:00
ac148612ab
* 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() in63fbdc4used 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 in63fbdc4.
76 lines
2.3 KiB
TypeScript
76 lines
2.3 KiB
TypeScript
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);
|
|
});
|
|
});
|