--- name: pm-perf-tracing description: Performance-trace Nub package-manager installs using the existing phase timings, structured diagnostics, and sampling-profiler workflow. Use when an install or package-manager operation is unexpectedly slow and the bottleneck needs to be localized before changing code. metadata: internal: true --- # pm-perf-tracing How to performance-trace the nub package manager (install/resolve/fetch/**link**) and find where the time actually goes — the method that cracked the hoisted-linker slowness (10.8s → root-caused to a per-file copy loop). Reach for this any time a `nub install` / PM operation is "mysteriously slow" — do NOT reverse-engineer from source; the instrumentation already exists, turn it on. ## The two layers that already exist 1. **Phase timings — works under nub TODAY.** `RUST_LOG=debug nub install` emits `phase: ` lines on stderr: `phase:resolve`, `phase:fetch (N packages)`, `phase:link (N files)`, `phase:link_bins`. This alone tells you the coarse split (is it network/resolve, or linking?). The aube engine wires these through the `tracing` crate. 2. **Rich diagnostics layer — native under nub via `NUB_DIAG_*`.** `aube_util::diag` emits structured JSONL to `NUB_DIAG_FILE=` — including, for the linker, one event per file naming the strategy used (`link_clonedir`, `link_reflink`, `link_macos_small_copy`, `link_copy`, `link_hardlink`). This is the load-independent crux for a link-perf question. The full knob set (all off by default, zero cost when unset): - `NUB_DIAG_FILE=` — JSONL events to a file. - `NUB_DIAG_PRINT=1` — live per-span lines to stderr. - `NUB_DIAG_SUMMARY=1` — end-of-run aggregate table. - `NUB_DIAG_CRITPATH=1` — retain records for the critical-path / lifecycle / starvation analyzers. - `NUB_DIAG_THRESHOLD_MS=` — filter live prints below `` ms. - `NUB_DIAG_KERNEL=1` — `getrusage` kernel deltas around phases. - `NUB_BENCH_PHASES_FILE=` — per-run phase-timing JSON for the bench harness. ```sh cargo build -p nub-cli --profile fast # dev binary at -target/fast/nub NUB=-target/fast/nub NUB_DIAG_FILE=/tmp/d.jsonl NUB_DIAG_SUMMARY=1 "$NUB" install --offline grep -o '"name":"link_[a-z_]*"' /tmp/d.jsonl | sort | uniq -c # per-strategy tally ``` (The diag layer reads `NUB_DIAG_*` under the nub embedder profile via the `diag_env_prefix` hook — no source edit needed. `AUBE_DIAG_*` is NOT read under nub. The `dev-tracing-telemetry` thread / `wiki/research/dev-tracing-telemetry.md` tracks the optional chrome-trace/flamegraph export layer on top.) ## The measurement discipline (load-independent — this host is permanently contended) The dev box runs load ~30–50 and never goes quiet, so **absolute wall-clock is untrustworthy**. Measure things contention can't ruin: - **Verified-clean warm loop:** `rm -rf node_modules` and *assert it's gone*, warm store already populated, `--offline` (proves zero network: `phase:fetch` shows `0 packages`), and check **rc=0** on every run (a timing from an errored install — e.g. npm's `rm: Directory not empty` purge failures → rc=254 — is garbage). - **Strategy tally, not seconds:** "75,079/76,167 files took `link_macos_small_copy`, 0 took `link_clonedir`" is a fact regardless of load. That's what proves a design gap. - **Back-to-back A/B on the same box, report the RATIO:** e.g. hoisted vs `--node-linker isolated` on the same fixture, same load window → the relative delta (≈26×) is robust even when both absolutes are inflated. - For a real clean wall-clock number, hand it to a quiet machine / CI runner — never block on this box settling. ## Layout matters — always check which linker path runs nub mirrors the incumbent layout: an npm/yarn/bun lockfile → **hoisted** layout (`link.rs` → `hoisted::link_hoisted_importer`); nub-identity / `--node-linker isolated` → **isolated** layout (`materialize_into`, the only path with the whole-dir `clonefile(2)` fast path). They have completely different perf characteristics. When a perf question is about linking, run BOTH (`--node-linker isolated` vs default) and diff — that A/B is what localized the hoisted-linker gap. ## When spans aren't enough — sampling profiler Span/JSONL instrumentation can distort a syscall-bound, parallel pass (observer effect). For "where inside the link phase do the syscalls go" use a sampling profiler on a **release** build: `samply record -- install --offline` (macOS/Linux), or `cargo flamegraph`. Spans tell you *which phase/strategy*; the sampler tells you *which syscalls/functions* dominate. ## Fixtures - `/tmp/coffee2-demo` — CoffeeScript 2.0.1, npm `lockfileVersion:1`, 519 pkgs / ~76k hoisted files. The canonical heavy-hoisted-layout fixture. - A minimal hoisted repro: a `package.json` + `package-lock.json` with `webpack@3.6.0` + `underscore` (no `node_modules`). ## The one-liner to remember `RUST_LOG=debug nub install` for the phase split; if it's `phase:link`, set `NUB_DIAG_FILE=…` for the per-file strategy tally; A/B against `--node-linker isolated`; judge by strategy-tally + ratio, never the contended absolute.