Perf-trace report — 2026-07-24 · 2.7.0.dev1

First unified per-release perf report under the resolidified framework (../index.md). Establishes the 2.7.0.dev1 baseline across the Search, Graph, and Surfaces harnesses. No prior unified release to diff against, so the Δ columns open next release.

• Corpus: .test_outputs/manual/prod-v2/corpus (99 episodes; reindexed to LANCE_SCHEMA_VERSION 3 — carries insight_type).
• Conditions: headless Chromium, 1440×900 @ DPR-2 (UI); localhost api (API).
• Sampling: 6 runs; run-1 (cold) is EXCLUDED from the target metrics (first query pays index-open + embedding-model load). Headline = warm min / median / max over runs 2–6; the cold value is recorded in its own column. The cold/warm split is the headline finding — see below.
• Code: branch search-and-player-enhancement; ships in the 2.7.0.dev1 train.

Search — UI (warm min/mean/median/max over 5 runs, cold excluded)

data/perf/traces/search/2.7.0.dev1-search-ui.ui.metrics.json

Scenario	min	mean	median	max	cold (excl.)
workspace-open	202	209	207	218	997
filter-apply	15	28	28	36	19
results-paint	182	183	183	184	4316
cmdk-open	2	2	2	3	3
operator-cluster	13	15	15	16	23
operator-compare	349	367	356	421	355

Fix applied this session: results-paint was 788 ms before — the first query per page queued behind /api/corpus/digest's ~520 ms of LanceDB band searches on the single event loop. Two changes landed: (1) search/compare run off the event loop behind a single-flight gate (hygiene; #1205-safe), and (2) the digest topic bands are cached per process, self-invalidating on the lance-index mtime (reindex). Net: 788 → 285 ms (−503 ms, −64%), measured median-of-6. Remaining cold (5817 ms, first query per process) is the separate index+model warmup (#1276).

FU1 (resolved): 285 → 182 ms, stable. The residual after the digest fix was GIL contention, not event-loop blocking: the page-load burst's pure-Python work (/api/corpus/feeds catalog scan ~150 ms; digest rows ~100 ms; /api/index/stats full row-scan) held the GIL against the search's Python (RRF/assembly), even after moving handlers off the event loop — threads don't beat the GIL for CPU-bound Python. Fix: cache that Python work. index_stats, digest bands, digest rows, and feeds now go through a central cache (podcast_scraper.perf_cache) with the right freshness token per source — lance-mtime (reindex) for index-derived, corpus-run-summary mtime (ingest) for corpus-derived. Full arc: 788 → 285 → 182 ms, warm distribution 182–184 (no bimodality). Stats at GET /api/ops/cache-stats.

The three latency regimes of a search (measured)

results-paint above is the first query on a freshly-loaded page — the harness opens a new browser context per run, so every "warm" run is a first-query. That is the honest "user opens Search and types a query" number. Breaking it down (submit → first card):

Regime	total (post-fix)	was (pre-fix)	when
process-cold	~4.8–6.8 s	(same)	first query after the api boots (index + model load) — #1276
first-query-per-page	~182 ms	~788 ms	first query after each page load — the headline above
same-page repeat	~115 ms	~115 ms	2nd+ query without navigating away

Server compute for a search is only ~108 ms. The pre-fix first-query inflation to ~570 ms server ttfb was not search cost — the first query queued behind /api/corpus/digest, which ran ~520 ms of LanceDB topic-band searches (one hybrid search per configured topic) synchronously on the single-worker event loop. Fix (landed this session):

