Repository navigation
tier2: dead_code is 83% of background scan time, and its cost distribution is bimodal (p50 326ms, p95 19s) #209
Description
Census from a live daemon's module log — 110 perf ticks, ~2h uptime, several project roots bound by concurrent sessions:
| category | runs | total | share | p50 | p95 | max |
|---|---|---|---|---|---|---|
| dead_code | 34 | 52,586 ms | 83% | 326 ms | 19,087 ms | 19,655 ms |
| duplicates | 30 | 4,863 ms | 7% | 42 ms | 788 ms | 2,046 ms |
| unused_exports | 30 | 2,902 ms | 4% | 38 ms | 239 ms | 889 ms |
| cycles | 30 | 2,656 ms | 4% | 23 ms | 485 ms | 768 ms |
63 s of background scan time in the window, and dead_code is five sixths of it.
The interesting part isn't the total, it's the shape. p50 is 326 ms and p95 is 19 s — a 58× spread. Sorted run times:
19655 19087 2741 1167 771 637 597 466 ...
Two runs account for 74% of all dead_code time. This isn't a uniformly slow scanner; it's a fast one with a rare catastrophic mode, and that shape usually means a specific input class rather than general cost.
What I could rule out from the log: it isn't watcher volume, and it isn't callgraph churn.
13:11:11 2741ms watcher_paths= 25 callgraph_invalidations=3
14:18:21 19655ms watcher_paths= 52 callgraph_invalidations=0
14:21:21 19087ms watcher_paths=218 callgraph_invalidations=0
The 218-path tick ran faster than the 52-path one, and both 19 s runs had zero callgraph invalidations. Whatever drives the tail, it isn't how much changed.
Where I'd look, and why I'm asking rather than patching:
project_dead_code_snapshot opens the callgraph SQLite read-only and does what looks like a full projection — SELECT path FROM files ORDER BY path, then all nodes, then all refs — per scan. If that's per-root-per-scan with no incremental path, a large root would give exactly this bimodal profile: cheap on small roots, cliff on the big one. I haven't confirmed that's the code path taken in the slow runs, and the log doesn't carry the root, so I can't attribute it from here.
Two things that would make this diagnosable from a log without guessing:
- Tag tier2 timings with the root (or a stable root id). Right now a 19 s dead_code run is anonymous — you can't tell whether it's one pathological repo or a general regression, which is the first question anyone asks.
- A per-category soft deadline for tier2.
InspectManager::soft_deadlinebounds a caller waiting on an outcome, but a background scan appears to run to completion regardless. A 19 s scan on a shared daemon competes with interactive work for the same process; a bounded scan that reportscomplete: falsefits the honest-reporting convention better than an unbounded one that finishes eventually.
Happy to dig further on either if useful, but you'll know immediately whether the projection is the right suspect and whether the tail is expected on a large root.
Method note so the numbers can be discounted appropriately: single host, single daemon instance, ~2 h, mixed real workload from several concurrent sessions. Not a controlled benchmark — a census of what one production instance actually spent.
Activity
ualtinok commentedon Aug 10, 2026
Verified at source, and your instinct about where to look was exact:
project_dead_code_snapshot(crates/aft/src/callgraph_store/dead_code_projection.rs) opens the store read-only and projects the full graph —SELECT path FROM files ORDER BY path, all nodes, all refs — on every scan, per root, with no caching between scans. Your own log data is the conviction: both 19 s runs hadcallgraph_invalidations=0, so they re-projected byte-identical data the previous scan had already projected. The bimodal shape is exactly what you called it — cheap on small stores, cliff on large ones, and the tail is pure duplicate work.Fix going out now: cache the projected snapshot keyed on the store's generation pointer (the
.currentfile that already serializes atomic swaps — when the generation hasn't moved, the store bytes cannot have changed by construction, so the cached projection is exact, not heuristic). Invalidation is generation movement; no TTL, no staleness window. On your census that converts ~74% of dead_code's total time into a cache hit, and the p95 should collapse toward the p50.The
ORDER BY pathand full-refs shape stay as-is — with the cache in front, the projection runs once per graph change instead of once per scan, which is the right cost point. Will note here when it ships.iceteaSA commentedon Aug 12, 2026
Ran the post-fix census on a live multi-root daemon. The predicted collapse did not appear, and I think the reason is a workload property rather than a defect in the cache — but I can't prove that from this data, so here it is with the confound named.
Cache fix confirmed present in the running binary (
5808e16eis an ancestor of the deployed build; verified withmerge-base --is-ancestor, not assumed).p95 down 16%, ms/run slightly up. Not the ~74%.
What I think is happening — the invalidation rate exceeds the scan rate.
1.26 refreshes per scan. Every refresh moves
write_revision, which is (correctly) part of your cache identity, so the next scan on that root must re-project. On a daemon serving 7 actively-edited roots, there may be no interval in which a root's graph is stable long enough for a second scan to hit the same key.If that's right, the cache is working exactly as designed and this workload just doesn't present the reuse it exploits. The tail would then be genuinely fresh projections of large stores — real work, not duplicate work.
Two things that make me hold that loosely. The pre-fix census was taken at 8 h uptime and this one at 2 h, so I'm comparing a warm daemon against one whose cache started empty — that alone biases against the fix. And the expensive runs no longer correlate with graph churn the way I'd expect if they were all genuinely-invalidated re-projections:
Three expensive runs with zero callgraph invalidations in that interval. If the graph didn't change, either the revision moved for a reason I'm not seeing (a refresh that touches the store without invalidating), or those are cache misses that should have been hits. That's the thread worth pulling, and it's in your code rather than my log.
A hit/miss counter on the projection cache would answer this in one tick — right now I'm inferring cache behaviour from timings, which is exactly the indirect reading that produced the original misdiagnosis on #206. If you add one I'm happy to re-run this census and give you the actual hit rate rather than my guess at it.
Method, so it can be discounted properly: single host, one daemon instance per census, real mixed workload from concurrent sessions, not a controlled benchmark.
runsis the summed count field from the perf-tick tier2 group; per-tick means where a tick aggregated multiple runs, so p50/p95 are over per-tick means rather than individual runs.iceteaSA commentedon Aug 12, 2026
Followed the zero-invalidation thread by reading the source rather than waiting on the counter, and it resolves — those three runs are correctly-invalidated misses, not a hidden key mover.
refresh_files_profiled_with_workspace_crate_prefix_cachecallsbump_projection_write_revisionon every successful refresh. The dead_code scan path refreshes the store immediately before projecting (manager.rs:2392), so each scan's own refresh bumps the revision it is about to key against.Checking the three cases against refresh events in the log:
All three had a refresh land between the previous scan and that one. So
callgraph_invalidations=0was me reading the wrong signal — that counter tracks something else, and the store was genuinely refreshed in each interval. My "misses that should have been hits" reading was wrong, and I'd rather retract it here than leave it as a false lead in your inbox.The invalidation-rate explanation therefore holds up better than when I posted it, and it's now mechanical rather than statistical: the scan refreshes the store it's about to project. So a hit requires two scans on one root with no intervening file change at all. Across 53 refreshes / 42 scans / 7 actively-edited roots, that window is rare by construction.
One thing I checked and could not find, which is the part that would make this a real defect: every refresh in the log reports a nonzero
changed=count, so nothing is bumping the revision for a no-op. If some refreshes were arriving withchanged=0and still bumping, that'd be free invalidation worth eliminating — it isn't happening here.So the honest read on my census: the cache is correct and this workload doesn't present the reuse pattern it exploits. Whether that's true of quieter single-root daemons is a different question, and one my host can't answer — a hit/miss counter would still tell you more in one tick than my timing inference does, but the case for it is now "confirm the mechanism" rather than "explain an anomaly".
iceteaSA commentedon Aug 12, 2026
Follow-up numbers, ~1h more uptime on the same daemon. p95 dropped 16,023 ms → 6,890 ms, but I don't think you should credit that to the cache yet — the load dropped at the same time and I can't separate them.
Split by window, the change looks dramatic:
The confound: watcher paths in the late window are 1,285 against 3,428 early — 2.7× less churn. p95 fell 16× while load fell 2.7×, so the cache may well be doing real work, but "cache warmed" and "workload quieted" moved together and this data can't separate them. The refresh:run ratio barely moved (1.24 → 1.22), which argues the shape of the work is similar and only the volume changed.
One pattern that does look structural. Lining the expensive runs up against when each root's callgraph store was first touched:
Three of the four most expensive runs land within a minute of a root's first projection — necessarily a cold miss, since nothing has been cached for that root yet. Seven roots came online across the first 30 minutes of this daemon's life, which is why the early window is dense with them.
If that generalises, the residual tail after your fix is mostly first-projection-per-root rather than repeated re-projection, and the fix removed the duplicate work it targeted. That would also explain why my 8h-warm pre-fix census and this 2h census aren't comparable in the way I set them up: the pre-fix daemon had long since paid its first-projection cost for every root, so its tail was genuinely repeated work — exactly what you fixed.
I'd want a longer post-fix window with comparable churn before calling that confirmed, and my host's workload isn't controllable enough to guarantee it. Offering the observation rather than the conclusion.
The hit/miss counter would settle all of this in one tick, and would specifically distinguish "cold first projection" from "invalidated re-projection" — which is the distinction this whole comment is dancing around.
ftzi commentedon Aug 13, 2026
If I don't want any of these detections I simply disallow
aft_inspect? I use oxlint alreadyiceteaSA commentedon Aug 13, 2026
@ftzi Yes, and worth knowing there are two levers with different reach — the one you'd reach for first only does half the job you probably want.
disabled_toolsdeletes the entry from the registered tool map (tool-registration.ts:85), and the Tier-2 idle scheduler gates onregisteredTools.has("aft_inspect")(index.ts:1103). So removing the tool also stops the periodic background scans — you're not left paying for scans whose results nothing can read. That's the part I'd want confirmed before assuming it, and it's why this issue's numbers matter to you at all: the 83%-of-Tier-2 dead_code cost is background work, not something charged at call time.If you already run oxlint, the overlap is real for dead code and unused exports but not total —
aft_inspectalso covers import cycles, duplicate detection, and LSP diagnostics aggregation across languages oxlint doesn't touch. Depends whether your project is JS/TS-only.One caveat on
tool_surface: "minimal", since it's the blunt instrument: it drops a lot more than inspect. Preferdisabled_toolsif inspect is the only thing you want gone.None of this is affected by the fix in this issue — that only makes the scans cheaper when they do run.
ftzi commentedon Aug 13, 2026
Thanks! I also use knip, that also does some cleanings. Nothing against aft doing these, just my flow already have these wired up, including in the CI
ualtinok commentedon Aug 14, 2026
Shipped in v0.50.0/v0.50.1: dead-code projections are now cached across unchanged callgraphs, and automatic Tier-2 dead-code passes are skipped entirely when the callgraph store is disabled — the 83% share and the bimodal p95 both derive from re-running the projection on unchanged state, which no longer happens. The deeper incremental-refresh rework you outlined in #214 is tracked there.