indexer: per-phase timing instrumentation (#103)

docs/runbooks/indexing-parallelism.md

@@ -116,8 +116,9 @@ loop, third-party libraries) carry `-`.
 ```
 INFO indexer.job [-]: local disk at /tmp: 41.2 GB free of 64.0 GB total; 4 worker(s) x 2.5 GB peak
 INFO indexer.fetch [acme/widgets]: ...
-INFO indexer.job [acme/widgets]: finished acme/widgets in 71.30s
-INFO indexer.job [acme/gadgets]: skipped acme/gadgets: already indexed at abc123 (semantics v1) in 0.41s
+INFO indexer.job [acme/widgets]: phase timing acme/widgets@main: total=213.32s resolve=0.00s download=12.10s extract=8.40s parse=31.00s embed=88.20s db=64.50s sweep=0.30s other=8.82s
+INFO indexer.job [acme/widgets]: finished acme/widgets in 213.74s (resolve=0.42s list=0.00s)
+INFO indexer.job [acme/gadgets]: skipped acme/gadgets@main: already indexed at abc123 (semantics v1) in 0.41s
 ```
 
 **To find the giant:** grep for `finished .* in` and sort by the elapsed number.
@@ -130,6 +131,59 @@ accept the duration.
 line against the sum of the per-repo elapsed times. If the total is already
 close to the slowest single repo, the pool is not the bottleneck.
 
+### 2.1 Finding the dominant phase, not just the dominant repo
+
+Every **indexed** branch emits one `phase timing` line accounting for its entire
+wall clock. Skipped, failed, and conflicted branches emit none — there is nothing
+to attribute.
+
+```
+grep 'phase timing' run.log            # one line per indexed branch
+```
+
+The nine fields are fixed, always present, always in this order, always `%.2fs`.
+A phase that did not run prints `0.00s` rather than disappearing, so the line
+never changes shape between a semantic-on and a semantic-off run and every grep
+you write keeps working. Read the largest field; that is the branch's bottleneck.
+
+| Dominant phase | What it means | Which issue addresses it |
+|---|---|---|
+| `download` / `extract` | archive I/O bound | #106 (single-pass in-memory ingestion) |
+| `parse` | GIL-bound tree-sitter extraction | #108 (process-pool extraction) |
+| `embed` | serial AI Gateway round trips | #107 (concurrent embedding) |
+| `db` | per-file round trips | #105 (batched writes) |
+| any of the above, on **unchanged** content | redundant work | #104 (file-level delta indexing) |
+
+Four fields need interpretation before you act on them:
+
+- **`resolve=0.00s` on a default branch is expected, not a bug.** That branch's
+  HEAD SHA came from the repo-level resolve, which happens once per repo outside
+  every branch's total and is reported on the repo's `finished` line as
+  `resolve=`. The `list=` on the same line is the branch-listing API call, which
+  is `0.00s` unless the repo has `branches:` globs configured (it is not called
+  at all otherwise) and which is paginated — on a monorepo with hundreds of
+  branches it is a real, and otherwise invisible, cost. The elapsed value in
+  `finished … in Xs` is measured on its own clock and is deliberately not
+  reconciled against the parenthesised numbers.
+- **`other=` is the unattributed residual**, `total` minus every measured phase,
+  clamped at zero. It is dominated by the temp-dir teardown — an `rm -rf` of a
+  freshly extracted multi-GB tree — plus the pre-flight disk check. It exists so
+  the line has no silently missing time; a large `other` means something real is
+  happening outside every instrumented phase and is worth chasing.
+- **`embed=` covers chunking as well as the network.** It spans `iter_chunks`
+  (CPU/GIL-bound) *and* the serial AI Gateway round trips. #107 addresses only
+  the round trips, so before routing work there, confirm the phase is
+  network-bound rather than chunking-bound (a follow-up may split it into
+  `chunk=`/`embed=`).
+- **`db=` excludes parse and sweep, but the walk still happens inside the
+  transaction.** Files stream lazily through `index_repo`'s open transaction for
+  bounded memory, so file production is timed separately and subtracted from
+  `db`; the sweep is subtracted too. On the **non-semantic** path, though, the
+  directory walk itself materializes inside that open transaction (`parse.py`'s
+  `rglob`, on the first item). That is long-standing behavior which this
+  instrumentation merely makes visible for the first time — it is not a new
+  regression.
+
 ---
 
 ## 3. The three limits, and why raising concurrency is a bad trade

indexer/AGENTS.md

