fold/docs/internal/perf-audit.md
2026-05-27 10:36:57 -04:00

485 lines
21 KiB
Markdown
Raw Permalink Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

# fold performance audit (2026-05-23)
## Purpose and scope
fold's `--profile` output rolls per-detector wall-clock into a flat
list. That answered "which detector is slow?" but not "where does
the unaccounted time go?" or "what overhead is self-inflicted?".
This audit captures a baseline on a real codebase (curl), surfaces
the previously-hidden phases, ranks the self-inflicted overhead by
observed cost rather than gut feel, and queues concrete fixes
against the data.
**In scope:**
- Phase-level breakdown of `analyze_ms`.
- Existing cache + shared-state surfaces.
- Multi-walk redundancy (does the same TU/function get visited
multiple times when one pass would do?).
- Fold-on-fold static findings — does our own code have duplication
worth refactoring?
**Out of scope:**
- Z3 algorithmic complexity (not ours to optimise).
- Clang's `ASTUnit::create` cost per TU (architectural; mitigations
listed in the backlog).
- Worker fanout + IPC mechanics beyond timing them.
- Detector precision/recall (separate concern; tracked in
`docs/research/frontier.md` and `bench/results/`).
## Methodology
- **Target:** curl (`../curl-source/curl/build/compile_commands.json`),
306 TUs, 2339 functions. Picked because it's the documented bench
baseline (`bench/run_curl_ab.py`) and fits a single-machine session.
- **Detector set:** `clone,dead,equiv,null-deref` — covers the clone
hashing phase + the most expensive security detector (null-deref).
- **Mode:** `--profile` forces single-process serial execution
(`src/cli/scan_router.cpp:244`). All wall-clock numbers below are
serial; multi-worker reduces wall-clock proportionally for the
detector phases but not for the parts that already serialise (call-
graph build, cross-TU priming).
- **Tooling:** `/usr/bin/time -p` for wall-clock; `--profile-output`
for JSON breakdown; `python3` + `jq`-equivalents for parsing.
- **Baseline artifact:** `docs/internal/perf-audit/baseline-instrumented-2026-05-23.json`.
- **Fold-on-fold artifact:** `docs/internal/perf-audit/fold-on-fold-2026-05-23.json`
(639 findings); triage in `docs/internal/perf-audit/fold-on-fold.md`.
## Existing caches inventory
Six caches were mapped (Phase-1 exploration). Summary:
| Cache | Scope | Key | Invalidation | Notes |
|---|---|---|---|---|
| `CrossTUCache` | per-scan, process-global | qualified function name → `CalleeProperties` | cleared at shard boundary | Primed by a dedicated walk; rebuilt every scan |
| `SummaryStore` | per-scan, process-global | qualified name → `SymbolicSummary` | transitive on dependent change | In-memory only; no disk persistence |
| `ExprCache` | **per-TU**, process-global | z3 expr hash → check_result | cleared at TU boundary | Aggressive invalidation; solver results don't carry across functions |
| `IncrementalCache` | per-scan, disk-persisted | function (src hash, callee hash) | source/callee hash change | Opt-in via `--incremental`; forces `--processes=1` |
| `ProjectCallGraph` | per-scan, in-memory | def → callees + SCCs | rebuilt every scan | Not persisted |
| `BufferSizeTracker`, `HeapModel` | per-function | per-SymbolicEnv | end of function | Correct lifetime; not a cache problem |
**Note:** subprocess workers don't share any of these — each cold-
starts. That's a clang-binding limitation we can mitigate but not
eliminate.
## Empirical baseline
From `docs/internal/perf-audit/baseline-instrumented-2026-05-23.json`:
```
total_wall_ms: 455,756 (7.6 min)
compile_db_load_ms: 2
fanout_orchestration_ms: 0 (profile mode → serial)
serial_dispatch_ms: 455,682
parse_ms: 0
analyze_ms: 455,685
report_ms: 71
detector wall_ms breakdown:
null-deref 297,955 (65.4% of total)
dead 8,750 ( 1.9%)
equiv 2,240 ( 0.5%)
clone 216 ( 0.05%)
-------------------------------------
sum 309,161 (67.8%)
serial_dispatch_ms - sum 146,521 (32.2%)
```
Two findings jump out:
1. **null-deref dominates: 65% of total wall.** With ~3s of actual
Z3 query time (from `[solver-profile]` z3_time_ms aggregate), the
other ~297s is in the encoder / state-merging / walker.
2. **~32% (146s) was previously unaccounted.** New instrumentation
localizes it to `serial_dispatch_ms` minus detector wall — i.e.,
inside `runDetectorsOnShard` but outside any detector handler.
That bucket contains: clang ASTUnit construction per TU (~1.0s ×
306 ≈ 306s of CPU, but clang parses are roughly 0.5s wall each
on this hardware → ~150s wall, matches), cross-TU priming
(~1 full extra AST walk per TU), call-graph collection, function
fingerprinting.
## Self-inflicted-overhead findings (ranked by observed cost)
### 1. clang ASTUnit constructed once per TU, never shared
**Observed cost:** ~150s of the 455s baseline (33%). Dominant
contributor to `serial_dispatch_ms - sum(detector.wall_ms)`.
**Where:** `src/frontend/clang_backend.cpp:144`. Each TU spawns a
fresh `clang::tooling::ClangTool::run()`. Worker subprocesses
amplify this: each worker re-parses every TU it owns from cold.
**Remediation sketch:**
- Short-term: emit precompiled headers (PCH) for project headers
used by every TU; clang accepts `-include-pch` per invocation.
- Medium-term: persistent worker that holds an LRU of recently-
parsed ASTUnits keyed by TU + clang flags hash; new commands
reach it over a Unix socket. Requires a daemon model that fold
doesn't have today.
- Long-term: explore clang's `ASTReader` snapshot format if it
becomes usable for our access patterns.
**Estimated payoff:** 30–50% wall-clock reduction on warm runs.
The exact number depends on PCH coverage of fold's clang include
graph.
### 2. null-deref encoder + walker traversal: 5 min CPU per curl scan
**Observed cost:** ~287s of detector wall, ~99% outside Z3.
**Where:** `src/detect/null_deref.cpp` + `src/symbolic/encoder.cpp`
+ the security walker's path enumeration.
**Phase breakdown (final — `baseline-hooks-2026-05-23.json`):**
```
null-deref wall_ms: 344,644
walker_ms: 340,329 (98.8% of wall — almost all in walk/walkCFG)
encode_ms: 24,156 (7.1% of walker — NOT the target)
hook_ms: 11,860 (3.5% of walker — NOT the target)
state_merge_ms: 75 (0.02% of walker — NOT the target)
walker - the above: 304,238 (89.4% of walker — the actual cost)
```
Aggregate z3_time_ms across the entire scan: ~33ms (<0.01% of total).
**Four wrong hypotheses, four pivots:**
1. Hash-walk fusion (original plan): 0.04% of total.
2. State-merge optimization: 0.02% of null-deref walker.
3. Encoder optimization: 7% of null-deref walker.
4. Hook body optimization: 3.5% of null-deref walker.
The 304s that remains after subtracting all four was originally
hypothesised as "per-stmt bookkeeping that fires for every
statement." A second-round decomposition (Backlog #2) added four
timers — `cfg_build_ms`, `nonnull_precompute_ms`, `control_walk_ms`,
`stmt_overhead_ms` — and revised that hypothesis with measurement.
**Final decomposition (curl null-deref baseline):**
| Phase | ms | % of walker_ms |
|---|---|---|
| `control_walk_ms` (walkIf + walkSwitch + walkFor + walkWhile + walkDo) | 254,102 | 85.3% |
| `encode_ms` | 4,614 | 1.5% |
| `hook_ms` | 2,808 | 0.9% |
| `stmt_overhead_ms` (snapshot-delta remainder) | 287 | 0.1% |
| `state_merge_ms` / `cfg_build_ms` / `nonnull_precompute_ms` | 0 | 0% |
| `walker_ms` total | 297,749 | 100% |
The 89% bucket is **recursive control-flow body walks**, not
per-stmt bookkeeping. Each `walkIf` clones envs, recursively walks
each arm, and merges; `walkFor`/`walkWhile` unroll; the recursion
re-enters the per-block loop. Most source code lives inside
control structures, so most analysis time naturally falls there.
Caveat on double-counting: `control_walk_ms` covers the full wall
of the recursive walks, including the nested `encode_ms`/`hook_ms`
slices fired inside them. The 254s double-counts ≈7s of inner
encode+hook; net ≈247s is the recursive walking machinery itself
(env clone, refine ranges, body walk, merge).
A separate hypothesis — "env clones in walkIf dominate
`control_walk_ms`" — was added and refuted by direct measurement:
`env_clone_ms` totals 0 across 770,748 clones (under 1 µs each,
since `z3::expr` refcount bumps and 11 `unordered_map` shallow
copies amortize to nothing).
**Remediation candidates for the 89%:**
1. Bound `walkForStmt`/`walkWhileStmt` unroll cost — large loops
multiply the recursion factor.
2. Cache `refineRangesForCondition` / `refineOctagonForCondition`
results across re-entries of the same branch.
Neither will eliminate the bucket. The cost is symbolic execution
proportional to (statements × control-nesting depth). Meaningful
wall reduction requires changing the *semantic model* (lower
precision, deeper bounded unroll cap, branch pruning, AST+env
memoization) — design tradeoffs around precision vs speed, not
optimizations of a single hot loop. Those belong in a separate
proposal, not a perf-audit follow-up.
**Older notes (kept for context):** the pre-decomposition guesses
walked per statement to find DeclRef writes; the result is used
to invalidate octagon entries.
- **`getParentMapContext()` / parent-map queries** — clang's parent
lookup, allocated lazily but consulted frequently.
- **`buildNonNullAtBlockEntry`** — pre-pass that walks the entire
CFG to compute per-block non-null facts; runs at the start of
every walkCFG.
- **`BranchLivenessBuilder` + `WriteCollector`** — ancillary
per-function RecursiveASTVisitor passes (~4× per function).
- **`liveAtJoin(is)`** — live-set computation per if-statement.
**Remediation targets (ranked by likely payoff):**
1. **Cache `collectWrittenVars` per statement** — **landed.**
Memoizes a deterministic per-stmt result by `Stmt*` pointer; 5
call sites previously re-walked the same subtree (octagon
invalidation in walk() / walkCFG() main loops, BFS in
`buildNonNullAtBlockEntry`'s `writtenIn` lambda, loop-inc in
`unrollLoop`). Architecturally sound; perf delta within
run-to-run variance on a single curl scan (see "On measurement
discipline").
2. **Consolidate the 6 non-null-marking maps into one.** Each
stmt currently consults/updates several; merging them into a
single accumulator removes 5× the hash-lookup overhead.
3. **Skip `refineRanges` / `refineOctagon` when no IfStmt is in
the immediate continuation.** Today they fire unconditionally.
4. **Lazy `buildNonNullAtBlockEntry`** — only run when a detector
actually queries non-null facts. Currently runs for every
function.
Beyond these four, the next round needs profiling-grade
flame-graph data (perf, samply, Instruments) — phase-level
instrumentation isolated the 304s to the walker but can't
subdivide further without adding O(stmts) timers that would
themselves perturb the measurement.
## On measurement discipline
Cross-baseline data from this session shows ~15% run-to-run
variance on the same curl invocation:
```
baseline (no timers): 465s
baseline (+compile-db timers): 455s
baseline (+walker/merge): 454s
baseline (+encode timer): 442s
baseline (+hook timer): 533s ← anomalously slow run
after writtenvars cache: 451s
```
The baseline-hooks run is an outlier (likely system load or the
~millions of hook RAII timers compounding). After-cache lands at
451s, statistically indistinguishable from the 442–465s spread of
the earlier baselines. **Single-run measurements at this
resolution don't reliably attribute small wins.**
**Use `bench/perf_audit_run.py`** for any future perf claim
≤15%. It runs fold N times against a fixed compile DB and
reports median + IQR + min/max for every `--profile` metric:
```
bench/perf_audit_run.py --label baseline --runs 5
# ... apply change ...
bench/perf_audit_run.py --label after-fix --runs 5 \
--diff docs/internal/perf-audit/runs/baseline.json
```
The `--diff` output flags moves outside 1.5×IQR as "significant".
For high-confidence claims (sub-5%), bump `--runs 10+` and
quiesce the machine (close browsers etc.) during the window.
Other tactics worth knowing about:
- Pin CPU frequency where the OS allows (macOS: hard; Linux:
`cpupower frequency-set`).
- Use `samply` or `Instruments` for absolute line-level
attribution; reserve `--profile` JSON diff for monitoring
large regressions only.
The instrumentation that landed in this audit survives this
variance — it's about *relative* attribution within one run, not
absolute wall-time deltas across runs.
### 3. Cross-TU priming = one extra full AST walk per TU
**Observed cost:** baked into the 146s unaccounted bucket; not
isolated yet.
**Where:** `src/cli/scan_runner.cpp:1109-1115`. Before detector
dispatch, every TU is walked once to populate `CrossTUCache` with
"this function dereferences param 2", "this function returns null
sometimes", etc. The cache lives one scan and dies.
**Remediation sketch:** persist `CrossTUCache` to disk like
`IncrementalCache`. Cache key: (qualified name, body hash). Reuse
across runs unless the body changed.
**Estimated payoff:** the priming pass takes roughly 1× the
detector AST-walk cost, so eliminating it on warm scans saves
~30–60s on curl. Needs measurement.
### 4. `--incremental` is mutually exclusive with `--processes >1`
**Observed cost:** users pick speed (parallel) OR freshness
(incremental); never both.
**Where:** `src/cli/scan_router.cpp:210-212`. The incremental
implementation runs serially because the parent-side fingerprint
map can't be sharded today.
**Remediation sketch:** sharded fingerprint files per worker;
parent merges at completion. Already partially modelled by
SubprocessFanout's NDJSON merge.
**Estimated payoff:** for users on big repos who re-scan
frequently (CI runs, IDE), the speedup multiplies — incremental
already skips most functions; pairing with fanout gives near-zero
warm-scan times.
### 5. ExprCache lifetime is per-TU instead of per-scan
**Observed cost:** unmeasured but bounded by Z3 query time (~3s
across the whole scan, per `[solver-profile]` z3_time_ms summed).
Small absolute payoff today but rises with detector heaviness.
**Where:** `src/cli/scan_runner.cpp:1511`. ExprCache is cleared at
each TU boundary. Same arithmetic expression queried in TU A and
TU B re-solves from scratch.
**Remediation sketch:** extend lifetime to per-scan, with the
canonical expression hash as the key. Risk: if two different
expressions canonicalise to the same hash (collision), we'd
return the wrong cached result. Audit the hash function for
non-collision properties before changing lifetime.
**Estimated payoff:** small on curl (Z3 is already cheap here);
larger on z3-heavy targets (loops, complex bit manipulation).
### 6. Security-detector path fans out to 7 walks when ≤1 is enabled
**Observed cost:** zero today (the audit baseline runs >1, so the
composite path activates).
**Where:** `src/cli/scan_runner.cpp:1890-1995` —
`use_composite_security_walk` only flips on when
`enabledSecurityDetectorCount() > 1`. If a user runs `--detectors
null-deref` alone, we fall back to 7 independent walks.
**Remediation sketch:** drop the fallback; always use the
composite walker even for single-detector runs. The composite
walker handles the single-detector case correctly already.
**Estimated payoff:** negligible for default runs; clean-up for
single-detector debugging paths.
### Lower-priority items
| Item | Where | Estimated payoff |
|---|---|---|
| Dup CFG-build elimination (dead-statement + security walker build same CFG) | `src/detect/dead_statement.cpp:66` + `src/ir/cfg_walker.cpp:21` | small (CFG build ≪ encoder) |
| 5 hash/tokenize walks per function in clone phase | `src/frontend/ast_visitor.cpp:174-180` | ~170 ms on curl (clone is 0.05% of total) |
| Suppressions/baseline reparsed every command | `src/report/triage.cpp:73-90` | trivial |
The hash-walk fusion was the *plan's* highest-leverage target before
the baseline. Empirically it's ~0.04% of total — keep it on the
backlog for cleanliness, not perf.
## Fold-on-fold findings (summary)
Full triage in `docs/internal/perf-audit/fold-on-fold.md`. Top patterns
worth refactoring:
- **`mixHash` 5+ copies** across security-detector anonymous
namespaces. Lift to a shared helper.
- **`supportsParam` / `collectConjuncts`** repeated across detectors.
Move to a `src/symbolic/z3_helpers.{hpp,cpp}` sibling of the
existing `z3_model_support`.
- **`onFunctionEnd` boilerplate** across the 5 security observers.
Default implementation in a base class.
- **`ir::*::valid` / `operator bool` / `operator==`** boilerplate
for `Call`, `MemberRef`, `Symbol`, `Expr`. CRTP or macro.
The fold-on-fold pass also surfaced 152 dead-statement findings;
most are cache-layer short-circuits where a guard later in the
function makes an early-return provably unreachable. Some are
encoder bails that are intentionally defensive. Triage requires
file-by-file review; the JSON is the full record.
**Notable absence:** equiv detector emitted zero findings. That's
honest progress — the prior scout-rule extractions (encoder_arms,
clang_type_queries, callee names) moved colliding helpers out of
the per-detector files. The remaining duplication is in small
helpers that don't reach equiv's signature-match threshold.
## Phase-1 result: instrumentation, not the planned hash fusion
The original plan committed to fusing the 5 hash/tokenize walks
into one pass as the "highest-leverage" fix. Empirically that
target is 0.04% of total. **Plan pivot:** ship the
instrumentation (3 new ScanProfile fields:
`compile_db_load_ms`, `fanout_orchestration_ms`,
`serial_dispatch_ms`) so subsequent rounds have phase-level data
instead of a flat per-detector list. Commit: `503799a`.
Result: the 146s previously-unaccounted bucket is now named
(`serial_dispatch_ms - sum(detector.wall_ms)`) and the next
optimisation round can target it specifically.
## Phase-2 backlog (ranked by estimated payoff, after measurement)
For Z3 and Clang library-expansion opportunities (separate axis
from this backlog), see
[`library-expansion-matrix.md`](library-expansion-matrix.md) —
20 scored rows with file-cited insertion sites and a
recommended top-3 sequence.
The first two items below shipped in the same round as the
audit. They are kept on the list because each surfaced a
measurement worth recording.
1. **Persist CrossTUCache across scans — SHIPPED, ~8s wall (~2%).**
v2 reaches 100% hit rate and exact finding-count parity
(7112==7112 on curl null-deref). The audit's 30–60s estimate
was inflated 3–6×; actual priming cost on curl is ~9s and v2
saves essentially all of it. Treat the cache as a correctness
invariant for incremental scans + small wall win + infrastructure
for future caching. Design + measurement:
`docs/internal/perf-audit/cross-tu-cache-persistence.md`.
2. **Per-phase null-deref decomposition — SHIPPED, identified 89%
bucket.** Four new timers (`cfg_build_ms`,
`nonnull_precompute_ms`, `control_walk_ms`, `stmt_overhead_ms`)
resolve the previously-unattributed null-deref walker time.
The 89% turned out to be `control_walk_ms` (recursive control-
flow body walks), not per-stmt bookkeeping. See the null-deref
section above for the full breakdown.
3. **`--incremental` + `--processes >1` compatibility.** Requires
sharded fingerprint files.
4. **ExprCache lifetime extension to per-scan** (with collision
audit).
5. **Always-on composite security walker** (drop the ≤1 fallback).
Attempted as a ~115-line cleanup (delete the 7
`if (!use_composite && detectorEnabled(...))` blocks, force the
composite path). Build + 47/47 tests stayed green, but the
curl A/B at the standard `--budget-seconds 5` showed up to ~1.5%
finding drift across runs against the same code, indistinguishable
from the ~0.8% run-to-run noise observed between back-to-back
identical reruns. Reverted pending a longer-budget parity check
(60s/TU, ~30 min per leg) that can separate semantic drift from
budget-truncation noise.
6. **Dup CFG-build elimination** (small).
7. **Hash-walk fusion** (cleanliness, ~170ms).
8. **Fold-on-fold refactor: `mixHash`, `supportsParam`,
`onFunctionEnd`, `ir::*` boilerplate.** Cleanliness.
9. **PCH for project headers** — measured ceiling ~0.3% wall.
Keep on the list for documentation but do not invest design
effort until the 89% bookkeeping bucket is decomposed and proven
not to dominate.
## Regression prevention
Recommended addition to `bench/run_curl_ab.py`: capture the new
phase timings (`compile_db_load_ms`, `fanout_orchestration_ms`,
`serial_dispatch_ms`) alongside per-detector wall_ms. Diff the
JSON against `docs/internal/perf-audit/baseline-instrumented-2026-05-23.json`
on each release; alert on >10% regression in any phase.
The bench harness already parses `--profile` JSON; only the field
list needs extending.
## Pointers
- Baseline JSON: `docs/internal/perf-audit/baseline-instrumented-2026-05-23.json`
- Fold-on-fold JSON: `docs/internal/perf-audit/fold-on-fold-2026-05-23.json`
- Fold-on-fold triage: `docs/internal/perf-audit/fold-on-fold.md`
- Instrumentation commit: `503799a`
- Fold-on-fold commit: (this series)
- Audit commit (this doc): (HEAD)