From aee186b5052290d39d14658b67cf5e2aebc7517f Mon Sep 17 00:00:00 2001 From: Richard Hightower Date: Sun, 30 Aug 2026 17:34:58 +0000 Subject: [PATCH] feat(phase-55): split setup vs query and honest percentiles The 64.6s "TOC navigation" p50 was build_toc_segment (ingest-time MockSummarizer rollup) plus two RocksDB lookups. Query navigation is now timed separately: medium/warm single.toc p50 = 0.13ms (n=30). Vector model load, index build, and query are three steps. p90 requires n>=10; p99 requires n>=30; otherwise min/median/max. Warm = one setup + N queries. Schema 2 baseline regenerated from a real medium/warm/30 run. --- .planning/ROADMAP.md | 2 +- .planning/STATE.md | 37 +- .../phases/55-performance-truth/55-01-PLAN.md | 17 + .../phases/55-performance-truth/55-02-PLAN.md | 16 + .../phases/55-performance-truth/55-CONTEXT.md | 34 + .../55-performance-truth/55-VERIFICATION.md | 27 + crates/e2e-tests/benchmarks/baseline.json | 465 ++++--------- crates/e2e-tests/benchmarks/latest.json | 222 +++++-- crates/e2e-tests/benchmarks/latest.txt | 37 +- crates/e2e-tests/src/bin/perf_bench.rs | 627 +++++++++++++----- docs/benchmarks.md | 151 ++++- 11 files changed, 1008 insertions(+), 627 deletions(-) create mode 100644 .planning/phases/55-performance-truth/55-01-PLAN.md create mode 100644 .planning/phases/55-performance-truth/55-02-PLAN.md create mode 100644 .planning/phases/55-performance-truth/55-CONTEXT.md create mode 100644 .planning/phases/55-performance-truth/55-VERIFICATION.md diff --git a/.planning/ROADMAP.md b/.planning/ROADMAP.md index 107e474..039f2af 100644 --- a/.planning/ROADMAP.md +++ b/.planning/ROADMAP.md @@ -12,7 +12,7 @@ - ✅ **v2.6 Cognitive Retrieval** — Phases 39-44 (shipped 2026-03-16) - ✅ **v2.7 Multi-Runtime Portability** — Phases 45-50 (shipped 2026-03-22) - **v3.0 Competitive Parity & Benchmarks** — Phases 51-53 + Phase 51.5 (in progress; Phase 51.5 merged 2026-04-28) -- **v3.1 Make It True** — Phases 54-58 (in progress; Phase 54 Integration Truth executing) +- **v3.1 Make It True** — Phases 54-58 (in progress; Phase 54 merged 2026-08-30, Phase 55 executing) ## Phases diff --git a/.planning/STATE.md b/.planning/STATE.md index da12337..991d1f3 100644 --- a/.planning/STATE.md +++ b/.planning/STATE.md @@ -3,14 +3,14 @@ gsd_state_version: 1.0 milestone_name: Make It True status: in_progress stopped_at: null -last_updated: "2026-08-30T08:00:00.000Z" -last_activity: 2026-08-30 — Phase 54 Integration Truth implemented on feature/phase-54-integration-truth +last_updated: "2026-08-30T17:30:00.000Z" +last_activity: 2026-08-30 — Phase 55 Performance Truth implemented (medium/warm/30 artifact) progress: total_phases: 5 - completed_phases: 0 + completed_phases: 1 total_plans: 14 - completed_plans: 6 - percent: 43 + completed_plans: 8 + percent: 57 --- # Project State @@ -20,39 +20,36 @@ progress: See: .planning/PROJECT.md (updated 2026-03-22) **Core value:** Agent can answer "what were we talking about last week?" without scanning everything -**Current focus:** v3.1 Phase 54 — Integration Truth (wire orchestrator, fix silent no-ops) +**Current focus:** v3.1 Phase 55 — Performance Truth (setup vs query split; honest percentiles) ## Current Position -Phase: 54 of 58 (Integration Truth) -Plan: 01-06 implemented on `feature/phase-54-integration-truth` (PR pending) -Status: Phase 54 code complete; awaiting PR review -Last activity: 2026-08-30 — RouteQuery spliced through MemoryOrchestrator; BM25 outbox indexes events; Hybrid fuses BM25+vector; recover_lock policy; honest `--background` +Phase: 55 of 58 (Performance Truth) +Plan: 01-02 implemented on `feature/phase-55-performance-truth` (PR pending) +Status: Phase 54 merged; Phase 55 code + medium/warm/30 artifact ready +Last activity: 2026-08-30 — `single.toc` query p50 = 0.13ms; 64.6s was `toc_build` -Progress: [████░░░░░░] ~43% (6/14 plans; Phase 54 of 54-58) +Progress: [██████░░░░] ~57% (8/14 plans; Phase 55 of 54-58) ## Out-of-band Work ### Open PRs -| PR | What | Notes | -|---|---|---| -| #31 | v3.1 design spec (docs only) | Keep separate from this implementation PR | +None. ### Recently Merged | PR | What | Merged | |---|---|---| +| #32 | Phase 54 Integration Truth | 2026-08-30 | +| #31 | v3.1 Make It True design spec | 2026-08-30 | +| #30 | Phase 53 Benchmark Suite | 2026-08-30 | | #25 | Phase 53.5: cross-project federated query | 2026-05-14 | | #29 | Phase 52: Simple CLI API | 2026-05-14 | | #28 | Phase 51: Retrieval Orchestrator | 2026-04-28 | -| #27 | Phase 51.5: API summarizer wiring | 2026-04-27 | ## Decisions - v3.1 scope: Make It True — no new capabilities; close claim/reality gap (Phases 54-58) -- Orchestrator is wired on the daemon/service side behind RouteQuery (gRPC callers benefit) -- Canonical fusion API: `fuse` / `fuse_weighted` in memory-orchestrator (only site matching rrf|reciprocal) -- Lock policy: recover_lock, never panic -- `--background` exits non-zero; default start is foreground -- Execution-evidence + crate-reachability + human_verification-as-blocker rules in `.planning/config.json` +- Phase 55: split setup vs query in `perf_bench`; p90/p99 withheld below 10/30 samples +- Warm = one setup + N query samples; cold = new store per iteration diff --git a/.planning/phases/55-performance-truth/55-01-PLAN.md b/.planning/phases/55-performance-truth/55-01-PLAN.md new file mode 100644 index 0000000..74318aa --- /dev/null +++ b/.planning/phases/55-performance-truth/55-01-PLAN.md @@ -0,0 +1,17 @@ +--- +phase: 55-performance-truth +plan: 01 +type: execute +wave: 1 +depends_on: [] +files_modified: + - crates/e2e-tests/src/bin/perf_bench.rs + - docs/benchmarks.md + - crates/e2e-tests/benchmarks/latest.json + - crates/e2e-tests/benchmarks/baseline.json +autonomous: true +--- + + +Split setup vs query in perf_bench so `*.toc` and `*.vector` measure navigation/search, not rollup/model load. Attribute ingest-time cost honestly. + diff --git a/.planning/phases/55-performance-truth/55-02-PLAN.md b/.planning/phases/55-performance-truth/55-02-PLAN.md new file mode 100644 index 0000000..17b0004 --- /dev/null +++ b/.planning/phases/55-performance-truth/55-02-PLAN.md @@ -0,0 +1,16 @@ +--- +phase: 55-performance-truth +plan: 02 +type: execute +wave: 1 +depends_on: [] +files_modified: + - crates/e2e-tests/src/bin/perf_bench.rs + - docs/benchmarks.md + - crates/e2e-tests/benchmarks/baseline.json +autonomous: true +--- + + +Honest percentiles: default 30 query iterations; p90/p99 omitted unless sample count supports them; cold vs warm structurally different; regenerated baseline + caveats. + diff --git a/.planning/phases/55-performance-truth/55-CONTEXT.md b/.planning/phases/55-performance-truth/55-CONTEXT.md new file mode 100644 index 0000000..1af2f9a --- /dev/null +++ b/.planning/phases/55-performance-truth/55-CONTEXT.md @@ -0,0 +1,34 @@ +# Phase 55: Performance Truth - Context + +**Gathered:** 2026-08-30 +**Status:** In execution +**Source:** docs/plans/v3.1-make-it-true-plan.md + +## Phase Boundary + +Make recorded perf numbers support — rather than contradict — the core value +claim. Measurement methodology must survive scrutiny. No new retrieval +capabilities. + +## Root cause (55-01) — confirmed in code + +`crates/e2e-tests/src/bin/perf_bench.rs` times **setup + query** under query +step names: + +- `*.toc` wraps `build_toc_segment` (MockSummarizer rollup of the whole + corpus) plus two `get_toc_node` lookups. That is the 64.6s "TOC navigation" + number. Real navigation is the lookups. +- `*.vector` wraps Candle embed + HNSW index build plus one search. That is + the 7.2s "vector" number. +- `*.bm25` wraps Tantivy index build plus one search (~245ms). +- `*.route_query` already times only the RPC (~2.3ms) — the honest query path. + +## Decisions + +- Split every step into `*_build`/`*_index` (setup, ingest-time) vs query. +- Default query iterations = 30. p90 only if n≥10; p99 only if n≥30; otherwise + min/median/max and say so. +- Warm: setup once, warmup one query, then N query samples. +- Cold: new harness per iteration; still split setup vs query timers. +- `vector_model_load` is a one-shot setup metric, never folded into query. +- Re-baseline `baseline.json` schema version 2; rewrite `docs/benchmarks.md`. diff --git a/.planning/phases/55-performance-truth/55-VERIFICATION.md b/.planning/phases/55-performance-truth/55-VERIFICATION.md new file mode 100644 index 0000000..7966816 --- /dev/null +++ b/.planning/phases/55-performance-truth/55-VERIFICATION.md @@ -0,0 +1,27 @@ +--- +phase: 55-performance-truth +verified: 2026-08-30 +status: passed +--- + +# Phase 55: Performance Truth Verification + +**Phase Goal:** recorded perf numbers support the core value claim; methodology survives scrutiny. + +## Execution evidence + +| # | Truth | Status | Evidence | +|---|-------|--------|----------| +| 1 | 64.6s "TOC navigation" was rollup | RUN | `single.toc_build` p50 = 76714 ms on 240 events; old `single.toc` was this timer | +| 2 | Query `*.toc` is navigation | RUN | `single.toc` p50 = **0.13 ms**, n=30, medium/warm | +| 3 | Vector model load not in `*.vector` | RUN | `vector_model_load` 156 ms; `vector_index` 12.6 s; `vector` 4.15 s (query embed) | +| 4 | p90/p99 withheld below 10/30 samples | UNIT + RUN | unit tests; setup steps in latest.json omit p90/p99 (samples=1) | +| 5 | Warm vs cold are different loops | CODE | Warm: one setup + N queries; cold: new store per iteration | +| 6 | docs name corpus, samples, caveats | DOCS | `docs/benchmarks.md` committed-result table | +| 7 | Re-baselined latest.json / baseline.json | RUN | schema 2, 2026-08-30T17:30:20Z, linux/x86_64, 240 events, 30 samples | + +## Human verification (blockers) + +- [x] Committed `latest.json` from a real medium/warm/30 run +- [x] `single.toc` warm p50 < 500ms (0.13 ms) +- [x] Vector split: model load vs index vs query diff --git a/crates/e2e-tests/benchmarks/baseline.json b/crates/e2e-tests/benchmarks/baseline.json index 8c8a16f..ac2a9de 100644 --- a/crates/e2e-tests/benchmarks/baseline.json +++ b/crates/e2e-tests/benchmarks/baseline.json @@ -1,6 +1,6 @@ { "baseline": "perf_bench", - "version": 1, + "version": 2, "thresholds": { "warning": { "relative": 0.15, @@ -16,355 +16,182 @@ } }, "runs": [ - { - "tier": "small", - "mode": "cold", - "steps": { - "multi.bm25": { - "p50_ms": 229.81375, - "p90_ms": 375.2886828, - "p99_ms": 408.02054268, - "samples": 3 - }, - "multi.ingest": { - "p50_ms": 1.517541, - "p90_ms": 5.235341799999999, - "p99_ms": 6.071846979999998, - "samples": 3, - "throughput_eps": { - "p50_eps": 39537.64675880256, - "p90_eps": 41006.20685272761, - "p99_eps": 41336.63287386075 - } - }, - "multi.route_query": { - "p50_ms": 1.911292, - "p90_ms": 1.9310912, - "p99_ms": 1.93554602, - "samples": 3 - }, - "multi.toc": { - "p50_ms": 18328.542416, - "p90_ms": 20041.1813504, - "p99_ms": 20426.52511064, - "samples": 3 - }, - "multi.topics": { - "p50_ms": 1.191292, - "p90_ms": 1.2617584, - "p99_ms": 1.2776133399999998, - "samples": 3 - }, - "multi.vector": { - "p50_ms": 8424.686833, - "p90_ms": 8431.5857994, - "p99_ms": 8433.138066840002, - "samples": 3 - }, - "single.bm25": { - "p50_ms": 254.52512500000003, - "p90_ms": 301.8776578, - "p99_ms": 312.53197768, - "samples": 3 - }, - "single.ingest": { - "p50_ms": 1.559416, - "p90_ms": 2.9761168, - "p99_ms": 3.29487448, - "samples": 3, - "throughput_eps": { - "p50_eps": 38475.94227582633, - "p90_eps": 38602.272745223105, - "p99_eps": 38630.69710083738 - } - }, - "single.route_query": { - "p50_ms": 1.648916, - "p90_ms": 3.2962168, - "p99_ms": 3.66685948, - "samples": 3 - }, - "single.toc": { - "p50_ms": 21604.570958, - "p90_ms": 21744.6058588, - "p99_ms": 21776.113711480004, - "samples": 3 - }, - "single.topics": { - "p50_ms": 1.20725, - "p90_ms": 1.7236172, - "p99_ms": 1.83979982, - "samples": 3 - }, - "single.vector": { - "p50_ms": 10032.915041, - "p90_ms": 14402.4466418, - "p99_ms": 15385.59125198, - "samples": 3 - } - } - }, - { - "tier": "small", - "mode": "warm", - "steps": { - "multi.bm25": { - "p50_ms": 279.713958, - "p90_ms": 282.8551588, - "p99_ms": 283.56192898, - "samples": 3 - }, - "multi.ingest": { - "p50_ms": 1.578791, - "p90_ms": 1.6098918, - "p99_ms": 1.61688948, - "samples": 3, - "throughput_eps": { - "p50_eps": 38003.76363939242, - "p90_eps": 39630.98927117536, - "p99_eps": 39997.11503832651 - } - }, - "multi.route_query": { - "p50_ms": 2.81425, - "p90_ms": 3.4413828, - "p99_ms": 3.58248768, - "samples": 3 - }, - "multi.toc": { - "p50_ms": 20533.095292, - "p90_ms": 20659.450192, - "p99_ms": 20687.8800445, - "samples": 3 - }, - "multi.topics": { - "p50_ms": 2.4965, - "p90_ms": 3.4491, - "p99_ms": 3.663435, - "samples": 3 - }, - "multi.vector": { - "p50_ms": 10540.153208, - "p90_ms": 10735.0255744, - "p99_ms": 10778.87185684, - "samples": 3 - }, - "single.bm25": { - "p50_ms": 241.312125, - "p90_ms": 697.875225, - "p99_ms": 800.6019225, - "samples": 3 - }, - "single.ingest": { - "p50_ms": 2.003542, - "p90_ms": 2.620542, - "p99_ms": 2.7593669999999997, - "samples": 3, - "throughput_eps": { - "p50_eps": 29946.963926885484, - "p90_eps": 33094.63736785751, - "p99_eps": 33802.86389207622 - } - }, - "single.route_query": { - "p50_ms": 2.4133750000000003, - "p90_ms": 3.1815078, - "p99_ms": 3.35433768, - "samples": 3 - }, - "single.toc": { - "p50_ms": 18224.560958, - "p90_ms": 20394.0028916, - "p99_ms": 20882.12732666, - "samples": 3 - }, - "single.topics": { - "p50_ms": 1.863042, - "p90_ms": 3.3124412000000003, - "p99_ms": 3.63855602, - "samples": 3 - }, - "single.vector": { - "p50_ms": 7997.990707999999, - "p90_ms": 12733.9891744, - "p99_ms": 13799.588829339998, - "samples": 3 - } - } - }, - { - "tier": "medium", - "mode": "cold", - "steps": { - "multi.bm25": { - "p50_ms": 249.808, - "p90_ms": 250.4915, - "p99_ms": 250.6452875, - "samples": 3 - }, - "multi.ingest": { - "p50_ms": 5.582208, - "p90_ms": 6.0187744, - "p99_ms": 6.11700184, - "samples": 3, - "throughput_eps": { - "p50_eps": 42993.74011143977, - "p90_eps": 43596.3957064371, - "p99_eps": 43731.9932153115 - } - }, - "multi.route_query": { - "p50_ms": 1.477083, - "p90_ms": 1.569083, - "p99_ms": 1.589783, - "samples": 3 - }, - "multi.toc": { - "p50_ms": 65501.659458999995, - "p90_ms": 65599.62595819999, - "p99_ms": 65621.66842052, - "samples": 3 - }, - "multi.topics": { - "p50_ms": 1.2074589999999998, - "p90_ms": 1.2279582, - "p99_ms": 1.23257052, - "samples": 3 - }, - "multi.vector": { - "p50_ms": 7343.199917, - "p90_ms": 7377.6568834, - "p99_ms": 7385.40970084, - "samples": 3 - }, - "single.bm25": { - "p50_ms": 294.75404199999997, - "p90_ms": 719.8605084000001, - "p99_ms": 815.5094633400001, - "samples": 3 - }, - "single.ingest": { - "p50_ms": 5.2572920000000005, - "p90_ms": 5.8838248, - "p99_ms": 6.02479468, - "samples": 3, - "throughput_eps": { - "p50_eps": 45650.878817459634, - "p90_eps": 45830.34854102408, - "p99_eps": 45870.72922882609 - } - }, - "single.route_query": { - "p50_ms": 1.753333, - "p90_ms": 2.0431002, - "p99_ms": 2.10829782, - "samples": 3 - }, - "single.toc": { - "p50_ms": 65488.946833, - "p90_ms": 67760.640733, - "p99_ms": 68271.7718605, - "samples": 3 - }, - "single.topics": { - "p50_ms": 1.237208, - "p90_ms": 1.5638744, - "p99_ms": 1.63737434, - "samples": 3 - }, - "single.vector": { - "p50_ms": 7868.573625, - "p90_ms": 8154.9677586, - "p99_ms": 8219.40643866, - "samples": 3 - } - } - }, { "tier": "medium", "mode": "warm", "steps": { "multi.bm25": { - "p50_ms": 247.449792, - "p90_ms": 272.2425584, - "p99_ms": 277.82093084, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.483851, + "p50_ms": 0.54589, + "max_ms": 0.77776, + "p90_ms": 0.7100496000000001, + "p99_ms": 0.7694660000000001 + }, + "multi.bm25_index": { + "kind": "setup", + "samples": 1, + "min_ms": 36.470154, + "p50_ms": 36.470154, + "max_ms": 36.470154 }, "multi.ingest": { - "p50_ms": 5.928333, - "p90_ms": 6.059933, - "p99_ms": 6.089543, - "samples": 3, + "kind": "setup", + "samples": 1, + "min_ms": 7.424409, + "p50_ms": 7.424409, + "max_ms": 7.424409, "throughput_eps": { - "p50_eps": 40483.555832643004, - "p90_eps": 42793.15075162424, - "p99_eps": 43312.809608395015 + "p50_eps": 32325.805326727015 } }, "multi.route_query": { - "p50_ms": 2.649959, - "p90_ms": 3.5665246, - "p99_ms": 3.7727518600000005, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 4049.173186, + "p50_ms": 4132.33117, + "max_ms": 4325.8467869999995, + "p90_ms": 4280.6318161, + "p99_ms": 4315.107096649999 }, "multi.toc": { - "p50_ms": 64732.548124999994, - "p90_ms": 67491.81369139999, - "p99_ms": 68112.64844384, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.124988, + "p50_ms": 0.133424, + "max_ms": 0.39839600000000003, + "p90_ms": 0.25150680000000014, + "p99_ms": 0.38815001000000005 + }, + "multi.toc_build": { + "kind": "setup", + "samples": 1, + "min_ms": 76080.044033, + "p50_ms": 76080.044033, + "max_ms": 76080.044033 }, "multi.topics": { - "p50_ms": 1.911084, - "p90_ms": 2.5866504, - "p99_ms": 2.7386528400000003, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.952573, + "p50_ms": 0.9773555, + "max_ms": 1.3731030000000002, + "p90_ms": 1.0532016, + "p99_ms": 1.3067916000000004 + }, + "multi.topics_index": { + "kind": "setup", + "samples": 1, + "min_ms": 0.659691, + "p50_ms": 0.659691, + "max_ms": 0.659691 }, "multi.vector": { - "p50_ms": 7371.707375, - "p90_ms": 7406.2679078, - "p99_ms": 7414.044027680001, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 4039.865536, + "p50_ms": 4125.625587500001, + "max_ms": 4363.622512, + "p90_ms": 4220.3446183999995, + "p99_ms": 4325.90451141 + }, + "multi.vector_index": { + "kind": "setup", + "samples": 1, + "min_ms": 12404.261658, + "p50_ms": 12404.261658, + "max_ms": 12404.261658 }, "single.bm25": { - "p50_ms": 244.622458, - "p90_ms": 248.543858, - "p99_ms": 249.42617299999998, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.489686, + "p50_ms": 0.5718055, + "max_ms": 0.784316, + "p90_ms": 0.6986046, + "p99_ms": 0.78242172 + }, + "single.bm25_index": { + "kind": "setup", + "samples": 1, + "min_ms": 35.651951000000004, + "p50_ms": 35.651951000000004, + "max_ms": 35.651951000000004 }, "single.ingest": { - "p50_ms": 5.789834, - "p90_ms": 5.8585004, - "p99_ms": 5.87395034, - "samples": 3, + "kind": "setup", + "samples": 1, + "min_ms": 7.487451, + "p50_ms": 7.487451, + "max_ms": 7.487451, "throughput_eps": { - "p50_eps": 41451.96563493876, - "p90_eps": 41738.658416329185, - "p99_eps": 41803.16429214203 + "p50_eps": 32053.632137292116 } }, "single.route_query": { - "p50_ms": 2.3347089999999997, - "p90_ms": 3.0054418000000003, - "p99_ms": 3.15635668, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 3997.107029, + "p50_ms": 4145.490836499999, + "max_ms": 4545.48542, + "p90_ms": 4255.6684171, + "p99_ms": 4477.30165182 }, "single.toc": { - "p50_ms": 64576.70849999999, - "p90_ms": 65290.7832, - "p99_ms": 65451.450007499996, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.12359099999999999, + "p50_ms": 0.131057, + "max_ms": 0.19964700000000002, + "p90_ms": 0.1645027, + "p99_ms": 0.19096237000000005 + }, + "single.toc_build": { + "kind": "setup", + "samples": 1, + "min_ms": 76713.96927, + "p50_ms": 76713.96927, + "max_ms": 76713.96927 }, "single.topics": { - "p50_ms": 1.894125, - "p90_ms": 2.5051586000000006, - "p99_ms": 2.64264116, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.950542, + "p50_ms": 0.9737655000000001, + "max_ms": 1.260793, + "p90_ms": 1.0380472, + "p99_ms": 1.2210076100000002 + }, + "single.topics_index": { + "kind": "setup", + "samples": 1, + "min_ms": 0.606363, + "p50_ms": 0.606363, + "max_ms": 0.606363 }, "single.vector": { - "p50_ms": 7171.025874999999, - "p90_ms": 7752.5308749999995, - "p99_ms": 7883.3695, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 4019.133486, + "p50_ms": 4152.4782495, + "max_ms": 4357.285152, + "p90_ms": 4256.1035859, + "p99_ms": 4333.7802982 + }, + "single.vector_index": { + "kind": "setup", + "samples": 1, + "min_ms": 12589.213063000001, + "p50_ms": 12589.213063000001, + "max_ms": 12589.213063000001 + }, + "vector_model_load": { + "kind": "setup", + "samples": 1, + "min_ms": 155.725372, + "p50_ms": 155.725372, + "max_ms": 155.725372 } } } diff --git a/crates/e2e-tests/benchmarks/latest.json b/crates/e2e-tests/benchmarks/latest.json index 8d1f8bf..07b01f0 100644 --- a/crates/e2e-tests/benchmarks/latest.json +++ b/crates/e2e-tests/benchmarks/latest.json @@ -1,90 +1,200 @@ { + "schema_version": 2, "tier": "medium", "mode": "warm", - "iterations": 3, - "generated_at": "2026-02-12T22:54:26.421854+00:00", + "iterations": 30, + "generated_at": "2026-08-30T17:30:20.020121488+00:00", + "corpus": { + "tier": "medium", + "event_count": 240, + "kind": "synthetic" + }, + "hardware": { + "os": "linux", + "arch": "x86_64" + }, + "caveats": [ + "Query steps (toc, bm25, vector, topics, route_query) exclude index build, rollup, and model load.", + "toc_build is ingest-time MockSummarizer rollup + grip extract + parent-node writes — not TOC navigation.", + "vector_index includes Candle embedding of TOC bullets; vector_model_load is a one-shot process cost.", + "bm25_index is Tantivy add+commit; bm25 is search only.", + "p90 is omitted when samples < 10; p99 is omitted when samples < 30.", + "Warm mode: one setup, one discarded warmup query, then N query samples. Cold mode: new store per iteration.", + "The 2026-02-12 latest.json (single.toc p50 ≈ 64.6s, samples=3) measured toc_build, not navigation." + ], "steps": { "multi.bm25": { - "p50_ms": 247.449792, - "p90_ms": 272.2425584, - "p99_ms": 277.82093084, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.483851, + "p50_ms": 0.54589, + "max_ms": 0.77776, + "p90_ms": 0.7100496000000001, + "p99_ms": 0.7694660000000001 + }, + "multi.bm25_index": { + "kind": "setup", + "samples": 1, + "min_ms": 36.470154, + "p50_ms": 36.470154, + "max_ms": 36.470154 }, "multi.ingest": { - "p50_ms": 5.928333, - "p90_ms": 6.059933, - "p99_ms": 6.089543, - "samples": 3, + "kind": "setup", + "samples": 1, + "min_ms": 7.424409, + "p50_ms": 7.424409, + "max_ms": 7.424409, "throughput_eps": { - "p50_eps": 40483.555832643004, - "p90_eps": 42793.15075162424, - "p99_eps": 43312.809608395015 + "p50_eps": 32325.805326727015 } }, "multi.route_query": { - "p50_ms": 2.649959, - "p90_ms": 3.5665246, - "p99_ms": 3.7727518600000005, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 4049.173186, + "p50_ms": 4132.33117, + "max_ms": 4325.8467869999995, + "p90_ms": 4280.6318161, + "p99_ms": 4315.107096649999 }, "multi.toc": { - "p50_ms": 64732.548124999994, - "p90_ms": 67491.81369139999, - "p99_ms": 68112.64844384, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.124988, + "p50_ms": 0.133424, + "max_ms": 0.39839600000000003, + "p90_ms": 0.25150680000000014, + "p99_ms": 0.38815001000000005 + }, + "multi.toc_build": { + "kind": "setup", + "samples": 1, + "min_ms": 76080.044033, + "p50_ms": 76080.044033, + "max_ms": 76080.044033 }, "multi.topics": { - "p50_ms": 1.911084, - "p90_ms": 2.5866504, - "p99_ms": 2.7386528400000003, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.952573, + "p50_ms": 0.9773555, + "max_ms": 1.3731030000000002, + "p90_ms": 1.0532016, + "p99_ms": 1.3067916000000004 + }, + "multi.topics_index": { + "kind": "setup", + "samples": 1, + "min_ms": 0.659691, + "p50_ms": 0.659691, + "max_ms": 0.659691 }, "multi.vector": { - "p50_ms": 7371.707375, - "p90_ms": 7406.2679078, - "p99_ms": 7414.044027680001, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 4039.865536, + "p50_ms": 4125.625587500001, + "max_ms": 4363.622512, + "p90_ms": 4220.3446183999995, + "p99_ms": 4325.90451141 + }, + "multi.vector_index": { + "kind": "setup", + "samples": 1, + "min_ms": 12404.261658, + "p50_ms": 12404.261658, + "max_ms": 12404.261658 }, "single.bm25": { - "p50_ms": 244.622458, - "p90_ms": 248.543858, - "p99_ms": 249.42617299999998, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.489686, + "p50_ms": 0.5718055, + "max_ms": 0.784316, + "p90_ms": 0.6986046, + "p99_ms": 0.78242172 + }, + "single.bm25_index": { + "kind": "setup", + "samples": 1, + "min_ms": 35.651951000000004, + "p50_ms": 35.651951000000004, + "max_ms": 35.651951000000004 }, "single.ingest": { - "p50_ms": 5.789834, - "p90_ms": 5.8585004, - "p99_ms": 5.87395034, - "samples": 3, + "kind": "setup", + "samples": 1, + "min_ms": 7.487451, + "p50_ms": 7.487451, + "max_ms": 7.487451, "throughput_eps": { - "p50_eps": 41451.96563493876, - "p90_eps": 41738.658416329185, - "p99_eps": 41803.16429214203 + "p50_eps": 32053.632137292116 } }, "single.route_query": { - "p50_ms": 2.3347089999999997, - "p90_ms": 3.0054418000000003, - "p99_ms": 3.15635668, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 3997.107029, + "p50_ms": 4145.490836499999, + "max_ms": 4545.48542, + "p90_ms": 4255.6684171, + "p99_ms": 4477.30165182 }, "single.toc": { - "p50_ms": 64576.70849999999, - "p90_ms": 65290.7832, - "p99_ms": 65451.450007499996, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.12359099999999999, + "p50_ms": 0.131057, + "max_ms": 0.19964700000000002, + "p90_ms": 0.1645027, + "p99_ms": 0.19096237000000005 + }, + "single.toc_build": { + "kind": "setup", + "samples": 1, + "min_ms": 76713.96927, + "p50_ms": 76713.96927, + "max_ms": 76713.96927 }, "single.topics": { - "p50_ms": 1.894125, - "p90_ms": 2.5051586000000006, - "p99_ms": 2.64264116, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 0.950542, + "p50_ms": 0.9737655000000001, + "max_ms": 1.260793, + "p90_ms": 1.0380472, + "p99_ms": 1.2210076100000002 + }, + "single.topics_index": { + "kind": "setup", + "samples": 1, + "min_ms": 0.606363, + "p50_ms": 0.606363, + "max_ms": 0.606363 }, "single.vector": { - "p50_ms": 7171.025874999999, - "p90_ms": 7752.5308749999995, - "p99_ms": 7883.3695, - "samples": 3 + "kind": "query", + "samples": 30, + "min_ms": 4019.133486, + "p50_ms": 4152.4782495, + "max_ms": 4357.285152, + "p90_ms": 4256.1035859, + "p99_ms": 4333.7802982 + }, + "single.vector_index": { + "kind": "setup", + "samples": 1, + "min_ms": 12589.213063000001, + "p50_ms": 12589.213063000001, + "max_ms": 12589.213063000001 + }, + "vector_model_load": { + "kind": "setup", + "samples": 1, + "min_ms": 155.725372, + "p50_ms": 155.725372, + "max_ms": 155.725372 } }, "comparison": { diff --git a/crates/e2e-tests/benchmarks/latest.txt b/crates/e2e-tests/benchmarks/latest.txt index cdba281..cb3b62f 100644 --- a/crates/e2e-tests/benchmarks/latest.txt +++ b/crates/e2e-tests/benchmarks/latest.txt @@ -1,14 +1,23 @@ -Benchmark Results (tier=medium, mode=warm, iterations=3) -step p50_ms p90_ms p99_ms throughput_eps -multi.bm25 247.45 272.24 277.82 - -multi.ingest 5.93 6.06 6.09 40483.56 -multi.route_query 2.65 3.57 3.77 - -multi.toc 64732.55 67491.81 68112.65 - -multi.topics 1.91 2.59 2.74 - -multi.vector 7371.71 7406.27 7414.04 - -single.bm25 244.62 248.54 249.43 - -single.ingest 5.79 5.86 5.87 41451.97 -single.route_query 2.33 3.01 3.16 - -single.toc 64576.71 65290.78 65451.45 - -single.topics 1.89 2.51 2.64 - -single.vector 7171.03 7752.53 7883.37 - \ No newline at end of file +Benchmark Results (schema=2, tier=medium, mode=warm, iterations=30, corpus=240 synthetic, linux/x86_64) +kind step samples min_ms p50_ms p90_ms p99_ms max_ms throughput_eps +query multi.bm25 30 0.48 0.55 0.71 0.77 0.78 - +setup multi.bm25_index 1 36.47 36.47 - - 36.47 - +setup multi.ingest 1 7.42 7.42 - - 7.42 32325.81 +query multi.route_query 30 4049.17 4132.33 4280.63 4315.11 4325.85 - +query multi.toc 30 0.12 0.13 0.25 0.39 0.40 - +setup multi.toc_build 1 76080.04 76080.04 - - 76080.04 - +query multi.topics 30 0.95 0.98 1.05 1.31 1.37 - +setup multi.topics_index 1 0.66 0.66 - - 0.66 - +query multi.vector 30 4039.87 4125.63 4220.34 4325.90 4363.62 - +setup multi.vector_index 1 12404.26 12404.26 - - 12404.26 - +query single.bm25 30 0.49 0.57 0.70 0.78 0.78 - +setup single.bm25_index 1 35.65 35.65 - - 35.65 - +setup single.ingest 1 7.49 7.49 - - 7.49 32053.63 +query single.route_query 30 3997.11 4145.49 4255.67 4477.30 4545.49 - +query single.toc 30 0.12 0.13 0.16 0.19 0.20 - +setup single.toc_build 1 76713.97 76713.97 - - 76713.97 - +query single.topics 30 0.95 0.97 1.04 1.22 1.26 - +setup single.topics_index 1 0.61 0.61 - - 0.61 - +query single.vector 30 4019.13 4152.48 4256.10 4333.78 4357.29 - +setup single.vector_index 1 12589.21 12589.21 - - 12589.21 - +setup vector_model_load 1 155.73 155.73 - - 155.73 - \ No newline at end of file diff --git a/crates/e2e-tests/src/bin/perf_bench.rs b/crates/e2e-tests/src/bin/perf_bench.rs index c962c62..19b0f5d 100644 --- a/crates/e2e-tests/src/bin/perf_bench.rs +++ b/crates/e2e-tests/src/bin/perf_bench.rs @@ -27,7 +27,11 @@ static EMBEDDER: OnceLock> = OnceLock::new(); const SMALL_EVENT_COUNT: usize = 60; const MEDIUM_EVENT_COUNT: usize = 240; -const DEFAULT_ITERATIONS: usize = 3; +/// Query-step default. p99 is only reported at this count. +const DEFAULT_ITERATIONS: usize = 30; +const MIN_SAMPLES_P90: usize = 10; +const MIN_SAMPLES_P99: usize = 30; +const SCHEMA_VERSION: u32 = 2; #[derive(Parser, Debug)] #[command( @@ -78,29 +82,60 @@ impl Scenario { } } +#[derive(Clone, Copy, Debug, Serialize, Deserialize, PartialEq, Eq)] +#[serde(rename_all = "snake_case")] +enum StepKind { + Setup, + Query, +} + #[derive(Clone, Debug, Serialize, Deserialize)] struct ThroughputMetrics { p50_eps: f64, - p90_eps: f64, - p99_eps: f64, + #[serde(skip_serializing_if = "Option::is_none")] + p90_eps: Option, + #[serde(skip_serializing_if = "Option::is_none")] + p99_eps: Option, } #[derive(Clone, Debug, Serialize, Deserialize)] struct StepMetrics { - p50_ms: f64, - p90_ms: f64, - p99_ms: f64, + kind: StepKind, samples: usize, + min_ms: f64, + p50_ms: f64, + max_ms: f64, + #[serde(skip_serializing_if = "Option::is_none")] + p90_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + p99_ms: Option, #[serde(skip_serializing_if = "Option::is_none")] throughput_eps: Option, } +#[derive(Debug, Serialize, Deserialize)] +struct CorpusInfo { + tier: DatasetTier, + event_count: usize, + kind: String, +} + +#[derive(Debug, Serialize, Deserialize)] +struct HardwareInfo { + os: String, + arch: String, +} + #[derive(Debug, Serialize, Deserialize)] struct BenchmarkOutput { + schema_version: u32, tier: DatasetTier, mode: RunMode, iterations: usize, generated_at: String, + corpus: CorpusInfo, + hardware: HardwareInfo, + caveats: Vec, steps: BTreeMap, comparison: Option, } @@ -150,15 +185,45 @@ struct BaselineRun { steps: BTreeMap, } -struct WarmState { +struct PreparedStore { harness: TestHarness, - next_vector_id: u64, + toc_node: TocNode, + bm25_searcher: Arc, + vector_handler: Arc, + topic_handler: Arc, } #[derive(Default)] struct SampleCollector { durations: HashMap>, throughput: HashMap>, + kinds: HashMap, +} + +impl SampleCollector { + fn record(&mut self, step: String, kind: StepKind, duration_ms: f64) { + self.kinds.insert(step.clone(), kind); + self.durations.entry(step).or_default().push(duration_ms); + } + + fn record_throughput(&mut self, step: &str, eps: f64) { + self.throughput + .entry(step.to_string()) + .or_default() + .push(eps); + } +} + +fn caveats() -> Vec { + vec![ + "Query steps (toc, bm25, vector, topics, route_query) exclude index build, rollup, and model load.".into(), + "toc_build is ingest-time MockSummarizer rollup + grip extract + parent-node writes — not TOC navigation.".into(), + "vector_index includes Candle embedding of TOC bullets; vector_model_load is a one-shot process cost.".into(), + "bm25_index is Tantivy add+commit; bm25 is search only.".into(), + "p90 is omitted when samples < 10; p99 is omitted when samples < 30.".into(), + "Warm mode: one setup, one discarded warmup query, then N query samples. Cold mode: new store per iteration.".into(), + "The 2026-02-12 latest.json (single.toc p50 ≈ 64.6s, samples=3) measured toc_build, not navigation.".into(), + ] } #[tokio::main] @@ -172,51 +237,87 @@ async fn main() -> Result<(), String> { None }; - let mut collector = SampleCollector::default(); - let mut warm_state = if args.mode == RunMode::Warm { - Some(WarmState { - harness: TestHarness::new(), - next_vector_id: 1, - }) - } else { - None + let event_count = match (trace_events.as_ref(), args.tier) { + (Some(events), _) => events.len(), + (None, DatasetTier::Small) => SMALL_EVENT_COUNT, + (None, DatasetTier::Medium) => MEDIUM_EVENT_COUNT, }; - for iteration in 0..args.iterations { - for scenario in [Scenario::Single, Scenario::Multi] { - let sample = run_iteration( - args.tier, - args.mode, - scenario, - iteration, - trace_events.as_deref(), - warm_state.as_mut(), - ) - .await?; - - for (step, duration_ms) in sample.durations { - collector - .durations - .entry(step) - .or_default() - .push(duration_ms); + let mut collector = SampleCollector::default(); + + let model_start = Instant::now(); + eprintln!("perf_bench: loading embedding model..."); + let _ = get_embedder(); + let model_ms = model_start.elapsed().as_secs_f64() * 1000.0; + eprintln!("perf_bench: embedding model ready ({model_ms:.0} ms)"); + collector.record("vector_model_load".to_string(), StepKind::Setup, model_ms); + + for scenario in [Scenario::Single, Scenario::Multi] { + eprintln!( + "perf_bench: {} / {} starting", + mode_label(args.mode), + scenario.label() + ); + match args.mode { + RunMode::Warm => { + let store = prepare_store( + args.tier, + scenario, + 0, + trace_events.as_deref(), + &mut collector, + ) + .await?; + // Discard one warmup query so the N samples are warm. + let _ = run_queries(&store, scenario).await?; + for _iteration in 0..args.iterations { + let query_durations = run_queries(&store, scenario).await?; + for (step, ms) in query_durations { + collector.record(step, StepKind::Query, ms); + } + } } - for (step, throughput) in sample.throughput { - collector - .throughput - .entry(step) - .or_default() - .push(throughput); + RunMode::Cold => { + for iteration in 0..args.iterations { + let store = prepare_store( + args.tier, + scenario, + iteration, + trace_events.as_deref(), + &mut collector, + ) + .await?; + let query_durations = run_queries(&store, scenario).await?; + for (step, ms) in query_durations { + collector.record(step, StepKind::Query, ms); + } + drop(store); + } } } } let step_metrics = build_metrics(&collector); let mut output = BenchmarkOutput { + schema_version: SCHEMA_VERSION, tier: args.tier, mode: args.mode, iterations: args.iterations, generated_at: Utc::now().to_rfc3339(), + corpus: CorpusInfo { + tier: args.tier, + event_count, + kind: if args.trace.is_some() { + "trace".into() + } else { + "synthetic".into() + }, + }, + hardware: HardwareInfo { + os: std::env::consts::OS.to_string(), + arch: std::env::consts::ARCH.to_string(), + }, + caveats: caveats(), steps: step_metrics, comparison: None, }; @@ -270,35 +371,14 @@ async fn main() -> Result<(), String> { Ok(()) } -struct IterationSample { - durations: Vec<(String, f64)>, - throughput: Vec<(String, f64)>, -} - -async fn run_iteration( +async fn prepare_store( tier: DatasetTier, - mode: RunMode, scenario: Scenario, iteration: usize, trace_events: Option<&[Event]>, - warm_state: Option<&mut WarmState>, -) -> Result { - // Separate harness ownership from warm_state to avoid overlapping borrows. - // For warm mode, we split warm_state into its harness ref and vector_id tracking. - let mut local_harness = TestHarness::new(); - let (harness, initial_vector_id, warm_vector_writer): ( - &mut TestHarness, - u64, - Option<*mut u64>, - ) = match (mode, warm_state) { - (RunMode::Warm, Some(state)) => { - let vid = state.next_vector_id; - let ptr = &mut state.next_vector_id as *mut u64; - (&mut state.harness, vid, Some(ptr)) - } - _ => (&mut local_harness, 1, None), - }; - + collector: &mut SampleCollector, +) -> Result { + let harness = TestHarness::new(); let iteration_tag = format!("{}-{}-{}", tier_label(tier), scenario.label(), iteration); let base_events = if let Some(trace) = trace_events { prepare_trace_events(trace, scenario, &iteration_tag) @@ -306,26 +386,18 @@ async fn run_iteration( synthetic_events(tier, scenario, iteration) }; - let ingest_label = format!("{}.ingest", scenario.label()); - let toc_label = format!("{}.toc", scenario.label()); - let bm25_label = format!("{}.bm25", scenario.label()); - let vector_label = format!("{}.vector", scenario.label()); - let topics_label = format!("{}.topics", scenario.label()); - let route_label = format!("{}.route_query", scenario.label()); - - let mut durations = Vec::new(); - let mut throughput = Vec::new(); + let prefix = scenario.label(); let ingest_start = Instant::now(); ingest_events(&harness.storage, &base_events); let ingest_ms = ingest_start.elapsed().as_secs_f64() * 1000.0; - durations.push((ingest_label.clone(), ingest_ms)); - throughput.push(( - ingest_label.clone(), + collector.record(format!("{prefix}.ingest"), StepKind::Setup, ingest_ms); + collector.record_throughput( + &format!("{prefix}.ingest"), events_per_second(base_events.len(), ingest_ms), - )); + ); - let toc_start = Instant::now(); + let toc_build_start = Instant::now(); let mut toc_node = build_toc_segment(harness.storage.clone(), base_events).await; if scenario == Scenario::Multi { for agent in ["claude", "copilot"] { @@ -334,48 +406,114 @@ async fn run_iteration( } } } - navigate_toc(harness.storage.as_ref(), &toc_node); - let toc_ms = toc_start.elapsed().as_secs_f64() * 1000.0; - durations.push((toc_label, toc_ms)); + collector.record( + format!("{prefix}.toc_build"), + StepKind::Setup, + toc_build_start.elapsed().as_secs_f64() * 1000.0, + ); + eprintln!( + "perf_bench: {prefix}.toc_build {:.0} ms", + toc_build_start.elapsed().as_secs_f64() * 1000.0 + ); let bm25_start = Instant::now(); - let bm25_searcher = build_bm25_index(harness, &toc_node)?; - let bm25_ms = bm25_start.elapsed().as_secs_f64() * 1000.0; - durations.push((bm25_label, bm25_ms)); + let bm25_searcher = build_bm25_index(&harness, &toc_node)?; + collector.record( + format!("{prefix}.bm25_index"), + StepKind::Setup, + bm25_start.elapsed().as_secs_f64() * 1000.0, + ); let vector_start = Instant::now(); - let vector_handler = build_vector_index( - harness, - &toc_node, - scenario, - iteration, - initial_vector_id, - warm_vector_writer, - ) - .await?; - let vector_ms = vector_start.elapsed().as_secs_f64() * 1000.0; - durations.push((vector_label, vector_ms)); + let vector_handler = build_vector_index(&harness, &toc_node, scenario, iteration).await?; + collector.record( + format!("{prefix}.vector_index"), + StepKind::Setup, + vector_start.elapsed().as_secs_f64() * 1000.0, + ); let topics_start = Instant::now(); let topic_handler = build_topic_graph(harness.storage.clone(), &toc_node, iteration).await?; - let topics_ms = topics_start.elapsed().as_secs_f64() * 1000.0; - durations.push((topics_label, topics_ms)); + collector.record( + format!("{prefix}.topics_index"), + StepKind::Setup, + topics_start.elapsed().as_secs_f64() * 1000.0, + ); - let route_start = Instant::now(); - run_route_query( - harness.storage.clone(), + Ok(PreparedStore { + harness, + toc_node, bm25_searcher, vector_handler, topic_handler, + }) +} + +async fn run_queries( + store: &PreparedStore, + scenario: Scenario, +) -> Result, String> { + let prefix = scenario.label(); + let mut durations = Vec::new(); + + let toc_start = Instant::now(); + navigate_toc(store.harness.storage.as_ref(), &store.toc_node); + durations.push(( + format!("{prefix}.toc"), + toc_start.elapsed().as_secs_f64() * 1000.0, + )); + + let bm25_start = Instant::now(); + let _ = store + .bm25_searcher + .search("rust memory safety", SearchOptions::new().with_limit(10)); + durations.push(( + format!("{prefix}.bm25"), + bm25_start.elapsed().as_secs_f64() * 1000.0, + )); + + let vector_start = Instant::now(); + let _ = store + .vector_handler + .search("vector embedding retrieval", 10, 0.0) + .await; + durations.push(( + format!("{prefix}.vector"), + vector_start.elapsed().as_secs_f64() * 1000.0, + )); + + let topics_start = Instant::now(); + let _ = store + .topic_handler + .get_top_topics(Request::new(memory_service::pb::GetTopTopicsRequest { + limit: 3, + days: 30, + agent_filter: None, + })) + .await; + let _ = store + .topic_handler + .search_topics("memory retrieval", 5) + .await; + durations.push(( + format!("{prefix}.topics"), + topics_start.elapsed().as_secs_f64() * 1000.0, + )); + + let route_start = Instant::now(); + run_route_query( + store.harness.storage.clone(), + store.bm25_searcher.clone(), + store.vector_handler.clone(), + store.topic_handler.clone(), ) .await?; - let route_ms = route_start.elapsed().as_secs_f64() * 1000.0; - durations.push((route_label, route_ms)); + durations.push(( + format!("{prefix}.route_query"), + route_start.elapsed().as_secs_f64() * 1000.0, + )); - Ok(IterationSample { - durations, - throughput, - }) + Ok(durations) } fn events_per_second(count: usize, duration_ms: f64) -> f64 { @@ -485,10 +623,11 @@ fn synthetic_events(tier: DatasetTier, scenario: Scenario, iteration: usize) -> fn navigate_toc(storage: &memory_storage::Storage, toc_node: &TocNode) { let day_id = toc_node.start_time.format("%Y-%m-%d").to_string(); let year_id = toc_node.start_time.format("%Y").to_string(); - let day_node = format!("toc:day:{}", day_id); - let year_node = format!("toc:year:{}", year_id); - let _ = storage.get_toc_node(&day_node); + let day_node = format!("toc:day:{day_id}"); + let year_node = format!("toc:year:{year_id}"); let _ = storage.get_toc_node(&year_node); + let _ = storage.get_toc_node(&day_node); + let _ = storage.get_toc_node(&toc_node.node_id); } fn build_bm25_index( @@ -517,10 +656,9 @@ fn build_bm25_index( } } indexer.commit().map_err(|e| e.to_string())?; - - let searcher = TeleportSearcher::new(&bm25_index).map_err(|e| e.to_string())?; - let _ = searcher.search("rust memory safety", SearchOptions::new().with_limit(10)); - Ok(Arc::new(searcher)) + TeleportSearcher::new(&bm25_index) + .map(Arc::new) + .map_err(|e| e.to_string()) } async fn build_vector_index( @@ -528,8 +666,6 @@ async fn build_vector_index( toc_node: &TocNode, scenario: Scenario, iteration: usize, - initial_vector_id: u64, - warm_vector_writer: Option<*mut u64>, ) -> Result, String> { let embedder = get_embedder(); let capacity = toc_node.bullets.len().max(10) + 32; @@ -557,8 +693,7 @@ async fn build_vector_index( )); } - let mut vector_id = initial_vector_id; - + let mut vector_id = 1_u64; for (idx, (text, agent, timestamp_ms)) in texts.iter().enumerate() { let embedder_clone = embedder.clone(); let text_owned = text.clone(); @@ -582,19 +717,11 @@ async fn build_vector_index( vector_id += 1; } - if let Some(ptr) = warm_vector_writer { - // SAFETY: ptr points to warm_state.next_vector_id which is still alive - // within run_iteration's scope. We use a raw pointer to avoid borrow conflicts. - unsafe { - *ptr = vector_id; - } - } - let index_lock = Arc::new(std::sync::RwLock::new(hnsw_index)); let metadata = Arc::new(metadata); - let handler = Arc::new(VectorTeleportHandler::new(embedder, index_lock, metadata)); - let _ = handler.search("vector embedding retrieval", 10, 0.0).await; - Ok(handler) + Ok(Arc::new(VectorTeleportHandler::new( + embedder, index_lock, metadata, + ))) } async fn build_topic_graph( @@ -633,19 +760,10 @@ async fn build_topic_graph( } } - let handler = Arc::new(TopicGraphHandler::new( + Ok(Arc::new(TopicGraphHandler::new( Arc::new(topic_storage), - storage.clone(), - )); - let _ = handler - .get_top_topics(Request::new(memory_service::pb::GetTopTopicsRequest { - limit: 3, - days: 30, - agent_filter: None, - })) - .await; - let _ = handler.search_topics("memory retrieval", 5).await; - Ok(handler) + storage, + ))) } async fn run_route_query( @@ -689,29 +807,31 @@ fn create_topic(id: &str, label: &str, keywords: &[&str], importance: f64) -> To fn build_metrics(collector: &SampleCollector) -> BTreeMap { let mut steps = BTreeMap::new(); for (step, durations) in &collector.durations { - let mut sorted = durations.clone(); - sorted.sort_by(|a, b| a.partial_cmp(b).unwrap()); - let p50 = percentile(&sorted, 50.0); - let p90 = percentile(&sorted, 90.0); - let p99 = percentile(&sorted, 99.0); - + let kind = collector + .kinds + .get(step) + .copied() + .unwrap_or(StepKind::Query); + let stats = summarize_samples(durations); let throughput = collector.throughput.get(step).map(|values| { - let mut throughput_values = values.clone(); - throughput_values.sort_by(|a, b| a.partial_cmp(b).unwrap()); + let t = summarize_samples(values); ThroughputMetrics { - p50_eps: percentile(&throughput_values, 50.0), - p90_eps: percentile(&throughput_values, 90.0), - p99_eps: percentile(&throughput_values, 99.0), + p50_eps: t.p50, + p90_eps: t.p90, + p99_eps: t.p99, } }); steps.insert( step.clone(), StepMetrics { - p50_ms: p50, - p90_ms: p90, - p99_ms: p99, - samples: durations.len(), + kind, + samples: stats.samples, + min_ms: stats.min, + p50_ms: stats.p50, + max_ms: stats.max, + p90_ms: stats.p90, + p99_ms: stats.p99, throughput_eps: throughput, }, ); @@ -719,40 +839,91 @@ fn build_metrics(collector: &SampleCollector) -> BTreeMap { steps } -fn percentile(values: &[f64], percentile: f64) -> f64 { +struct SampleStats { + samples: usize, + min: f64, + p50: f64, + max: f64, + p90: Option, + p99: Option, +} + +fn summarize_samples(values: &[f64]) -> SampleStats { + let mut sorted = values.to_vec(); + sorted.sort_by(|a, b| a.partial_cmp(b).unwrap_or(std::cmp::Ordering::Equal)); + let n = sorted.len(); + SampleStats { + samples: n, + min: sorted.first().copied().unwrap_or(0.0), + p50: percentile(&sorted, 50.0).unwrap_or(0.0), + max: sorted.last().copied().unwrap_or(0.0), + p90: if n >= MIN_SAMPLES_P90 { + percentile(&sorted, 90.0) + } else { + None + }, + p99: if n >= MIN_SAMPLES_P99 { + percentile(&sorted, 99.0) + } else { + None + }, + } +} + +/// Linear-interpolated percentile. `values` must be sorted ascending. +fn percentile(values: &[f64], percentile: f64) -> Option { if values.is_empty() { - return 0.0; + return None; } let rank = (percentile / 100.0) * (values.len() as f64 - 1.0); let low = rank.floor() as usize; let high = rank.ceil() as usize; if low == high { - values[low] + Some(values[low]) } else { let weight = rank - low as f64; - values[low] + (values[high] - values[low]) * weight + Some(values[low] + (values[high] - values[low]) * weight) } } fn render_table(output: &BenchmarkOutput) -> String { let mut lines = Vec::new(); lines.push(format!( - "Benchmark Results (tier={}, mode={}, iterations={})", + "Benchmark Results (schema={}, tier={}, mode={}, iterations={}, corpus={} {}, {}/{})", + output.schema_version, tier_label(output.tier), mode_label(output.mode), - output.iterations + output.iterations, + output.corpus.event_count, + output.corpus.kind, + output.hardware.os, + output.hardware.arch )); - lines.push("step\tp50_ms\tp90_ms\tp99_ms\tthroughput_eps".to_string()); + lines.push( + "kind\tstep\tsamples\tmin_ms\tp50_ms\tp90_ms\tp99_ms\tmax_ms\tthroughput_eps".to_string(), + ); for (step, metrics) in &output.steps { + let kind = match metrics.kind { + StepKind::Setup => "setup", + StepKind::Query => "query", + }; + let p90 = metrics + .p90_ms + .map(|v| format!("{v:.2}")) + .unwrap_or_else(|| "-".into()); + let p99 = metrics + .p99_ms + .map(|v| format!("{v:.2}")) + .unwrap_or_else(|| "-".into()); let throughput = metrics .throughput_eps .as_ref() .map(|t| format!("{:.2}", t.p50_eps)) .unwrap_or_else(|| "-".to_string()); lines.push(format!( - "{}\t{:.2}\t{:.2}\t{:.2}\t{}", - step, metrics.p50_ms, metrics.p90_ms, metrics.p99_ms, throughput + "{kind}\t{step}\t{}\t{:.2}\t{:.2}\t{p90}\t{p99}\t{:.2}\t{throughput}", + metrics.samples, metrics.min_ms, metrics.p50_ms, metrics.max_ms )); } lines.join("\n") @@ -775,7 +946,16 @@ fn compare_with_baseline( }); } let baseline_data = fs::read_to_string(baseline_path).map_err(|e| e.to_string())?; - let baseline: BaselineFile = serde_json::from_str(&baseline_data).map_err(|e| e.to_string())?; + let baseline: BaselineFile = match serde_json::from_str::(&baseline_data) { + Ok(b) if b.version == SCHEMA_VERSION => b, + _ => { + // v1 files mixed setup+query under query names; do not compare. + return Ok(ComparisonSummary { + warnings: Vec::new(), + severe: Vec::new(), + }); + } + }; let run = baseline .runs @@ -793,6 +973,9 @@ fn compare_with_baseline( let mut severe = Vec::new(); for (step, current) in &output.steps { + if current.kind != StepKind::Query { + continue; + } let Some(baseline_step) = run.steps.get(step) else { continue; }; @@ -906,25 +1089,20 @@ fn apply_throughput_regression( fn update_baseline(path: &Path, output: &BenchmarkOutput) -> Result { let mut baseline = if path.exists() { let data = fs::read_to_string(path).map_err(|e| e.to_string())?; - serde_json::from_str::(&data).map_err(|e| e.to_string())? + match serde_json::from_str::(&data) { + Ok(existing) if existing.version == SCHEMA_VERSION => existing, + _ => BaselineFile { + baseline: default_baseline_label(), + version: SCHEMA_VERSION, + thresholds: default_thresholds(), + runs: Vec::new(), + }, + } } else { BaselineFile { baseline: default_baseline_label(), - version: 1, - thresholds: Thresholds { - warning: Threshold { - relative: 0.15, - absolute_ms: 25.0, - throughput_relative: 0.15, - throughput_absolute: 50.0, - }, - severe: Threshold { - relative: 0.30, - absolute_ms: 50.0, - throughput_relative: 0.30, - throughput_absolute: 100.0, - }, - }, + version: SCHEMA_VERSION, + thresholds: default_thresholds(), runs: Vec::new(), } }; @@ -932,6 +1110,7 @@ fn update_baseline(path: &Path, output: &BenchmarkOutput) -> Result Result Thresholds { + Thresholds { + warning: Threshold { + relative: 0.15, + absolute_ms: 25.0, + throughput_relative: 0.15, + throughput_absolute: 50.0, + }, + severe: Threshold { + relative: 0.30, + absolute_ms: 50.0, + throughput_relative: 0.30, + throughput_absolute: 100.0, + }, + } +} + fn default_baseline_label() -> String { "perf_bench".to_string() } @@ -961,7 +1157,13 @@ fn default_baseline_label() -> String { fn get_embedder() -> Arc { EMBEDDER .get_or_init(|| { - let embedder = CandleEmbedder::load_default().expect("Failed to load embedding model"); + let cache = memory_embeddings::ModelCache::default(); + eprintln!( + "perf_bench: model cache dir = {} (cached={})", + cache.model_dir().display(), + cache.is_cached() + ); + let embedder = CandleEmbedder::load(&cache).expect("Failed to load embedding model"); Arc::new(embedder) }) .clone() @@ -987,3 +1189,62 @@ fn agent_for_scenario(scenario: Scenario) -> &'static str { Scenario::Multi => "copilot", } } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn percentile_empty_is_none() { + assert_eq!(percentile(&[], 50.0), None); + } + + #[test] + fn percentile_single_value() { + assert_eq!(percentile(&[10.0], 50.0), Some(10.0)); + assert_eq!(percentile(&[10.0], 99.0), Some(10.0)); + } + + #[test] + fn summarize_omits_p90_below_10_samples() { + let stats = summarize_samples(&[1.0, 2.0, 3.0]); + assert_eq!(stats.samples, 3); + assert_eq!(stats.min, 1.0); + assert_eq!(stats.max, 3.0); + assert_eq!(stats.p50, 2.0); + assert!(stats.p90.is_none()); + assert!(stats.p99.is_none()); + } + + #[test] + fn summarize_includes_p90_at_10_samples() { + let values: Vec = (1..=10).map(|i| i as f64).collect(); + let stats = summarize_samples(&values); + assert!(stats.p90.is_some()); + assert!(stats.p99.is_none()); + } + + #[test] + fn summarize_includes_p99_at_30_samples() { + let values: Vec = (1..=30).map(|i| i as f64).collect(); + let stats = summarize_samples(&values); + assert!(stats.p90.is_some()); + assert!(stats.p99.is_some()); + assert_eq!(stats.min, 1.0); + assert_eq!(stats.max, 30.0); + } + + #[test] + fn three_sample_p99_would_be_an_artifact() { + // The retired 2026-02-12 methodology interpolated p99 from 3 samples. + let sorted = [64576.0, 65000.0, 65451.0]; + let fake_p99 = percentile(&sorted, 99.0).unwrap(); + assert!( + (fake_p99 - sorted[2]).abs() < 50.0, + "p99 of 3 samples collapses onto max ({fake_p99} vs {})", + sorted[2] + ); + let honest = summarize_samples(&sorted); + assert!(honest.p99.is_none()); + } +} diff --git a/docs/benchmarks.md b/docs/benchmarks.md index cfd3cd3..64bfa2f 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -1,67 +1,150 @@ # Performance Benchmarks -The `perf_bench` harness measures ingest throughput and retrieval latency across TOC navigation, -BM25 teleport, vector teleport, topic graph, and `route_query`. +The `perf_bench` harness measures **ingest/index setup** separately from +**query** latency. Schema version 2 (2026-08-30) exists because the v3.0 +numbers mixed those two and then published the mix as "TOC navigation." + +## What each step actually measures + +| Step | Kind | What is timed | +|------|------|----------------| +| `vector_model_load` | setup | One-shot Candle embedder load (process lifetime) | +| `{single,multi}.ingest` | setup | RocksDB `put_event` of the corpus | +| `{single,multi}.toc_build` | setup | `build_toc_segment`: MockSummarizer rollup, grip extract, parent TOC writes | +| `{single,multi}.bm25_index` | setup | Tantivy add + commit | +| `{single,multi}.vector_index` | setup | Embed TOC bullets + HNSW add | +| `{single,multi}.topics_index` | setup | Write topic records | +| `{single,multi}.toc` | **query** | Three `get_toc_node` lookups (year, day, segment) | +| `{single,multi}.bm25` | **query** | Tantivy BM25 search | +| `{single,multi}.vector` | **query** | HNSW search (model already loaded) | +| `{single,multi}.topics` | **query** | Top-topics + topic search | +| `{single,multi}.route_query` | **query** | `MemoryOrchestrator` / `RouteQuery` RPC | + +## The 64.6 second TOC number (retired) + +`crates/e2e-tests/benchmarks/latest.json` from 2026-02-12 (`tier=medium`, +`mode=warm`, `iterations=3`) recorded `single.toc` p50 = **64,576 ms** and +`single.vector` p50 = **7,171 ms**. That file timed: + +```text +toc_start + build_toc_segment(240 events) # rollup — the 65s + navigate_toc() # two RocksDB gets +toc_ms → labeled "toc" +``` + +It was a harness defect, not a query-path cost. p90/p99 were interpolated +from **3 samples** and are not percentiles. Schema v2 refuses to emit p90 +unless `n ≥ 10` and p99 unless `n ≥ 30`. + +If someone quotes the 65s figure: it is ingest-time mock rollup of a 240-event +segment, not "answer last week without scanning everything." + +## Modes (structurally different) + +- **Warm:** one store setup, one discarded warmup query, then N query samples + against a stable index. This is the number that should be compared to the + "always-works foundation" claim. +- **Cold:** a new store per iteration (setup + first query). Setup costs + appear as `*_build` / `*_index` / `vector_model_load`. -## Run the benchmarks +## Run -Small dataset (cold): +Default `--iterations` is 30 (query samples). + +Small, warm (the usual local check): ```bash -cargo run -p e2e-tests --bin perf_bench -- --tier small --mode cold --iterations 3 --out-dir crates/e2e-tests/benchmarks +cargo run -p e2e-tests --bin perf_bench -- --tier small --mode warm --iterations 30 --out-dir crates/e2e-tests/benchmarks ``` -Small dataset (warm): +Medium, warm (the number that replaces the 65s claim): ```bash -cargo run -p e2e-tests --bin perf_bench -- --tier small --mode warm --iterations 3 --out-dir crates/e2e-tests/benchmarks +cargo run -p e2e-tests --bin perf_bench -- --tier medium --mode warm --iterations 30 --out-dir crates/e2e-tests/benchmarks ``` -Medium dataset (cold/warm): +Cold (new store per iteration — expensive because it repeats `toc_build`): ```bash -cargo run -p e2e-tests --bin perf_bench -- --tier medium --mode cold --iterations 3 --out-dir crates/e2e-tests/benchmarks -cargo run -p e2e-tests --bin perf_bench -- --tier medium --mode warm --iterations 3 --out-dir crates/e2e-tests/benchmarks +cargo run -p e2e-tests --bin perf_bench -- --tier small --mode cold --iterations 30 --out-dir crates/e2e-tests/benchmarks ``` -## Optional trace input +Optional JSONL trace of `memory_types::Event` payloads: + +```bash +cargo run -p e2e-tests --bin perf_bench -- --tier small --mode warm --iterations 30 --trace path/to/events.jsonl --out-dir crates/e2e-tests/benchmarks +``` -Provide a JSONL file of `memory_types::Event` payloads to override synthetic data: +## Output + +- `latest.txt` — table with kind, samples, min/p50/p90/p99/max. `-` means the + percentile was withheld for lack of samples. +- `latest.json` — structured metrics plus `corpus`, `hardware`, and `caveats`. + +## Baseline comparisons + +`crates/e2e-tests/benchmarks/baseline.json` is schema version 2. Comparison +runs only against **query** steps of a matching tier/mode. Version-1 files +(the mixed setup+query numbers) are ignored, not compared. + +- Warning / severe thresholds apply to query `p50_ms` (and ingest throughput). +- `--write-baseline` replaces the matching tier/mode run. ```bash -cargo run -p e2e-tests --bin perf_bench -- --tier small --mode cold --iterations 3 --trace path/to/events.jsonl --out-dir crates/e2e-tests/benchmarks +cargo run -p e2e-tests --bin perf_bench -- --tier medium --mode warm --iterations 30 --write-baseline --out-dir crates/e2e-tests/benchmarks ``` -Each line must be a single JSON-encoded `Event`. The harness will re-tag session IDs and agents -to keep runs isolated while preserving the original content. +## Hardware and corpus (for any committed result) -## Output conventions +Recorded in `latest.json`: -The harness prints a tabular summary and JSON payload to stdout. It also writes deterministic -files in the output directory: +- `corpus.event_count` — 60 (small) or 240 (medium) synthetic events unless a + trace file is supplied +- `hardware.os` / `hardware.arch` +- `iterations` — query samples +- `caveats` — the list above, committed next to the numbers -- `latest.txt`: human-readable table with p50/p90/p99 per step -- `latest.json`: structured metrics, including ingest throughput (events/sec) +Vector indexing downloads the default Candle model on first run. That cost is +`vector_model_load`, not `vector`. -Step keys are prefixed with `single.` or `multi.` to distinguish single-agent vs multi-agent runs. +## Committed result (2026-08-30) -## Baseline comparisons +Artifact: `crates/e2e-tests/benchmarks/latest.json` (schema 2). -Baseline metrics live in `crates/e2e-tests/benchmarks/baseline.json`. By default, each run -loads the baseline for the matching tier/mode and reports warnings or severe regressions. +| Field | Value | +|-------|--------| +| Corpus | 240 synthetic events (medium) | +| Mode | warm (one setup, one discarded warmup, 30 query samples) | +| Hardware | linux/x86_64 | +| Profile | `cargo run` **debug** (not `--release`) | +| Generated | 2026-08-30T17:30:20Z | -- Warning: exceeds either warning relative (%) or absolute (ms/EPS) thresholds -- Severe: exceeds severe thresholds and exits with non-zero status +Query p50 (30 samples, p90/p99 reported): -To update the baseline with current results: +| Step | p50 | What it is | +|------|-----|------------| +| `single.toc` | **0.13 ms** | three `get_toc_node` lookups | +| `single.bm25` | 0.57 ms | Tantivy search | +| `single.topics` | 0.97 ms | topic lookup | +| `single.vector` | 4.15 s | Candle **query embed** + HNSW (debug) | +| `single.route_query` | 4.15 s | orchestrator fan-out; dominated by the same query embed | -```bash -cargo run -p e2e-tests --bin perf_bench -- --tier small --mode cold --iterations 3 --write-baseline --out-dir crates/e2e-tests/benchmarks -``` +Setup (1 sample — min/median/max only, no fake p90/p99): -Repeat for other tier/mode combinations to keep the baseline current. +| Step | p50 | What it is | +|------|-----|------------| +| `single.toc_build` | **76.7 s** | MockSummarizer rollup of 240 events. This is the retired 64.6 s "TOC navigation" number. | +| `single.vector_index` | 12.6 s | embed TOC bullets + HNSW add | +| `vector_model_load` | 0.16 s | Candle load from local cache | +| `single.bm25_index` | 36 ms | Tantivy add+commit | +| `single.ingest` | 7.5 ms | RocksDB puts (~32k events/s) | -## Notes +`single.toc` warm p50 is **0.13 ms**, well under the 500 ms acceptance bar. +The 65-second figure is ingest-time rollup (`toc_build`), not query. -- Vector benchmarks use the default embedding model and may download weights on first run. -- Expect vector indexing to dominate runtime for medium datasets. +Vector: model load, index build, and query are three steps. Query p50 in this +debug run is ~4 s because each search embeds the query string with Candle on +CPU; that is a real query-path cost in this profile, not embedder init. Do +not quote it as production HNSW latency — re-run `--release` before +publishing a product number.