perf: per-ident `:introduced-by` / lineage point queries are 1.33M graph reads — 33.6% of ingestion wall clock

[adityamukho]

Summary

With #236's rowid delete landed, _retract is no longer the bottleneck: it fell from
4,137.8 s / 73.5% of the run to 32.7 s / 2.1%. The new dominant cost is
graph read queries: _db_execute on (query ...) is 1,328,250 calls costing
523.0 s — 33.6% of a 1,558.6 s run.

91% of that sits in two call sites, and both issue the same shape of query — a
single-entity point lookup, one entity at a time, in a loop over every candidate ident
of every file of every commit:

[:find ?c :where [<ident> :introduced-by ?c]]

This is the facts_dedup story again in a different table: a per-item lookup issued in a
loop where a set-at-a-time form is available, and the codebase already contains the
preload pattern that fixes it (_preload_provisional_idents, whose own docstring says it
exists because "this set is consulted where a per-ident check is too expensive").

Measurements

Full instrumented at-scale ingestion of this repo, master, 568 commits, 1,558.61 s,
inclusive/exclusive per-function attribution. Reproduced across three runs of the same
build — plain 1,600.55 s, leaf-instrumented 1,622.50 s, inclusive/exclusive 1,558.61 s
(±2%).

D1 — where the 1,558.61 s goes (exclusive, no double-counting)

component	calls	seconds	% of run
_db_execute (query ...)	1,328,250	523.02	33.6%
_forward_apply own Python (incl. _build_code_triples)	568	369.70	23.7%
_reverse_apply own Python	284	162.22	10.4%
_db_execute (retract ...)	88,917	21.81	1.4%
_db_execute (transact ...)	10,191	9.93	0.6%
fact_index.delete_facts (234,928 triples)	88,902	8.79	0.6%
_lineage_is_provisional own code	603,486	5.08	0.3%
_correction_sweep_apply own Python	284	4.82	0.3%
fact_index.insert_facts (314,091 triples)	10,191	3.42	0.2%
_entity_introduced_by_query own code	464,377	3.88	0.2%
_resolved_facts_triples	99,108	1.70	0.1%
all other wrapped functions	—	1.97	0.1%
attributed total		1,117.14	71.7%
unattributed (_extract_commit on the process pool, _run_ingestion orchestration, thread hops)		441.47	28.3%

Stage A 623.25 s (40.0%), Stage B 933.88 s (59.9%).

D2 — the 1.33M queries, by calling function

query call site	count	seconds	% of run	avg
_correction_sweep_apply (inline :introduced-by + :modified-in)	258,074	255.48	16.4%	0.99 ms
_entity_introduced_by_query (from _reverse_apply)	464,377	215.44	13.8%	0.46 ms
_lineage_is_provisional	603,486	50.28	3.2%	0.08 ms
everything else combined	2,313	1.82	0.1%
total	1,328,250	523.02	33.6%

The first two are 30.2% of the entire run on their own.

D3 — what #236 actually bought

	before (553 commits, 5,627 s)	after (568 commits, 1,558.6 s)
all _retract	79,414 calls / 4,137.8 s / 73.5%	88,917 calls / 32.7 s / 2.1%
avg per _retract	52.1 ms	0.37 ms
fact_index.delete_facts	(not separated; ~all of the above)	8.79 s / 0.6%
_entity_introduced_by_set_provisional_batch retract	204 calls / 2,181.4 s / 38.8%	208 calls / 6.79 s / 0.4%
_correction_sweep_apply retract	72,971 calls / 1,629.1 s / 29.0%	82,210 calls / 21.5 s / 1.4%

Wall clock: 5,133.19 s → 1,600.55 s against the plain harness, i.e. 20.3x the 78.87 s
forward-only baseline, down from 65x.

The code

mcp_server.py:8967-9001, inside _correction_sweep_apply's per-file loop:

for ident in candidate_idents:
    raw = _db_execute(db, f"(query [:find ?c :where [{ident} :introduced-by ?c]])")
    ...
    if _lineage_is_provisional(db, ident):        # a second point query
        ...
    else:
        raw2 = _db_execute(db, f"(query [:find ?c :where [{ident} :modified-in ?c]])")

mcp_server.py:7914-7942, inside _reverse_apply's per-file loop — the same ident is
queried up to twice per pass:

known_before = {ident: "known" for ident in candidate_idents
                if _entity_introduced_by_query(db, ident) is not None}
...
for ident in set(candidate_idents) & known_before_snapshot:
    if _lineage_is_provisional(db, ident):
        superseded_ident = _entity_introduced_by_query(db, ident)
    else:
        already_authoritative_touched.append((ident, _entity_introduced_by_query(db, ident)))

