Implement initial support for timing sections (`--json=timings`) #142123

Kobzol · 2025-06-06T15:30:49Z

This PR implements initial support for emitting high-level compilation section timings. The idea is to provide a very lightweight way of emitting durations of various compilation sections (frontend, backend, linker, or on a more granular level macro expansion, typeck, borrowck, etc.). The ultimate goal is to stabilize this output (in some form), make Cargo pass --json=timings and then display this information in the HTML output of cargo build --timings, to make it easier to quickly profile "what takes so long" during the compilation of a Cargo project. I would personally also like if Cargo printed some of this information in the interactive cargo build output, but the build --timings use-case is the main one.

Now, this information is already available with several other sources, but I don't think that we can just use them as they are, which is why I proposed a new way of outputting this data (--json=timings):

This data is available under -Zself-profile, but that is very expensive and forever unstable. It's just a too big of a hammer to tell us the duration it took to run the linker.
It could also be extracted with -Ztime-passes. That is pretty much "for free" in terms of performance, and it can be emitted in a structured form to JSON via -Ztime-passes-format=json. I guess that one alternative might be to stabilize this flag in some form, but that form might just be --json=timings? I guess what we could do in theory is take the already emitted time passes and reuse them for --json=timings. Happy to hear suggestions!

I'm sending this PR mostly for a vibeck, to see if the way I implemented it is passable. There are some things to figure out:

How do we represent the sections? Originally I wanted to output { section, duration }, but then I realized that it might be more useful to actually emit start and end events. Both because it enables to see the output incrementally (in case compilation takes a long time and you read the outputs directly, or Cargo decides to show this data in cargo build some day in the future), and because it makes it simpler to represent hierarchy (see below). The timestamps currently emit microseconds elapsed from a predetermined point in time (~start of rustc), but otherwise they are fully opaque, and should be only ever used to calculate the duration using end - start. We could also precompute the duration for the user in the end event, but that would require doing more work in rustc, which I would ideally like to avoid :P
Do we want to have some form of hierarchy? I think that it would be nice to show some more granular sections rather than just frontend/backend/linker (e.g. macro expansion, typeck and borrowck as a part of the frontend). But for that we would need some way of representing hierarchy. A simple way would be something like { parent: "frontend" }, but I realized that with start/end timestamps we get the hierarchy "for free", only the client will need to reconstruct it from the order of start/end events (e.g. start A, start B means that B is a child of A).
What exactly do we want to stabilize? This is probably a question for later. I think that we should definitely stabilize the format of the emitted JSON objects, and maybe some specific section names (but we should also make it clear that they can be missing, e.g. you don't link everytime you invoke rustc).

The PR be tested e.g. with rustc +stage1 src/main.rs --json=timings --error-format=json -Zunstable-options on a crate without dependencies (it is not easy to use --json with stock Cargo, because it also passes this flag to rustc, so this will later need Cargo integration to be usable with it).

Zulip discussions: #t-compiler > Outputting time spent in various compiler sections

MCP: rust-lang/compiler-team#873

r? @nnethercote

rustbot · 2025-06-06T15:30:53Z

nnethercote is not on the review rotation at the moment.
They may take a while to respond.

compiler/rustc_errors/src/json.rs

compiler/rustc_session/src/config.rs

nnethercote · 2025-06-12T05:13:42Z

compiler/rustc_errors/src/json.rs

+        let kind = match kind {
+            TimingSectionKind::Start => "start",
+            TimingSectionKind::End => "end",
+        };


This could be a method on TimingSectionKind.

Hmm, but the TimingSectionKind is a shared data structure for all emitters, and this form of output is specific for JSON. It should IMO live here, in theory we could emit the timings also in other formats. It also avoids having to go to a different file to see how the output format looks like.

I'm fine with moving it to a function in the json module, but I don't think it belongs as a method on the section kind.

nnethercote · 2025-06-12T05:14:22Z

compiler/rustc_errors/src/json.rs

+        };
+        let name = match section {
+            TimingSection::Linking => "link",
+        };


Ditto, for TimingSection.

compiler/rustc_errors/src/json.rs

nnethercote · 2025-06-12T05:25:29Z

Seems reasonable as a starting point. I feel like hierarchy is inevitable -- every profiler I've ever written has ended up with it.

Kobzol · 2025-06-12T11:35:01Z

I agree. Are you fine with the "implicit hierarchy", which then has to be reconstructed by the user reading the JSON events?

nnethercote · 2025-06-13T05:53:48Z

Sure. Keeping it simple to start with sounds good, given that it's somewhat unclear exactly how this data will be used. r=me when you're ready.

Kobzol · 2025-06-13T14:03:20Z

Added documentation and fixed a few review remarks.

