feat(cli): Allow logging to chrome traces #13399

epage · 2024-02-05T20:32:54Z

What does this PR try to resolve?

The time from executing cargo to executing rustc is 230 ms. I wonder if there’s scope for caching whatever expensive computations cargo is doing here.

Source: https://davidlattimore.github.io/working-on-rust-iteration-time.html

This made me curious where the time was going. I've been meaning to try out tracing-chrome for a while and this gave me the opportunity.

This adds CARGO_LOG_PROFILE=<bool> and CARGO_LOG_PROFILE_CAPTURE_ARGS=<bool> for enabling and controlling these trace files. These are perma-unstable env variables.

Traces can be viewed at https://ui.perfetto.dev or chrome://tracing.

Example: no-op cargo check run on cargo-nextest:

TODO

Find a place to document this, see https://doc.crates.io/contrib/tests/profiling.html#internal-profiler

How should we test and review this PR?

I looked in config/ and didn't see a env variable parser to reuse (get_cv_with_env is too specialized).

Additional information

In past projects, I've been able to use features like this to better understand code bases, bugs, etc. Hopefully this can evolve to help on-board people one day.

Most of the implementation was inspired by https://github.com/arxanas/git-branchless/blob/2923924dfbff07faa61d50771b6604cb18e64bc8/git-branchless-invoke/src/lib.rs#L55

tracing-chrome hasn't received updates recently, but it is also fairly quiet on Issues and PRs, so this might just be "maturity". It does have over a million downloads. It also is only enabled if explicitly opted into.

rustup added trace visualization in rust-lang/rustup#3287 using open telemetry but it is behind a feature flag and and requires running a server to receive the traces.

rustbot · 2024-02-05T20:32:59Z

r? @ehuss

(rustbot has picked a reviewer for you, use r? to override)

weihanglo · 2024-02-05T20:49:41Z

What's the difference between tracing-chrome and samply, and maybe other old school dtrace flamgraph approaches?

epage · 2024-02-05T21:08:51Z

What's the difference between tracing-chrome and samply, and maybe other old school dtrace flamgraph approaches?

This builds on tracing

Limited to what you trace
But doesn't require any other special binary setup
But can show argument values and other information
The new instrument calls would hopefully improve the overall quality of our tracing

Overall, I'd say this is a lot more approachable solution for users asking the question "where is my build time going?", like those using --timings or Ztime-passes

arxanas · 2024-02-06T03:43:25Z

Incidentally, cargo was a hotspot when I measured it a while back, as per https://lobste.rs/s/ktyp2q/improving_incremental_test_times_rust#c_ukhulp

src/bin/cargo/main.rs

epage · 2024-02-09T18:29:44Z

src/bin/cargo/main.rs