_entity_introduced_by_query (mcp_server.py:5378) and _lineage_is_provisional
(mcp_server.py:5210) are both one-line single-entity _db_execute wrappers with no
caching.

Suggested direction

The set-at-a-time precedent already exists in this file: _preload_known_deps,
_preload_provisional_idents, _preload_known_entities, and
_rebuild_index_from_graph's ident_map all bind ?e as an output variable and
retrieve the whole relation in one query.

The design question this needs to answer is cache maintenance, not whether the batch
query works. :introduced-by is written during the run by the very walks that read
it, so a run-start snapshot goes stale — unlike state.provisional_idents, which is
already a preload snapshot precisely because its staleness is tolerable there and
_forward_apply documents at length (mcp_server.py:8306-8356) that it is "not the
authority". The writers are bounded and enumerable:

• _entity_introduced_by_set_provisional_batch (mcp_server.py:5457-5458)
• _re_date_structural_facts' supersede path (mcp_server.py:5568)
• _build_code_triples (mcp_server.py:6677-6736), via _forward_apply/_reverse_apply
• _forward_apply's external-entity path (mcp_server.py:8586)

so a write-through in-run cache is feasible. Whether it should be that, or a per-commit
batch query scoped to the commit's candidate idents, is a spec decision — the per-commit
form avoids the staleness problem entirely at the cost of one query per commit over
~1,200 idents, and should be measured against the write-through form before either is
built.

The three sites are not equally worth it: at 0.99 ms and 0.46 ms per call the two
:introduced-by sites carry 30.2% of the run, while _lineage_is_provisional at 0.08 ms
carries 3.2% despite being the most-called of the three. Do the first two.

What NOT to do — checked against the post-#236 numbers

Do not batch _correction_sweep_apply's case-3 :modified-in retract. #236 said this
was worthless before the rowid fix and that the post-fix table should decide it. The table
has now decided: that site is 82,210 calls costing 21.52 s — 1.4% of the run, down
from 1,629 s / 29.0%. The entire (retract ...) cost across every call site in the run is
21.81 s. Collapsing 82,210 calls into ~284 therefore has a hard ceiling of about 1.4% of
wall clock and a realistic recovery well under that. Still not worth doing — but note
the reason has changed: it is no longer "the cost follows facts, not calls", it is simply
that the whole line item is now small.

Do not target _resolved_facts_triples' _query_ident calls. #236's spec named this
as the expected largest residual inside _retract. Measured: _resolved_facts_triples is
1.70 s — 0.1% of the run, and _query_ident is never called at all during
ingestion, because it only fires for #uuid-tagged entities and every ingestion entity is
already a keyword ident. The expectation was wrong; this is a dead end.

Notes on the measurement

• Harness: parent-process monkeypatching of _transact/_retract/_db_execute and the
  main apply functions with a per-thread call stack giving inclusive and exclusive wall
  time, driving a real in-process mcp_server._run_ingestion against an isolated tempdir
  graph. Same convention as perf: reverse walk issues 3,152 transactions per commit vs forward-only's 12 (263x write amplification) #233's stage-split harness.
• Not covered: _extract_commit, which runs in ProcessPoolExecutor workers and is
  invisible to parent-process patching. It is most of the 28.3% unattributed. perf: reverse walk issues 3,152 transactions per commit vs forward-only's 12 (263x write amplification) #233
  measured it at 180 s Stage A (pipelined, hidden behind the write side) and 132 s Stage B
  (serial, directly on the critical path); nothing in perf: fact_index.delete_facts is O(index size) per triple — 73.5% of ingestion wall clock #236 changes parsing cost, so those
  carry over approximately.
• Harness overhead is bounded by the three-run spread: plain 1,600.55 s vs fully
  instrumented 1,558.61 s — the instrumented run was faster, so overhead is within
  run-to-run variance.

[adityamukho]

At-scale re-measurement: this is now the dominant cost, and it blocks other work

Surfaced while running #245's acceptance probe (--verify-fix) against full
history on this repository. Recording it here because #239's headline 33.6%
figure has a known provenance problem — it comes from the 20260803T095104Z
benchmark.md entry, produced by an ad-hoc harness in a directory that no
longer exists, which never named _db_checkpoint and left 28.3%
unattributed. That entry cannot be reconciled from artifacts, only
re-measured. This is a re-measurement, and it is far starker than 33.6%.

What was run

evals/at_scale/probe_dep_preload_exposure.py --verify-fix on branch
fix-238-245-position-exact-preload, doing a full forward ingestion of the
branch (657 commits) into a scratch graph before driving the preloads.