bjorn3 · 2025-06-14T08:57:22Z

compiler/rustc_errors/src/json.rs

+        let name = match section {
+            TimingSection::Linking => "link",
+        };
+        let timestamp = SystemTime::now()


I think this should use Instant rather than SystemTime. Using the latter causes issues when changing the system time during a build, for example because your ntp daemon finally got an internet connection. And IMHO it should preferrably use CLOCK_MONOTONIC rather than CLOCK_BOOTTIME as it doesn't make sense to count time where the system is suspended in performance profiles.

We already use system time for some incr dir names, I think, but you're right that for profiling Instant makes more sense. But then I have to count the duration from some origin time again. Before it was from the creation of the JSON emitter, but that had some issues w.r.t. multiple emitters existing. Should I just take a snapshot when rustc starts or something? 🤔

Right and Instant doesn't provide a way to serialize it. Maybe call clock_gettime(CLOCK_MONOTONIC) (unix) or QueryPerformanceCounter (windows) directly and return the raw result?

Uhh, I would really like to avoid dealing with OS specific code here, especially since the main use-case for this right now is Cargo, which will most likely ignore the timestamp field anyway, because it streams the output and just uses current time when an event is generated for the timestamp. I'll just go back to instant, but this take count it from the start of the compilation session.

bors · 2025-06-16T04:31:59Z

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

Kobzol · 2025-06-16T09:51:56Z

Rebased. I made some changes based on the discussion in review comments around the usage of Instant vs SystemTime, so not approving yet.

@rustbot ready

src/doc/rustc/src/json.md

nnethercote · 2025-06-18T00:55:31Z

r=me with the nits above addressed. I figure this output will need to be used in earnest by some external tool before we really know what the exact format should be.

Kobzol · 2025-06-18T07:45:12Z

r=me with the nits above addressed. I figure this output will need to be used in earnest by some external tool before we really know what the exact format should be.

Definitely agreed. I plan to integrate this into Cargo once this PR is merged.

@bors r=nnethercote

bors · 2025-06-18T07:45:14Z

📌 Commit 7e42320 has been approved by nnethercote

It is now in the queue for this repository.