@@ -14,13 +14,14 @@ The serverless indexing job (`code-search-index`, wired as a `python_wheel_task`
 | `chunk_store.py` | `write_chunks`: delete-and-reinsert one file's rows in the `chunks` table (no natural key). Takes a live `Connection`; never opens an engine, never calls the embedder — vectors arrive precomputed. No `repo_id` parameter: `chunks` is scoped by `file_id` only. |
 | `fetch.py` | All GitHub HTTP: paginated org/user repo enumeration (`RepoMeta`), branch listing, `resolve_ref`/`resolve_branch_head` (branch name -> immutable SHA), streamed tarball download capped at `MAX_TARBALL_BYTES` (500 MB), safe extraction (`filter="data"`, bomb check) capped at `MAX_EXTRACTED_BYTES` (2 GB), `assert_disk_headroom` (2.5 GB per worker, both caps alive at once). `RateLimitError` is deliberately narrow: 429 always; 403 only with `Retry-After` or `X-RateLimit-Remaining: 0` — other 403s are permission failures. |
 | `hashing.py` | `content_sha`: canonical SHA-256 hex of content (`None` -> empty string). Single source of truth for `files.content_sha`; must stay byte-identical to the `0003` migration's SQL backfill forever or cross-branch dedup silently breaks (`tests/integration/test_content_sha_parity.py` is the gate). |
-| `job.py` | Entry point and orchestration: `main()`/`run()`, `ThreadPoolExecutor` sized by `effective_workers` (unit of work = one repo, all branches sequential), batched `repo_branches` stamp read, per-branch skip-if-unchanged, per-branch `BranchOutcome` classification (`indexed`/`skipped`/`conflict`/`failed`), semantic precompute (`_precompute_chunk_writer`), `ContextVar`-based `[repo]` log attribution. Returns 1 if any branch failed; conflicts self-heal and do not fail the run. **Reconciliation checkpoint**: after every worker joins, `_decide_reconciliation` gates on zero failures/conflicts, every repo accounted for, and every repo's `discovery_complete`; on a pass, `_reconcile` reuses the pre-fan-out stamp snapshot to compute each repo's retired branches and the run's full desired repo set, then calls the injected `reconcile_retired_fn`/`reconcile_removed_fn` seams (default: the real `indexer.store` primitives) on one post-fan-out connection — retired branches first, repo purge second. `MAX_PURGE_SHRINK_FRACTION = 0.5` (hardcoded, no config knob) withholds ONLY the purge, as a logged incident signal, if it would remove a strict majority of currently stored repos; retired-branch cleanup on survivors still applies. `ReconcileProgress.committed_any` drives an honest "partially reconciled" vs "left stale" failure message — never the raw exception, only its phase/repo/type name. Never called from worker-thread code (`_index_one*`) — a source-level tripwire test enforces it. |
+| `job.py` | Entry point and orchestration: `main()`/`run()`, `ThreadPoolExecutor` sized by `effective_workers` (unit of work = one repo, all branches sequential), batched `repo_branches` stamp read, per-branch skip-if-unchanged, per-branch `BranchOutcome` classification (`indexed`/`skipped`/`conflict`/`failed`), semantic precompute (`_precompute_chunk_writer`), `ContextVar`-based `[repo]` log attribution, and per-phase timing instrumentation (one `phase timing repo@branch: total=… resolve=… download=… extract=… parse=… embed=… db=… sweep=… other=…` INFO line per INDEXED branch, emitted from inside the worker so `[repo]` resolves; fixed unconditional field set; `_timed_items` charges lazy item production to `parse` so it is not fused into `db`; `resolve=`/`list=` on the per-repo `finished` line carry the repo-scoped costs that belong to no branch's total). Returns 1 if any branch failed; conflicts self-heal and do not fail the run. **Reconciliation checkpoint**: after every worker joins, `_decide_reconciliation` gates on zero failures/conflicts, every repo accounted for, and every repo's `discovery_complete`; on a pass, `_reconcile` reuses the pre-fan-out stamp snapshot to compute each repo's retired branches and the run's full desired repo set, then calls the injected `reconcile_retired_fn`/`reconcile_removed_fn` seams (default: the real `indexer.store` primitives) on one post-fan-out connection — retired branches first, repo purge second. `MAX_PURGE_SHRINK_FRACTION = 0.5` (hardcoded, no config knob) withholds ONLY the purge, as a logged incident signal, if it would remove a strict majority of currently stored repos; retired-branch cleanup on survivors still applies. `ReconcileProgress.committed_any` drives an honest "partially reconciled" vs "left stale" failure message — never the raw exception, only its phase/repo/type name. Never called from worker-thread code (`_index_one*`) — a source-level tripwire test enforces it. |
 | `languages.py` | Single source of truth shared by `parse.py` and `symbols.py`: `EXT_TO_LANG` (8 extensions -> tree-sitter language names), `SYMBOL_KINDS` (node type -> symbol kind per language), `EDGE_NODE_KINDS` (node type -> reference-edge kind per language, Python-only until #85), `MAX_FILE_BYTES` (1 MB), `SEMANTIC_CHUNK_MAX_CHARS` (2000, ~4 chars/token), and the frozen dataclasses `ParsedFile`, `Chunk`, `ExtractedSymbol`, `ExtractedEdge`, `FileExtraction`, `IndexCounts` (now carries `edges`). |
 | `parse.py` | `iter_source_files`: walk an extracted tree, yield every text file (unknown extensions kept with `lang=None`, since grep runs over all files); skips `.git/`, symlinks, files > `MAX_FILE_BYTES` (stat before read), NUL-sniffed binaries, and UTF-8 decode failures; strips surviving NULs (Postgres `text` rejects them). `iter_chunks`: deterministic line-aligned chunking, no overlap, no mid-line splits, 1-based inclusive line ranges. |
 | `repo_config.py` | Pydantic schema for `config.yaml` (`RepoConfig` / `GitHubConnection` / `ExcludeRules`), `normalize_repo` (URL/SSH/bare -> canonical `org/repo`, GitHub hosts only), `parse_config` (pure) vs `read_workspace_config` (SDK I/O, wraps every failure in `ConfigError` with HTTP status so 404 "never synced" stays distinguishable from 403 "no permission"), and `effective_workers` (the semantic clamp). A connection with no `orgs`/`users`/`repos` fails validation. `index_concurrency`: 1-8, default 4 — a disk bound (2.5 GB peak per worker), not a CPU one. `semantic_max_chunks_per_repo`: optional top-level `{"org/repo": N}` map overriding `app.config.Settings.semantic_max_chunks_per_repo` per repo; keys canonicalised via `normalize_repo` and rejected on collision post-casefold, values `>= 1`. Deliberately import-light: pydantic + PyYAML + stdlib only. |
 | `resolve.py` | `resolve_repos`: enumerate org/user selectors, apply `ExcludeRules` to enumerated repos only (explicit `repos` entries always win, unfiltered), dedup case-insensitively keeping first-seen spelling, union each connection's `branches:` globs into per-repo `RepoEntry.branch_globs`, then fail fast: `EmptyConfigError` on zero repos (indexing nothing must not exit 0), `RepoCeilingError` above `MAX_REPOS` (500, overridable via `--max_repos`). Also matches `RepoConfig.semantic_max_chunks_per_repo` case-insensitively onto each resolved repo's `RepoEntry.semantic_max_chunks` (`None` if unmatched); an override key matching no resolved repo logs a WARNING (typo guard). Enumerator params are a test seam only, not provider dispatch. |
-| `store.py` | `index_repo`: the single atomic unit of work for one (repo, branch) inside `with conn.begin():` — repos upsert, `repo_branches` CAS-baseline read, per-file array-union upsert on `(repo_id, path, content_sha)` with branch-membership union, delete-and-reinsert `symbols` AND `reference_edges` (both keyed only by `file_id`, no natural key), optional `chunk_writer` call, membership sweep (strip this branch from unseen rows, delete rows with empty `branches`; skipped with a WARNING on an empty seen-set), then CAS stamp (raises `StaleIndexError` on mismatch, rolling everything back). `items` is `Iterable[tuple[ParsedFile, FileExtraction]]`; the `reference_edges` delete runs unconditionally, even when a file's `FileExtraction.edges` is empty, so stale rows never survive a re-index. Pure DML, no TEMP tables (job role has no TEMP privilege on Lakebase). `reconcile_retired_branches` and `reconcile_removed_repos`: the desired-state storage primitives `job.py`'s reconciliation checkpoint calls — each its own `conn.begin()`, repo-scoped membership subtraction (never delete-by-path) and an exact-match repo purge respectively; neither decides WHAT is retired/desired, only applies a caller-supplied set (see `job.py`'s row). |
+| `store.py` | `index_repo`: the single atomic unit of work for one (repo, branch) inside `with conn.begin():` — repos upsert, `repo_branches` CAS-baseline read, per-file array-union upsert on `(repo_id, path, content_sha)` with branch-membership union, delete-and-reinsert `symbols` AND `reference_edges` (both keyed only by `file_id`, no natural key), optional `chunk_writer` call, membership sweep (strip this branch from unseen rows, delete rows with empty `branches`; skipped with a WARNING on an empty seen-set), then CAS stamp (raises `StaleIndexError` on mismatch, rolling everything back). `items` is `Iterable[tuple[ParsedFile, FileExtraction]]`; the `reference_edges` delete runs unconditionally, even when a file's `FileExtraction.edges` is empty, so stale rows never survive a re-index. The sweep call site is wall-clocked into `indexer.timing`'s ambient `PhaseTimer` (`record("sweep", …)`) — never into `IndexCounts` (frozen, compared by value) and never through a new `index_repo` parameter (that signature is an injected seam); `store.py` emits **no** log record for it. Pure DML, no TEMP tables (job role has no TEMP privilege on Lakebase). `reconcile_retired_branches` and `reconcile_removed_repos`: the desired-state storage primitives `job.py`'s reconciliation checkpoint calls — each its own `conn.begin()`, repo-scoped membership subtraction (never delete-by-path) and an exact-match repo purge respectively; neither decides WHAT is retired/desired, only applies a caller-supplied set (see `job.py`'s row). |
 | `symbols.py` | `extract_file` (#84): one tree-sitter parse, one full-tree walk, emitting both `symbols` and `reference_edges` candidates (`FileExtraction`) in the same pass — nested definitions captured, named nodes only for symbols, kinds from `SYMBOL_KINDS`/`EDGE_NODE_KINDS`, 1-based lines. Stack entries carry the innermost named enclosing definition so edges attribute to it in O(1) with no second walk. `extract_symbols` is a thin wrapper (`extract_file(pf).symbols`) kept for the existing call sites. Python-only edge helpers (`_python_call_target`, `_python_import_edges`) are the seam #85 generalizes to other languages. Parser cache is per-thread (`threading.local`) as insurance against a future GIL-releasing `parse()`. |
+| `timing.py` | Per-phase wall-clock accounting for one branch (#103). `PhaseTimer` accumulates `phase -> seconds`; `install_timer`/`reset_timer`/`current_timer` carry one ambiently in a `ContextVar` (the same idiom as `job.py`'s `_repo_ctx`, for the same cross-module attribution problem); `record(phase, seconds)` is a **no-op when no timer is installed and never raises**, so `index_repo` stays callable directly. `_CLOCK` (default `time.monotonic`) is the single clock source every asserted duration reads — via `now()`, or via `PhaseTimer.clock` captured at construction — and is the seam tests patch; never read `time.monotonic()` directly for a number that appears on those lines. Stdlib only. |
 
 ## For AI Agents
 
@@ -38,7 +39,7 @@ The serverless indexing job (`code-search-index`, wired as a `python_wheel_task`
 - **Import discipline**: `repo_config.py` stays import-light (no httpx/SQLAlchemy/SDK at module level); `normalize_repo` is imported from `repo_config`, never from `job` (import cycle); `app.embed`'s databricks-sdk dependency is only imported when semantic is on.
 
 ### Testing Requirements
-- `make test` (`pytest -m "unit or observability"`, no external deps): `tests/unit/test_branches.py`, `test_chunk_store.py`, `test_chunking.py`, `test_edges.py`, `test_fetch.py`, `test_job.py`, `test_job_redaction.py`, `test_languages.py`, `test_parse.py`, `test_repo_config.py`, `test_resolve.py`, `test_symbols.py`, `test_store_chunk_writer.py`, `test_semantics_version_tripwire.py`.
+- `make test` (`pytest -m "unit or observability"`, no external deps): `tests/unit/test_branches.py`, `test_chunk_store.py`, `test_chunking.py`, `test_edges.py`, `test_fetch.py`, `test_job.py`, `test_job_redaction.py`, `test_languages.py`, `test_parse.py`, `test_repo_config.py`, `test_resolve.py`, `test_symbols.py`, `test_store_chunk_writer.py`, `test_semantics_version_tripwire.py`, `test_timing.py`.
 - `make test-integration` (needs Postgres): `tests/integration/test_store.py`, `test_store_chunk_writer.py`, `test_content_sha_parity.py` (the hard gate on `hashing.py` vs the migration backfill), `test_reconcile.py` (the `reconcile_retired_branches`/`reconcile_removed_repos` storage primitives directly), and `test_job_reconcile.py` (#59: the real `run()` end to end — real primitives, real engine, only GitHub HTTP faked).
 - Schema tests must stay fast: changes to `repo_config.py` must not add heavy imports.