Result

Killed at 9.8 hours having ingested 247 of 657 commits — roughly 25
commits/hour, extrapolating to ~26 hours for the full run. For comparison the
post-#236 figure recorded in benchmark.md is 1,600.55 s for 610 commits.

The process was CPU-pegged throughout: main thread 0:18 of CPU, one
ThreadPoolExecutor worker holding 72:37 of a 72-minute sample, and all
eight parse workers idle at 0.0-0.2%. That is the "main saturated while
workers idle" signature that killed two #235 runs at 3h54m and 36m.

Where it is, by direct measurement

py-spy dump on the active thread, not inference:

_uniffi_rust_call_with_error (minigraf/minigraf_ffi/minigraf_ffi.py:293)
execute                      (minigraf/minigraf_ffi/minigraf_ffi.py:1034)
_db_execute                  (mcp_server.py:3368)
_entity_introduced_by_values_query (mcp_server.py:5683)
_entity_introduced_by_query  (mcp_server.py:5739)
_reverse_apply               (mcp_server.py:8872)

The reverse walk's per-ident :introduced-by gate, inside a single minigraf
execute. This is exactly the point-query volume #239 is about.

Why this is attributable to #239 and not to the branch it was found on

git diff master..HEAD -- mcp_server.py on that branch touches only
_preload_known_entities, _preload_known_deps, _preload_pinned_commits,
_load_ingestion_preload_state, and the helper insertion point above
_valid_time_window_clauses. _reverse_apply,
_entity_introduced_by_query and _entity_introduced_by_values_query are
untouched. The preload runs once per ingestion, not per commit, so it
cannot produce a stall 247 commits in.

Consequence for sequencing

This is no longer only a performance issue. It makes the at-scale
acceptance gate for #238/#245 unrunnable, so it now blocks correctness
verification and not just throughput. That branch is complete and its unit
and resumed-run regression tests pass; only its full-history probe run is
deferred, pending this.

Note for whoever picks this up

The standing observation on #239 still holds and this measurement sharpens
it: the real design question is cache maintenance, not the batch query —
:introduced-by is written during the run by the very walks that read it, so
any cache has to be invalidated by the writers. Note also that #238's design
spec replaced _reverse_apply's known-entity gate with a live-:ident test
(_entity_ident_is_live) for correctness reasons; the stack above shows
_entity_introduced_by_query still on that path, which is worth confirming
before designing around it.

Refs #222
Refs #245

[adityamukho]

Retraction: my previous comment was measured against the wrong minigraf

The at-scale measurement I posted above is not
valid evidence and should not be acted on. It was produced by a process
running /usr/bin/python, which on that machine carries minigraf 1.1.1,
while pyproject.toml pins minigraf>=1.2.3. The repo's own .venv has
1.2.3. The probe was launched with a bare python.

What the interpreter alone accounts for

Same machine, load ~0.9, 100k-fact fixture, 200 reps:

query	system python (1.1.1)	.venv (1.2.3)	speedup
_entity_introduced_by_query HIT	0.986 ms/call	0.144 ms/call	6.8x
_entity_introduced_by_query MISS	0.927 ms/call	0.136 ms/call	6.8x
_lineage_is_provisional HIT	1.213 ms/call	0.182 ms/call	6.7x

At 0.144 ms/call, _entity_introduced_by_query under the supported minigraf
is roughly 3x FASTER than the 0.46 ms/call this issue's own D2 table records —
not slower. The "25x regression" implied by my comment is an artifact of an
unsupported dependency version, not a property of the code.

What this means for the claims in that comment

• "247 of 657 commits in 9.8 hours" — real, but measured under 1.1.1. Not a
  valid figure for this codebase's supported configuration.
• "the first perf: per-ident :introduced-by / lineage point queries are 1.33M graph reads — 33.6% of ingestion wall clock #239 re-measurement that does not depend on the vanished
  20260803T095104Z harness" — withdrawn. It depends on something worse: an
  unsupported minigraf.
• The py-spy stack (_reverse_apply → _entity_introduced_by_query) is
  accurate as far as it goes — that was where the time went in that process.
  But it went there partly because every call was paying a 6.8x penalty that
  the supported version does not.