Implement initial support for timing sections (`--json=timings`) This PR implements initial support for emitting high-level compilation section timings. The idea is to provide a very lightweight way of emitting durations of various compilation sections (frontend, backend, linker, or on a more granular level macro expansion, typeck, borrowck, etc.). The ultimate goal is to stabilize this output (in some form), make Cargo pass `--json=timings` and then display this information in the HTML output of `cargo build --timings`, to make it easier to quickly profile "what takes so long" during the compilation of a Cargo project. I would personally also like if Cargo printed some of this information in the interactive `cargo build` output, but the `build --timings` use-case is the main one. Now, this information is already available with several other sources, but I don't think that we can just use them as they are, which is why I proposed a new way of outputting this data (`--json=timings`): - This data is available under `-Zself-profile`, but that is very expensive and forever unstable. It's just a too big of a hammer to tell us the duration it took to run the linker. - It could also be extracted with `-Ztime-passes`. That is pretty much "for free" in terms of performance, and it can be emitted in a structured form to JSON via `-Ztime-passes-format=json`. I guess that one alternative might be to stabilize this flag in some form, but that form might just be `--json=timings`? I guess what we could do in theory is take the already emitted time passes and reuse them for `--json=timings`. Happy to hear suggestions! I'm sending this PR mostly for a vibeck, to see if the way I implemented it is passable. There are some things to figure out: - How do we represent the sections? Originally I wanted to output `{ section, duration }`, but then I realized that it might be more useful to actually emit `start` and `end` events. Both because it enables to see the output incrementally (in case compilation takes a long time and you read the outputs directly, or Cargo decides to show this data in `cargo build` some day in the future), and because it makes it simpler to represent hierarchy (see below). The timestamps currently emit microseconds elapsed from a predetermined point in time (~start of rustc), but otherwise they are fully opaque, and should be only ever used to calculate the duration using `end - start`. We could also precompute the duration for the user in the `end` event, but that would require doing more work in rustc, which I would ideally like to avoid :P - Do we want to have some form of hierarchy? I think that it would be nice to show some more granular sections rather than just frontend/backend/linker (e.g. macro expansion, typeck and borrowck as a part of the frontend). But for that we would need some way of representing hierarchy. A simple way would be something like `{ parent: "frontend" }`, but I realized that with start/end timestamps we get the hierarchy "for free", only the client will need to reconstruct it from the order of start/end events (e.g. `start A`, `start B` means that `B` is a child of `A`). - What exactly do we want to stabilize? This is probably a question for later. I think that we should definitely stabilize the format of the emitted JSON objects, and *maybe* some specific section names (but we should also make it clear that they can be missing, e.g. you don't link everytime you invoke `rustc`). The PR be tested e.g. with `rustc +stage1 src/main.rs --json=timings --error-format=json -Zunstable-options` on a crate without dependencies (it is not easy to use `--json` with stock Cargo, because it also passes this flag to `rustc`, so this will later need Cargo integration to be usable with it). Zulip discussions: [#t-compiler > Outputting time spent in various compiler sections](https://rust-lang.zulipchat.com/#narrow/channel/131828-t-compiler/topic/Outputting.20time.20spent.20in.20various.20compiler.20sections/with/518850162) MCP: rust-lang/compiler-team#873 r? `@nnethercote`

Rollup of 12 pull requests Successful merges: - #135656 (Add `-Z hint-mostly-unused` to tell rustc that most of a crate will go unused) - #140774 (Affirm `-Cforce-frame-pointers=off` does not override) - #141610 (Stabilize `feature(generic_arg_infer)`) - #142123 (Implement initial support for timing sections (`--json=timings`)) - #142383 (CodeGen: rework Aggregate implemention for rvalue_creates_operand cases) - #142502 (rustdoc_json: improve handling of generic args) - #142591 (Add spawn APIs for BootstrapCommand to support deferred command execution) - #142606 (AsyncDrop trait without sync Drop generates an error) - #142619 (apply clippy::or_fun_call) - #142624 (Actually take `--build` into account in bootstrap) - #142627 (Add `StepMetadata` to describe steps) - #142660 (remove joboet from review rotation) r? `@ghost` `@rustbot` modify labels: rollup

rustbot assigned nnethercote Jun 6, 2025

rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. labels Jun 6, 2025

Mark-Simulacrum reviewed Jun 8, 2025

View reviewed changes

compiler/rustc_errors/src/json.rs Outdated Show resolved Hide resolved

nnethercote reviewed Jun 12, 2025

View reviewed changes

nnethercote added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Jun 12, 2025

bjorn3 reviewed Jun 14, 2025

View reviewed changes

Add parsing of --json=timings

7ad5248

Kobzol force-pushed the timings branch from 806b8bf to e704596 Compare June 16, 2025 09:51

Kobzol added 2 commits June 16, 2025 11:51

Add infrastructure for emitting timing sections

c9d3059

Emit linker timing section

60a59ae

Kobzol force-pushed the timings branch from e704596 to 60a59ae Compare June 16, 2025 09:51

rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Jun 16, 2025

nnethercote reviewed Jun 18, 2025

View reviewed changes

src/doc/rustc/src/json.md Show resolved Hide resolved

nnethercote reviewed Jun 18, 2025

View reviewed changes

src/doc/rustc/src/json.md Outdated Show resolved Hide resolved

nnethercote added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Jun 18, 2025

Clarify documentation

7e42320

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-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Jun 18, 2025

Kobzol mentioned this pull request Jun 18, 2025

Rollup of 12 pull requests #142665

Open

Implement initial support for timing sections (--json=timings) #142123

Are you sure you want to change the base?

Implement initial support for timing sections (--json=timings) #142123

Conversation

Kobzol commented Jun 6, 2025

Uh oh!

rustbot commented Jun 6, 2025

Uh oh!

Uh oh!

Uh oh!

Uh oh!

nnethercote Jun 12, 2025

Choose a reason for hiding this comment

Uh oh!

Kobzol Jun 13, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nnethercote Jun 12, 2025

Choose a reason for hiding this comment

Uh oh!

Uh oh!

nnethercote commented Jun 12, 2025

Uh oh!

Kobzol commented Jun 12, 2025

Uh oh!

nnethercote commented Jun 13, 2025

Uh oh!

Kobzol commented Jun 13, 2025

Uh oh!

bjorn3 Jun 14, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Kobzol Jun 14, 2025

Choose a reason for hiding this comment

Uh oh!

bjorn3 Jun 14, 2025

Choose a reason for hiding this comment

Uh oh!

Kobzol Jun 16, 2025

Choose a reason for hiding this comment

Uh oh!

bors commented Jun 16, 2025

Uh oh!

Kobzol commented Jun 16, 2025

Uh oh!

Uh oh!

Uh oh!

nnethercote commented Jun 18, 2025

Uh oh!

Kobzol commented Jun 18, 2025

Uh oh!

bors commented Jun 18, 2025

Uh oh!

Uh oh!

Implement initial support for timing sections (`--json=timings`) #142123

Implement initial support for timing sections (`--json=timings`) #142123

Kobzol Jun 13, 2025 •

edited

Loading

bjorn3 Jun 14, 2025 •

edited

Loading