indexer: per-phase timing instrumentation (#103)

[IceRhymers]

Refs #103

What & why

Adds per-phase wall-clock instrumentation to the indexer so the dominant cost of an indexing run (download/extract I/O, tree-sitter parse, embedding, DB writes, sweep) is visible in the logs instead of inferred. This is delivery-sequence item 1 of 7 in epic #110 (Indexer performance) — it is deliberately measurement-only so #104/#106/#107/#108 have real numbers to route work against, not guesses.

Design

• New indexer/timing.py — a PhaseTimer accumulator carried ambiently via a ContextVar (mirrors the existing _repo_ctx/RepoLogFilter idiom in job.py), plus a single module-level clock seam (_CLOCK = time.monotonic) that every asserted duration reads. record() is a no-op when no timer is installed, so store.py's index_repo stays callable directly with no timer in sight (as tests/integration/test_store.py's non-timing tests already do).
• indexer/job.py — _index_one_branch times resolve/download/extract/parse/embed/db/sweep and emits one new phase timing <repo>@<branch>: total=…s resolve=…s download=…s extract=…s parse=…s embed=…s db=…s sweep=…s other=…s INFO line per indexed branch (skipped/failed/conflicted branches emit none). All nine fields are always present in a fixed order — no format drift between semantic-on and semantic-off runs. Two hard problems solved rather than avoided:
  • Parse time is fused inside the DB transaction window (items stream lazily through index_repo for bounded memory) — a _timed_items generator wrapper charges only item production to parse, never materializing the generator, so db can subtract exactly the parse (and sweep) time that accrued during that window.
  • sweep runs inside store.py, behind a frozen IndexCounts return type — rather than changing that seam (which would force every existing index_fn test fake to change), the sweep call site is wrapped with the same ambient timer, crossing modules with zero signature change.
  • total= is measured from a new branch-scoped clock read, not the pre-existing repo-scoped started parameter (reusing that would make total repo-cumulative for branch 2+ of a multi-branch repo).
  • embed is recorded in a finally so a downed embedder's degrade path still reports the time it burned.
• indexer/store.py — wraps the existing _sweep_membership(...) call site with a timing record. No signature change, no new log line (an existing test pins exactly one indexer.store log record).
• Repo-level costs outside every branch's total (default-branch HEAD resolve, paginated branch listing) are appended as resolve=/list= to the existing per-repo finished line.
• docs/runbooks/indexing-parallelism.md §2 and indexer/AGENTS.md updated per AC4 (dominant-phase → epic-issue routing table, caveats on embed=/db=/other=).

Full design rationale, the two-round critic review, and every acceptance-criteria mapping: .omc/plans/issue-103/approved-plan.md.

Invariants preserved

• No IndexCounts field change, no new dependency.
• INDEX_SEMANTICS_VERSION not bumped — test_semantics_version_tripwire.py watches only symbols.py/parse.py/languages.py, none of which are touched.
• index_repo's transaction shape (one conn.begin(), same statement order) is unchanged.
• Redaction posture unchanged — the new timing line carries only repo, branch, and durations (anchored regex test asserts this exhaustively).

Test plan

20 new tests (19 unit + 1 integration) covering every acceptance criterion, the ContextVar leak/reset hazard across branches and reused worker threads, the parse/db/sweep window arithmetic, and the semantic-off no-format-drift requirement. See .omc/plans/issue-103/approved-plan.md §6 for the full per-test rationale.