• "perf: per-ident :introduced-by / lineage point queries are 1.33M graph reads — 33.6% of ingestion wall clock #239 blocks correctness verification for bug: forward-walk preload bound is valid-time over author dates, leaving the resume-time data-loss window narrowly open #238/bug: :depends-on and :pinned-commit preload bounds have no position handle, so they keep #238's author-date residual #245" — withdrawn pending
  a re-run. The bug: :depends-on and :pinned-commit preload bounds have no position handle, so they keep #238's author-date residual #245 acceptance probe is being re-run under .venv; if it
  completes, perf: per-ident :introduced-by / lineage point queries are 1.33M graph reads — 33.6% of ingestion wall clock #239 was never the blocker.

The one thing worth keeping

The same wrong interpreter also fabricated a test baseline: pytest tests/ -q
gives 122 failed / 1039 passed / 48 skipped under system python and
1 failed / 1169 passed under .venv. Two of those "environmental" failures
(test_second_open_in_same_process_is_refused,
test_real_same_process_open_is_classified_as_retryable) require minigraf

= 1.2.2's second-open refusal and cannot pass under 1.1.1 — and under 1.1.1 a
second same-process open silently succeeds, which is precisely the #251/#253
corruption mode. Any lock or concurrency behaviour observed under that
interpreter is meaningless.

Anyone benchmarking this project: use .venv/bin/python, and check
pip show minigraf against the floor in pyproject.toml before believing a
number.

#239 stands on its own prior evidence. It is not strengthened by my comment
above, and the fix direction it proposes should be decided by a measurement
taken under the supported configuration.

Refs #245
Refs #222

[adityamukho]

Measured: per-call cost is FLAT. The fix is a batch, not an index — but the prize is much smaller than this issue claims.

Bench: evals/at_scale/bench_introduced_by_query_cost.py on branch
bench-239-introduced-by-query-cost. Raw:
evals/at_scale/results/239-introduced-by-query-cost.json. Design spec and
plan are committed alongside it.

This measures the one thing that decides this issue's fix direction: is the
per-call cost constant in graph size, or does it grow? Batching a constant
cost removes it. Batching a growing cost only changes how often you pay it.

Verdict: FLAT

The threshold (under 2x growth across 50x, both axes, HIT and MISS) was fixed
in the design spec before any data existed, so it could not be chosen to
fit the outcome.

series	100k → 5M filler	growth
_entity_ident_is_live HIT	0.0544 → 0.0579 ms/call	1.065x
_entity_ident_is_live MISS	0.0499 → 0.0556	1.114x
_entity_introduced_by_query HIT	0.0547 → 0.0602	1.101x
_entity_introduced_by_query MISS	0.0527 → 0.0584	1.109x

Second axis (ident population 1k → 50k, filler fixed at 1M): worst growth
1.114x. All eight ratios fall between 1.015x and 1.114x.

Control: _lineage_is_provisional — whose flatness was already established
by bench_lineage_query_cost.py — reproduced at 1.14x. A run whose control
fails prints INVALID MEASUREMENT and withholds the verdict; this one passed.

Fix direction: per-commit batch or write-through cache

Whole-relation batch cost is flat too (7.65 / 7.63 / 7.61 ms at 100k / 1M /
5M). Crossover — the number of point queries costing one batch call — is
140 / 129 / 126, against 1265 candidate idents per commit. A per-commit
batch pays for itself roughly 9–10x at every graph size.

A companion index is NOT indicated. That was the live alternative going in
(#152 and #236 each found a per-item operation degrading to a scan and fixed it
with a companion table); it is ruled out here.

Note there is no server-side scoped form available: minigraf has no
set-membership predicate — contains? is a string predicate
(query/datalog/parser.rs:1175) — so the batch shape is whole-relation plus
Python narrowing, exactly as _preload_known_deps already does.

Two findings that matter more than the direction

1. This issue's headline is probably wrong by ~8x. D2 records
_entity_introduced_by_query at 0.46 ms/call and the whole query line item
at 523 s = 33.6% of a 1,558 s run. Measured here: 0.06 ms/call — 7.7x
lower. At that rate the same 1.33 M queries cost roughly 80 s, putting the
realistic ceiling on this fix in the single-digit percent of a run, not a
third of it.

Worth knowing why that gap is plausible: today it emerged that
/usr/bin/python on the development machine carried minigraf 1.1.1 against
this project's >=1.2.3 floor, and these queries run ~7x slower there. Any
figure taken with a bare python is suspect. Re-derive the 33.6% before
investing in the fix.

2. The superlinear ingestion growth is NOT these queries. #245's acceptance
run showed per-commit cost climbing 1.39 → 4.29 s/commit across ~520
commits. These queries are flat across a 50x graph range and a 50x
ident-population range. Whatever makes ingestion cost grow with history, it is
something else — and fixing this issue will not address it. That is probably
the more valuable thing to chase.

Refs #245
Refs #222