perf(pm): drop per-package debug logs from resolve hot path#2880
Merged
perf(pm): drop per-package debug logs from resolve hot path#2880
Conversation
The hot path emitted ~5-10 `tracing::debug!()` calls per resolved
manifest — cache hit/miss decisions, BFS dedup decisions, "Fetching"
notices, "Preloaded" markers, "Reusing existing" / "Resolved" /
"Creating node" traces. With 600+ packages on a typical project
that's thousands of events per cold install, each paying:
1. EnvFilter dispatch (callsite cache lookup),
2. fmt::layer format (target + line + thread_id + message),
3. tracing_appender::non_blocking channel send.
Steps 2-3 run on resolver threads; the format output landed in a
multi-megabyte file even though most lines are pure dedup noise the
operator never reads.
Failure paths already produce structured `anyhow!()` chains with full
URL + name + status context — `tracing::debug!("Fetching ... from
{url}")` is redundant at start, the error chain has the same data on
failure. Cache hit/miss, "Reusing", "found existing deps" are
implementation details that never inform user-facing diagnosis;
removing them keeps the file log focused on phase markers + statistics.
Measured on a 96-package cold install with `UTOO_FILE_LOG=debug`:
before: 2634 lines, 375 KB
after: 715 lines, 90 KB (-73% lines, -76% size)
ruborist's own emissions drop from ~2200 events to 14 (phase markers
only); the remainder is hyper / rustls / reqwest debug noise unaffected
by this change.
Kept (rare, informative for diagnosis):
- Phase markers: preload start/stats, build phase elapsed
- Override matched / Skipped optional / Conflict / Failed to preload
Dropped:
- service/cache.rs: 6× memory hit/insert per-package
- service/manifest.rs: 2× "Fetching ... from {url}" per request
- service/registry.rs: ETag/store-hit/cache-miss per resolve
- resolver/preload.rs: "Preloaded {}@{}" per package
- resolver/builder.rs: "Processing/Reusing/Creating/Need to resolve/Resolved" per BFS step
- resolver/version.rs: "Using dist-tags 'latest'" per resolve
- model/graph.rs: "found existing deps reuse" per BFS edge
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
Contributor
There was a problem hiding this comment.
Code Review
This pull request removes numerous tracing::debug! logging statements across the codebase, specifically within the dependency graph, resolver, and service modules. These changes streamline the code by removing verbose debug output during dependency resolution, manifest fetching, and cache operations. I have no feedback to provide.
…text Companion to #2880's ruborist hot-path log cleanup. Extends the same discipline to the pm side and fixes three real bugs in failure paths. ## Network retry: URL spam (downloader.rs) `download_bytes` retried up to 10 times and printed `tracing::warn!("Retry N/10 - Network error: ..., url: {url}")` on every attempt — plus an outer `inspect_err(|e| warn!("Download failed: name@version: e"))` at the call site, plus `.context( "Download failed after retries")` at the bottom that didn't even include the URL. One transient network hiccup = 12 log lines, URL repeated 10x. Fix: drop per-attempt warns. The retry framework already retries silently; final failure surfaces through `with_context(|| format!( "Download failed after retries: {url}"))` once. Per-package "Cache hit" / "Downloaded" / "URL not found" debug noise also dropped (same class as ruborist's recent BFS log cleanup). ## Link failure: lost paths (install.rs) The pre-fix code logged `source={resolved}, target={path}` only at debug level, then returned `anyhow!("Link failed: {e}")` which dropped both paths. User saw `Link failed: Permission denied (os error 13)` with no idea which file. Paths only landed in `UTOO_FILE_LOG=debug` capture, invisible to default CLI output. Fix: `link(...).await.with_context(|| format!("Link failed: {resolved} -> {path}"))?;` — paths now ride in the returned error's context chain. ## Hardlink fallback: per-file warn spam (cloner.rs) EXDEV cross-device failure already latched `force_copy = true` so subsequent files used copy. But the non-EXDEV branch (EMLINK / EPERM / ...) had no such latch — every failing file in a multi-thousand-file package fired its own warn line. Fix: latch a per-package `warned_per_file` bool, warn once with "further per-file failures suppressed" suffix, silently fall back for the rest. ## Optional dep: error chain dropped (install.rs) `tracing::warn!("Optional dependency {name} failed (ignored)")` had no `e`, user couldn't tell why. Inconsistent with the sibling at line 263 which does include `e`. Now: `... failed (ignored): {e:#}` with `{:#}` for full anyhow chain. ## classify_status: tracing/anyhow duplication (ruborist/fetch.rs) Each `tracing::warn!` in the match arms carried the same data the `anyhow!` immediately constructed — but the warn fires per retry attempt while the anyhow chain only surfaces on final failure. Stacked with downloader's per-attempt warns at the outer layer, one HTTP 500 was 6 separate emissions for the same fact. Fix: drop the per-attempt warns. anyhow chain owns the URL+status; caller's `with_context` adds the boundary annotation on final failure. ## Per-package debug noise (cloner.rs / install.rs / downloader.rs) Same class as #2880's ruborist cleanup — `Cloned: name@version`, `validating failed, since it's not a directory`, `cpu skipped`, `os skipped`, `Skipping omitted dependency`, etc. all fire per package on cold installs. None of them inform user-facing diagnosis and the extraction-thread CPU + non_blocking channel send isn't free. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
…nventions New review dimension covering the patterns the recent log audit (#2880 + follow-up) surfaced: - 14.1 Log level discipline — never per-package debug! in BFS hot paths (rule of thumb: if a project has 600+ packages and a callsite fires once per package, it produces multi-MB logs and CPU on resolver / extractor threads via non_blocking format/send) - 14.2 Don't double-log a failure — pick exactly one of warn vs anyhow chain; sibling layers are duplication - 14.3 Preserve context when wrapping errors — paths/URLs in with_context, not in opt-in debug - 14.4 anyhow idioms — with_context lazy closure, bail!, {:#} for full chain - 14.5 Per-incident warns inside loops — latch a "warned once" bool; retry frameworks should swallow per-attempt failures silently - 14.6 Failure paths must include the resource — URL for network, path for fs, source+target for link, command+args for spawn Adds 7 new anti-patterns A27-A33 to the quick-reference grep table: - A27 per-package debug in hot path - A28 retry-loop warn duplication - A29 lost context in returned error - A30 eager .context(format!()) - A31 source chain stripped via map_err - A32 outer-only error format ({} vs {:#}) - A33 per-iteration warn spam Updates the dimension count (12 -> 14) and anti-pattern range (A1-A26 -> A1-A33) in cross-references. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
📊 pm-bench-phases ·
|
| PM | wall | ±σ | user | sys | RSS | pgMinor |
|---|---|---|---|---|---|---|
| bun | 15.50s | 2.12s | 9.64s | 9.60s | 556M | 322.2K |
| utoo-next | 13.58s | 1.11s | 11.69s | 13.92s | 1.15G | 159.0K |
| utoo-npm | 13.83s | 1.09s | 12.02s | 13.89s | 1.28G | 155.1K |
| utoo | 12.20s | 2.12s | 11.33s | 13.60s | 1.19G | 158.7K |
| PM | vCtx | iCtx | netRX | netTX | cache | node_mod | lock |
|---|---|---|---|---|---|---|---|
| bun | 35.3K | 9.5K | 1.16G | 7M | 1.83G | 1.72G | 1M |
| utoo-next | 204.6K | 158.0K | 1.13G | 5M | 1.68G | 1.68G | 2M |
| utoo-npm | 205.4K | 161.7K | 1.14G | 6M | 1.68G | 1.68G | 2M |
| utoo | 187.5K | 140.4K | 1.13G | 5M | 1.68G | 1.68G | 2M |
p1_resolve
| PM | wall | ±σ | user | sys | RSS | pgMinor |
|---|---|---|---|---|---|---|
| bun | 5.59s | 0.62s | 3.65s | 1.15s | 471M | 217.3K |
| utoo-next | 10.00s | 0.37s | 6.52s | 1.49s | 421M | 74.0K |
| utoo-npm | 10.92s | 0.58s | 6.39s | 1.06s | 426M | 73.3K |
| utoo | 8.61s | 1.08s | 5.86s | 1.28s | 423M | 69.5K |
| PM | vCtx | iCtx | netRX | netTX | cache | node_mod | lock |
|---|---|---|---|---|---|---|---|
| bun | 20.0K | 1.2K | 202M | 3M | 104M | - | 1M |
| utoo-next | 103.0K | 7.2K | 197M | 2M | 7M | 3M | 2M |
| utoo-npm | 74.1K | 1.8K | 208M | 2M | 9M | 5M | 2M |
| utoo | 82.1K | 4.0K | 197M | 2M | 7M | 3M | 2M |
p3_cold_install
| PM | wall | ±σ | user | sys | RSS | pgMinor |
|---|---|---|---|---|---|---|
| bun | 7.78s | 0.61s | 6.13s | 9.98s | 451M | 194.6K |
| utoo-next | 12.31s | 4.51s | 5.71s | 12.08s | 821M | 115.5K |
| utoo-npm | 10.68s | 1.03s | 5.73s | 11.81s | 746M | 92.5K |
| utoo | 12.76s | 2.57s | 5.71s | 12.02s | 758M | 106.1K |
| PM | vCtx | iCtx | netRX | netTX | cache | node_mod | lock |
|---|---|---|---|---|---|---|---|
| bun | 11.9K | 8.0K | 993M | 4M | 1.73G | 1.73G | 1M |
| utoo-next | 151.2K | 108.9K | 965M | 4M | 1.67G | 1.67G | 2M |
| utoo-npm | 142.5K | 111.1K | 965M | 4M | 1.67G | 1.67G | 2M |
| utoo | 147.2K | 103.0K | 965M | 4M | 1.67G | 1.67G | 2M |
p4_warm_link
| PM | wall | ±σ | user | sys | RSS | pgMinor |
|---|---|---|---|---|---|---|
| bun | 3.28s | 0.06s | 0.22s | 2.33s | 135M | 32.5K |
| utoo-next | 2.33s | 0.20s | 0.61s | 3.92s | 83M | 18.6K |
| utoo-npm | 2.25s | 0.15s | 0.59s | 3.83s | 83M | 18.9K |
| utoo | 2.23s | 0.11s | 0.51s | 3.77s | 82M | 19.2K |
| PM | vCtx | iCtx | netRX | netTX | cache | node_mod | lock |
|---|---|---|---|---|---|---|---|
| bun | 354 | 24 | 7M | 27K | 1.88G | 1.72G | 1M |
| utoo-next | 49.0K | 21.1K | 15K | 12K | 1.67G | 1.67G | 2M |
| utoo-npm | 47.1K | 21.3K | 16K | 33K | 1.67G | 1.67G | 2M |
| utoo | 46.8K | 19.7K | 16K | 34K | 1.68G | 1.67G | 2M |
npmmirror.com: no output captured.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Strip ~17
tracing::debug!()callsites from ruborist's resolve hot path. Each per-package event paid 3 costs on resolver threads: (1)EnvFilterdispatch, (2)fmt::layerformat with target + line + thread_id, (3)tracing_appender::non_blockingchannel send. With 600+ packages on a typical project that adds up to thousands of events per cold install — and the resulting multi-MB file log was ~95% dedup/cache-hit noise no operator ever reads.Failure paths already produce structured
anyhow!()chains with URL + name + status, sotracing::debug!(\"Fetching ... from {url}\")adds nothing the error chain doesn't already carry.Measured impact (96-package cold install,
UTOO_FILE_LOG=debug)The 14 remaining ruborist events are all phase markers (preload start/stats, build elapsed, registry/cache config). The other ~700 lines come from external crates (hyper / rustls / reqwest debug). Default file filter (
utoo=infoafter #2872's log filter change, orutoo=debugtoday) emits 0 lines from ruborist hot path.What's dropped
service/cache.rsservice/manifest.rsservice/registry.rsresolver/preload.rsresolver/builder.rsresolver/version.rsmodel/graph.rsWhat's kept
Failed to preload,Skipped optional,Override matched,Conflict depsWhy ship as a standalone PR (not bundled with #2872)
This is a pure log hygiene change applied directly on top of
next, with no dependency on worker-pool or the rest of the #2818 perf bundle. Isolating it lets us measure the bench delta cleanly:31857362(file filter info+) hypothesisTest plan
cargo fmtcleancargo clippy -p utoo-ruborist -p utoo-pm --all-targets -- -D warnings --no-depscleancargo test -p utoo-ruborist: 162 passcargo test -p utoo-pm: 244 pass (1 pre-existing flaky network test in isolation)utoo depssmoke test on 96-pkg cold install: works, log size −76%pm-bench-phases-linux— main interest is whether ratio vs bun moves and σ collapses🤖 Generated with Claude Code