An independent review pass (fresh code-reviewer subagent, separate context from implementation) found one real coverage gap — two fake iter_source_files monkeypatches paid their simulated cost at call time instead of during iteration (it's a generator function), which meant they couldn't actually distinguish a correct wrap from a mis-scoped one. Fixed by making both fakes generators that advance the clock per yielded item. Also fixed: a runbook sample whose fields didn't sum to its stated total, a stale sibling log-line example missing its branch name, a dead/misleading PhaseTimer(clock=...) constructor parameter, a redundant assertion with a latent flake risk, and an asymmetric sweep window subtraction in the db= arithmetic (only parse was windowed; sweep used its running total, which is correct today only because sweep has exactly one call site — made symmetric for when #104/#105/#106 land on the same files).

make lint — green

uv run ruff check . && uv run ruff format --check . && uv run mypy app indexer webui
All checks passed!
134 files already formatted
Success: no issues found in 36 source files

make test — green, 1157 passed

uv run pytest -m "unit or observability"
...
========== 1157 passed, 245 deselected, 1 warning in 96.46s (0:01:36) ==========

Includes all 19 new unit tests (tests/unit/test_timing.py T13–T14; tests/unit/test_job.py T1–T12, T16–T20) plus the full pre-existing regression surface (test_job.py, test_job_redaction.py, test_semantics_version_tripwire.py) passing unmodified.

make test-integration — run locally against real Postgres, honest results below

CI caveat (stated per plan §8.3): this repo's ci-lakebase.yml job runs the integration suite against an ephemeral Lakebase branch, which is unprovisioned repo-wide — it has not been a real gate on any recent PR. The actual integration evidence for this PR comes from running make test-integration locally against a pgvector/pgvector:pg16 container (codesearch-pg, PGHOST=localhost PGUSER=codesearch PGDATABASE=codesearch):

= 8 failed, 191 passed, 1157 deselected, 3 xfailed, 2 xpassed, 3 warnings, 41 errors in 21.72s =

All 8 failures + 41 errors are a pre-existing environment gap, not caused by this change: vanilla pgvector/pgvector:pg16 doesn't have the lakebase_tokenizer/lakebase_ann/lakebase_bm25 Lakebase-beta Postgres extensions, so anything touching Alembic migration 0004+, reconciliation, semantic RRF ranking, the chunk-writer path, or semantic webui endpoints errors at fixture setup — this is documented as a known local-environment limitation independent of any code change. Confirmed by re-running the three non-obviously-extension-related failures (test_commit_search.py ×2, test_mcp_server.py::test_streamable_http_tools_and_health) against the unmodified base branch (origin/integration/indexer-performance) in a scratch worktree — they fail identically there, proving they predate this diff.

tests/integration/test_store.py — the module this PR actually touches, including the new test_index_repo_records_the_sweep_phase (T15) — is fully green (22 passed), run both before and after the independent-review fixes.

Acceptance criteria

AC	Status
AC1 — per-phase durations for every indexed branch, [%(repo)s]-attributable	T1, T3–T10, T14–T20
AC2 — semantic-off omits/zeroes embed, no format drift	T2 (+ T1/T12's anchored regex)
AC3 — no IndexCounts change, no new deps, negligible overhead	T11, T12, T13
AC4 — runbook §2 updated with the new line shape + dominant-phase procedure	docs/runbooks/indexing-parallelism.md

Epic-drift check

Read gh issue view 110 — the epic already anticipates this issue and states its findings are "code-derived, to be confirmed by #103." No epic edit required; confirming those numbers is a later production run, not this PR.

Integration-branch notes

• Base and target are integration/indexer-performance (not master), per the operator override recorded in .omc/plans/issue-103/approved-plan.md §3.
• Umbrella PR Indexing performance integration arc (#110) #111 (integration/indexer-performance → master) is left untouched and remains draft.
• This is delivery-sequence item 1 of epic [Epic] Indexer performance: delta indexing, batched writes, streaming ingest #110 — landing it first is intentional; indexer/timing.py is additive so indexer: file-level delta indexing keyed on (path, content_sha) #104–indexer: process-pool symbol/edge extraction #108 extend it rather than conflict with it.

[IceRhymers]

[LOW] The timing arithmetic and this logger.info sit inside the try: whose except Exception reclassifies the branch as failed -- after index_repo already committed.

indexer/timing.py states the principle: "Instrumentation must never be able to fail the work it measures." record() honours it. This block does not: the db = max(...) / total = ... / other = max(...) computation and the logger.info above all live under the except Exception: logger.exception(...); return BranchOutcome(status="failed") handler ~40 lines down.

If anything in here raised, the consequence is not a missing log line -- it is:

• a branch whose transaction already committed reported as failed,
• run() returning exit code 1,
• and _decide_reconciliation gating off (it requires zero failures), so the whole runs desired-state reconciliation is skipped.

That is a much larger blast radius than the measurement is worth.

I could not find a reachable way to trigger it -- timer.total() is a dict.get with a default, the arithmetic is float-only, and logging formats lazily and routes any formatting error through handleError rather than raising. So confidence that this is currently exploitable: LOW. Im flagging it as a structural note rather than a live bug.

Cheap hardening if you want the principle to hold structurally rather than incidentally: compute and emit inside a try/except Exception: logger.warning("phase timing unavailable for %s@%s", name, branch, exc_info=True), or hoist the whole block into a small _log_phase_timing(...) helper that swallows its own errors. Either keeps a measurement bug from ever costing a committed branch its indexed status.

[IceRhymers]

Acknowledged, leaving as-is for this PR. The timing arithmetic uses only max(0.0, ...) float subtraction and a fixed-format logger.info call, so the realistic failure surface is very small, and moving the emission outside the try/inside a broader restructure would touch control flow that went through two rounds of critic review for its current shape. If a reviewer wants this hardened (e.g. a narrower try/except around just the emission that logs a warning without flipping status to failed), happy to take it as a fast follow rather than block this PR on it.

[IceRhymers]

Review: fresh skeptical pass (independent of the pre-PR reviewer)

Read timing.py, job.py, store.py and all ~20 new tests in full, re-derived the phase arithmetic from source, and independently re-ran the gates. I did not take the PR description's claims on trust — the notes below say what I verified and how.

Verdict: COMMENT — no blocking issues. 4 findings, none CRITICAL/HIGH, none in the arithmetic that #104–#108 will route work against.

---

Independently re-run gates

Gate	Result
uv run ruff check .	All checks passed!
uv run mypy app indexer webui	Success: no issues found in 36 source files
pytest tests/unit/test_timing.py tests/unit/test_job.py	107 passed
pytest -m "unit or observability" tests/	1157 passed, 245 deselected

---

The five things I was most suspicious of

1. ContextVar leak/reset discipline under the real ThreadPoolExecutor — correct.
install_timer → try → finally: reset_timer(token) are all on one thread with no context switch between them, so the Token is never reset in a foreign Context (which would be a ValueError). _index_one_branch is never submitted to a pool itself — run() fans out at repo granularity (job.py:443) and _index_one_inner walks branches sequentially (job.py:936) — so exactly one timer is live per thread at a time. _timed_items is a plain generator, which shares the caller's context rather than getting its own, so the sweep record() inside index_repo lands on the right timer. No lock is needed and none is claimed.

2. db=/parse=/sweep=/other= window arithmetic — I re-derived it and it is right, including the semantic path.
Substituting db = db_wall − parse_during − sweep_during into the other expression collapses to other = total − resolve − download − extract − parse_eager − embed − db_wall, i.e. exactly the wall clock outside every instrumented region (tempdir teardown, disk pre-flight, skip-seam lookup). No double counting of the eager list(iter_source_files(root)) walk, because db subtracts only the windowed parse delta while other subtracts the phase total. The symmetric sweep_before windowing is genuinely load-bearing for a future second sweep call site, not just cosmetic symmetry — worth keeping.
T17 (test_other_is_the_exact_unattributed_residual) pins this properly: it drives distinct powers of two (1/2/4/8/16/32/64) through all seven phases, requires other == 0.00, then re-runs with a deliberately uninstrumented advance inside assert_disk_headroom and requires other == 9.00 exactly. That is a real residual test, not the total == sum(phases) + other tautology it explicitly calls out and avoids.

3. AC2 (no format drift semantic-on/off) — genuinely holds.
One format string, zero conditionals, all nine fields always emitted, %.2fs throughout; a phase that never ran prints 0.00s rather than vanishing. Confirmed by reading job.py:1173–1188 and by T2's assert list(on) == list(off). The anchored _TIMING_RE (^…$) additionally pins field set, field order, separator, and the redaction posture.

4. IndexCounts untouched and store.py adds no logger call — confirmed by reading, not by trusting make test.
store.py's diff is exactly +from indexer.timing import now, record, +sweep_started = now(), +record("sweep", now() - sweep_started) and a comment block. record() is dict accumulation with no logging import anywhere in timing.py. IndexCounts is unchanged in languages.py (and T11 adds a dataclasses.fields tripwire).
On the specific question of test_records_from_other_modules_inherit_the_repo_context: it cannot break, for two independent reasons — (a) it injects _logs_elsewhere as index_fn, so the real index_repo (and therefore the sweep hook) never executes at all, and (b) even if it did, record() emits no LogRecord. Its assert len(foreign) == 1 is safe.

5. Test quality — strong overall, one real gap (see the line comment on T10).
T17 and T5 are the standouts. The two generator-based fakes the earlier reviewer asked for are genuinely in place (_slow_walk and _iter_source_files both for … in real(...): clock.advance(...); yield), so they now discriminate a correctly-scoped wrap from a call-time one. The fake-clock discipline (_CLOCK is a process-wide global, so every multi-repo fake-clock test pins index_concurrency=1) is applied consistently — I checked all nine fake-clock tests.

---

Findings (4, all line-anchored)

#	Sev	Conf	Where	What
1	MEDIUM	HIGH	tests/unit/test_job.py:2627	T9/T10 claim to guard the finally: reset_timer(...); empirically they do not — neutering reset_timer leaves both green. The only thing that catches it is order-dependent cross-module ContextVar pollution into test_timing.py.
2	LOW	HIGH	docs/runbooks/indexing-parallelism.md:120	Sample log block is arithmetically impossible: finished … in 213.55s (resolve=0.42s) vs total=213.32s → 0.42 + 213.32 = 213.74 > 213.55. started is taken before resolve_ref on the same monotonic clock, so elapsed ≥ resolve + list + Σ(branch totals) is a hard invariant.
3	LOW	HIGH	indexer/timing.py:20	Docstring covers thread reuse but not thread/process creation: the ambient timer will silently no-op inside any pool #107 or #108 spawns. Worth two lines here since this module is their foundation.
4	LOW	LOW	indexer/job.py:1173	The timing arithmetic + logger.info are inside the try: whose except Exception marks the branch failed — after index_repo committed. Not reachable today (dict .get, float math, lazy log formatting), but it contradicts timing.py's own "instrumentation must never fail the work it measures".

Finding 1 is the only one I'd want addressed before this becomes the base for #104–#108, and it's a test-side change, not a code change.

Verified as genuinely fixed from the pre-PR review pass

Checked each rather than assuming: generator-based iter_source_files fakes ✅ · runbook phase timing sample now sums exactly to total=213.32 ✅ · skipped acme/gadgets@main sibling example carries its branch ✅ · no PhaseTimer(clock=...) ctor parameter ✅ · symmetric sweep_before windowing in the db= subtraction ✅.

Also verified

• Runbook's dominant-phase → epic-issue routing table is accurate against live issue titles (#104 delta indexing, #105 batched writes, #106 single-pass ingest, #107 concurrent embedding, #108 process-pool extraction).
• The finished line format change has no consumers outside docs and tests — grepped .py/.md/.yml/.yaml/.sql/.json/.ts/.tsx.
• embed in a finally really does report the downed-embedder degrade path (T19), and skipped/failed/conflicted branches really emit no line (T6/T7/T20).

Positive observations

• Choosing the ambient-ContextVar route over widening the index_fn seam is the right call and is argued from the actual constraint (frozen IndexCounts compared by value + every existing fake would need a parameter), not from convenience.
• Measuring total from a fresh branch-scoped clock read instead of the repo-scoped started is a subtle trap avoided, and T9 pins it.
• Emitting the line after the TemporaryDirectory teardown so a multi-GB rm -rf lands in other rather than nowhere is a detail most instrumentation PRs get wrong.
• The runbook's four "fields that need interpretation" caveats (resolve=0.00s on default branches, embed= spanning chunking, db= excluding parse/sweep, non-semantic walk inside the transaction) are exactly the misreadings an operator would otherwise make.

Not approving — leaving that to the operator per the review request.