+#[tracing::instrument(skip_all)]
 fn init_git(config: &Config) {


Aside: @Byron do you know if there should be or will be an equivalent to this in gitoxide? In the PR description is a trace that shows that this operation is 20% of the no-op cargo check time. Wondering if this is something that is worth hacking around or if its a "this will go away with git2".

This is an interesting case as its unclear to me how much 20% actually represent in absolute terms of time.
With that said, I looked at what init_git is doing and I was surprised it takes time at all - it felt like it's loading some code dynamically (which is probably wrong).

gitoxide isn't comparable with git2 as there are no globals, and everything is lazy, so I'd guess that the timing is going to be more favourable. For one, there is no equivalent to init_git - configuration is done only when opening the repository.

I hope that helps.

bors · 2024-02-20T19:58:50Z

☔ The latest upstream changes (presumably #13409) made this pull request unmergeable. Please resolve the merge conflicts.

You can browse these at https://ui.perfetto.dev

src/doc/contrib/src/tests/profiling.md

src/cargo/core/compiler/fingerprint/mod.rs

src/cargo/ops/resolve.rs

src/cargo/core/global_cache_tracker.rs

src/doc/contrib/src/tests/profiling.md

This is a follow up to rust-lang#13532 and prep for rust-lang#13399

fix(log): Trace parameters to align with profile This is a follow up to #13532 and prep for #13399

weihanglo · 2024-03-05T19:26:49Z

@bors r+

Thanks and really looking forward to this!

bors · 2024-03-05T19:26:51Z

📌 Commit 6d8708a has been approved by weihanglo

It is now in the queue for this repository.

bors · 2024-03-05T19:56:54Z

⌛ Testing commit 6d8708a with merge 00b9882...

bors · 2024-03-05T20:34:06Z

☀️ Test successful - checks-actions
Approved by: weihanglo
Pushing 00b9882 to master...

Update cargo 11 commits in f772ec0224d3755ce52ac5128a80319fb2eb45d0..c3c417b85e01a1de1633317fa55e4f1a31e346d4 2024-03-01 22:57:35 +0000 to 2024-03-06 01:16:08 +0000 - fix(rustdoc-map): dedup `--extern-html-too-url` for same unit (rust-lang/cargo#13544) - test: Add test for packaging a public dependency (rust-lang/cargo#13536) - doc: Edits for git/path dependency sections (rust-lang/cargo#13341) - feat(cli): Allow logging to chrome traces (rust-lang/cargo#13399) - fix(log): Trace parameters to align with profile (rust-lang/cargo#13538) - fix(toml): Don't warn on unset Edition if only 2015 is compatible (rust-lang/cargo#13533) - fix(cli): Trace core cargo operations (rust-lang/cargo#13532) - chore: update pulldown-cmark to 0.10.0 (rust-lang/cargo#13517) - feat(add): Fallback to `rustc -v` when no MSRV is set (rust-lang/cargo#13516) - chore(ci): Ensure lockfile is respected during MSRV testing (rust-lang/cargo#13523) - feat: Use consistent colors when testing (rust-lang/cargo#13520) r? ghost

Update cargo 14 commits in f772ec0224d3755ce52ac5128a80319fb2eb45d0..a4c63fe5388beaa09e5f91196c86addab0a03580 2024-03-01 22:57:35 +0000 to 2024-03-06 22:15:17 +0000 - fix(cli): Skip tracing-chrome for platforms without 64bit atomics (rust-lang/cargo#13551) - chore: downgrade to openssl v1.1.1 (again) (rust-lang/cargo#13550) - fix(cli): Add traces to clarify where time is going (rust-lang/cargo#13545) - fix(rustdoc-map): dedup `--extern-html-too-url` for same unit (rust-lang/cargo#13544) - test: Add test for packaging a public dependency (rust-lang/cargo#13536) - doc: Edits for git/path dependency sections (rust-lang/cargo#13341) - feat(cli): Allow logging to chrome traces (rust-lang/cargo#13399) - fix(log): Trace parameters to align with profile (rust-lang/cargo#13538) - fix(toml): Don't warn on unset Edition if only 2015 is compatible (rust-lang/cargo#13533) - fix(cli): Trace core cargo operations (rust-lang/cargo#13532) - chore: update pulldown-cmark to 0.10.0 (rust-lang/cargo#13517) - feat(add): Fallback to `rustc -v` when no MSRV is set (rust-lang/cargo#13516) - chore(ci): Ensure lockfile is respected during MSRV testing (rust-lang/cargo#13523) - feat: Use consistent colors when testing (rust-lang/cargo#13520)

rustbot assigned ehuss Feb 5, 2024

epage force-pushed the timing branch 2 times, most recently from 1736c61 to a8b6087 Compare February 5, 2024 20:46

epage force-pushed the timing branch 2 times, most recently from 58d9112 to 8ff0399 Compare February 5, 2024 20:55

weihanglo reviewed Feb 9, 2024

View reviewed changes

src/bin/cargo/main.rs Outdated Show resolved Hide resolved

src/bin/cargo/main.rs Outdated Show resolved Hide resolved

src/bin/cargo/main.rs Show resolved Hide resolved

epage force-pushed the timing branch from 8ff0399 to 7051f39 Compare February 9, 2024 17:38

epage commented Feb 9, 2024

View reviewed changes

weihanglo mentioned this pull request Mar 4, 2024

fix(cli): Trace core cargo operations #13532

Merged

epage added 4 commits March 5, 2024 08:43

feat(cli): Log to chrome trace

d188808

You can browse these at https://ui.perfetto.dev

docs(contrib): Document chrome tracing, rather than bespoke profiling

b9a939a

fix(cli): Remove bespoke profiling

caf4c30

fix(cli): Remove __ prefix

6d8708a

epage force-pushed the timing branch from 7051f39 to 6d8708a Compare March 5, 2024 16:18

rustbot added A-build-scripts Area: build.rs scripts A-cache-messages Area: caching of compiler messages A-documenting-cargo-itself Area: Cargo's documentation labels Mar 5, 2024

rustbot added the A-rebuild-detection Area: rebuild detection and fingerprinting label Mar 5, 2024

epage marked this pull request as ready for review March 5, 2024 16:19

epage commented Mar 5, 2024

View reviewed changes

src/doc/contrib/src/tests/profiling.md Show resolved Hide resolved

weihanglo reviewed Mar 5, 2024

View reviewed changes

src/cargo/core/compiler/fingerprint/mod.rs Show resolved Hide resolved

src/cargo/ops/resolve.rs Show resolved Hide resolved

src/cargo/core/global_cache_tracker.rs Show resolved Hide resolved

src/doc/contrib/src/tests/profiling.md Show resolved Hide resolved

epage added a commit to epage/cargo that referenced this pull request Mar 5, 2024

fix(log): Trace parameters to align with profile

956e3fc

This is a follow up to rust-lang#13532 and prep for rust-lang#13399

epage mentioned this pull request Mar 5, 2024

fix(log): Trace parameters to align with profile #13538

Merged

epage added a commit to epage/cargo that referenced this pull request Mar 5, 2024

fix(log): Trace parameters to align with profile

f16067a

This is a follow up to rust-lang#13532 and prep for rust-lang#13399

bors added a commit that referenced this pull request Mar 5, 2024

Auto merge of #13538 - epage:trace, r=weihanglo

39e21a9

fix(log): Trace parameters to align with profile This is a follow up to #13532 and prep for #13399

weihanglo approved these changes Mar 5, 2024

View reviewed changes

bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Mar 5, 2024

bors merged commit 00b9882 into rust-lang:master Mar 5, 2024
23 checks passed

epage deleted the timing branch March 5, 2024 20:54

weihanglo mentioned this pull request Mar 6, 2024

Update cargo rust-lang/rust#122054

Merged

rustbot added this to the 1.78.0 milestone Mar 7, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(cli): Allow logging to chrome traces #13399

feat(cli): Allow logging to chrome traces #13399

epage commented Feb 5, 2024 •

edited

rustbot commented Feb 5, 2024

weihanglo commented Feb 5, 2024

epage commented Feb 5, 2024

arxanas commented Feb 6, 2024

epage Feb 9, 2024

Byron Feb 10, 2024

bors commented Feb 20, 2024

weihanglo commented Mar 5, 2024

bors commented Mar 5, 2024

bors commented Mar 5, 2024

bors commented Mar 5, 2024

		#[tracing::instrument(skip_all)]
		fn init_git(config: &Config) {

feat(cli): Allow logging to chrome traces #13399

feat(cli): Allow logging to chrome traces #13399

Conversation

epage commented Feb 5, 2024 • edited

What does this PR try to resolve?

How should we test and review this PR?

Additional information

rustbot commented Feb 5, 2024

weihanglo commented Feb 5, 2024

epage commented Feb 5, 2024

arxanas commented Feb 6, 2024

epage Feb 9, 2024

Choose a reason for hiding this comment

Byron Feb 10, 2024

Choose a reason for hiding this comment

bors commented Feb 20, 2024

weihanglo commented Mar 5, 2024

bors commented Mar 5, 2024

bors commented Mar 5, 2024

bors commented Mar 5, 2024

epage commented Feb 5, 2024 •

edited