1. search_corpus / search_compare run their native work off the event loop via run_in_threadpool, behind a process-wide single-flight semaphore (_LANCE_GATE) — the loop is freed without allowing concurrent native LanceDB reads (#1205-safe).
2. /api/corpus/digest caches its topic bands per process, keyed on (corpus, window, since-day, band-config) and stamped with the lance-index mtime — so a warm page-load does zero band searches and self-invalidates on reindex (mirrors search.index_pool).

Net after the digest fix: 788 → 285 ms. The residual ~170 ms over the same-page-repeat (~115 ms) was GIL contention — the page-load fan-out (/api/corpus/feeds catalog scan, digest rows, /api/index/stats full row-scan) is pure-Python CPU work that held the GIL against the search's Python even once handlers were off the event loop. FU1 caches all of it through the central podcast_scraper.perf_cache (lance-mtime token for index-derived, corpus-run-summary token for corpus-derived): 285 → 182 ms, warm distribution 182–184, no bimodality. Full arc 788 → 285 → 182 ms. Process-cold (#1276) is untouched.

Search — API

data/perf/traces/search/2.7.0.dev1-search-api.api.metrics.json — pure-HTTP (capture-search-api), prod-v2, warm, 3 iterations. Query set: tests/fixtures/perf/prod-v2-search-queries.json (25 queries, 5 per RFC-092 intent class; latency baseline, relevance unlabeled).

Scenario	p50_ms	p95_ms	p99_ms	ok	sigsegv_free
api-intent-entity_lookup	108	127	138	15/15	—
api-intent-raw_evidence	118	137	140	15/15	—
api-intent-temporal_tracking	122	137	145	15/15	—
api-intent-cross_show_synthesis	117	131	133	15/15	—
api-intent-semantic	119	130	133	15/15	—
api-top_k-10	115	125	125	9/9	—
api-top_k-25	153	164	164	9/9	—
api-top_k-50	224	232	232	9/9	—
api-top_k-100	339	431	431	9/9	—
api-concurrent-4	474	487	488	60/60	true

Per-intent search compute is ~108–122 ms p50 (flat across intent classes), matching the ~108 ms server figure the UI section cites. Latency scales with top_k (115 → 339 ms p50 from 10 → 100). api-concurrent-4 is SIGSEGV-free (60/60 ok) — the runtime companion to the #1205 single-flight gate + forbidden- imports lint: 4-way concurrent native LanceDB load does not crash the worker.

Graph — API

data/perf/traces/graph/2.7.0.dev1-graph-api.api.metrics.json

Scenario	p50_ms	p95_ms	n	sigsegv_free
api-artifacts-list	108	109	3	—
api-artifact-fetch	0	0	60	—
api-topic-clusters	0	1	3	—
api-concurrent-4	1	1	60	true

Server-side serving is ~0 ms; artifacts-list (108 ms) is the only notable server cost. Graph time-to-canvas is a client-side parse/merge/fcose cost.

Graph — UI / LCP

data/perf/traces/graph/2.7.0.dev1-graph-lcp.metrics.json — Playwright/CDP, prod-v2, default run. First live prod-v2 re-capture of the graph shell + canvas (prior standing reference was the graph-v3 report).

Metric	value	notes
shell LCP	932 ms	FCP == LCP (text hero); matches the ~928 ms graph-v3 reference
time-to-canvas	6313 ms	click Graph → Cytoscape mounted; the #1219 client-side rebuild
long-tasks total	0 ms	no main-thread long task ≥50 ms recorded during the window

Shell paints fast (~932 ms). Time-to-canvas ~6.3 s is the sibling cold path (#1219) — full destroy+rebuild + fcose on the KG second wave; the real fix is the incremental-append refactor. Accepted for 2.7.0.dev1.

Harness fix (this run): the default canvas-appearance ceiling was coupled to --wait-ms (5000 ms), below the actual ttc (~6.3 s), so a default run silently recorded graph_time_to_canvas_ms=null — the harness could not measure its own headline metric. Split into a dedicated --canvas-wait-ms (default 12000 ms, > ttc); the default run now captures ttc.

Surfaces — UI (warm min/median/max, cold excluded)

data/perf/traces/surfaces/2.7.0.dev1-surfaces.ui.metrics.json

Scenario	min	mean	median	max	cold (excl.)
library-load	16	18	17	23	46
digest-load	25	28	27	31	16
entity-load	6	12	9	18	11

Tab-switch / interaction → container-visible (corpus envelope pre-loaded). Stable, no cold outlier (the app is already warm by the time these run) — all under 30 ms.

Common-sense assessment — what's off vs where we'd want to be

First-query-per-page is now fixed (788 → 182 ms). Two cold paths remain, both accepted/tracked.

1. Search first-query-per-page — FIXED this session: 788 → 182 ms (−77%, measured median-of-6). Two-stage fix. Stage 1 (digest): /api/corpus/digest's ~520 ms of LanceDB band searches hogged the single event loop; fixed by (a) running search/compare off the loop behind a single-flight gate (#1205-safe) and (b) per-process digest topic-band caching (self-invalidates on reindex) — 788 → 285. Stage 2 (FU1): the ~170 ms residual was GIL contention from the page-load fan-out's pure-Python CPU work (/api/corpus/feeds, digest rows, /api/index/stats); cached all of it through the central podcast_scraper.perf_cache — 285 → 182, warm 182–184, no bimodality.

2. Search process-cold — ~4.8–6.8 s (first query per process). Accepted this release; tracked in #1276 (performance). Index-open + embedding-model load; fix is a startup warmup.

3. Graph time-to-canvas — ~6.3 s (re-captured on prod-v2 this run; shell LCP ~932 ms). The sibling cold experience, client-side (fcose + KG-second-wave full rebuild). Want: < ~2 s. Known; the real fix is the incremental-append refactor (cy.add(delta) instead of destroy+rebuild) tracked in #1219 (performance). Accepted this release. (Consistent with the graph-v3 reference's ~5.8 s; the ~0.5 s delta is machine load, not a regression.)

4. operator-compare — ~356 ms (steady, no cold gap; was mis-reported as ~800 ms). Split is net 352 ms / render 4 ms — ~100% the API round trip (two subject-scoped searches, run serially; the two build_briefing_pack passes are ~0 ms). Render is trivial. FU4 (2026-07-24) investigated this: the earlier ~800 ms was a harness measurement artifact — captureOperatorCompare waited on columns.waitFor({state:'visible'}) alone, which settled ~480 ms after the columns actually painted; anchoring the timer on the /api/search/compare response collapsed it to the true ~356 ms. Not parallelizing the two searches: they are deliberately serialized inside one _LANCE_GATE (search.py) and concurrent native LanceDB reads are the #1205 SIGSEGV cause. No compare-perf work needed; the fix was the harness metric.

5. Everything else is where we'd want it — filter-apply ~28 ms, cmdk-open ~2 ms, operator-cluster ~15 ms, all three surfaces < 30 ms. No action.

Bottom line: first-query-per-page is fixed (788 → 182 ms, in two stages — digest cache then GIL-residual cache). Search compute is ~108 ms, repeats ~115 ms, and first-query-per-page is now within ~65 ms of the repeat floor. What remains is two cold paths — search process-cold ~5–7 s (#1276 startup warmup) and graph time-to-canvas ~5.8 s (#1219 client-side rebuild) — both accepted for 2.7.0.dev1. operator-compare is ~356 ms (net 352 / render 4), not the ~800 ms first reported — FU4 traced that to a harness waitFor artifact and fixed the metric; no steady-state item needs compare-perf work.

NOT captured this run

• Search — API (capture-search-api): now captured on prod-v2 (see the Search — API section above; 2.7.0.dev1-search-api.api.metrics.json, query set tests/fixtures/perf/prod-v2-search-queries.json). The old S4-shell-fixture-baseline.api.metrics.json (fixture corpus) is superseded for the prod-v2 series. Relevance labels are still unlabeled — this is a latency, not a correctness, baseline.
• Graph — UI / LCP (capture-graph-lcp): now re-captured on prod-v2 (see the Graph — UI / LCP section above; shell LCP 932 ms, time-to-canvas 6313 ms). Starts the live Δ series against the graph-v3 reference.
• Absolute-latency caveat: scripted deterministic settles on one machine — good for cross-release relative diffs, indicative (not definitive) for real-user latency.