Add profiler to bootstrap command

[Shourya742]

This PR adds command profiling to the bootstrap command. It tracks the total execution time and records cache hits for each command. It also provides the ability to export execution result to a JSON file. Integrating this with Chrome tracing could further enhance observability.

r? @Kobzol

[Kobzol]

Thank you! I don't think that we'll need JSON output for now, I think that the main output should be some lightly formatted text that will be human interpretable.

[Kobzol]

Gonna try it tomorrow.

[Kobzol]

Ok I tried it locally. Good job, it seem to work as expected! I can already see this becoming quite useful when dealing with reports of bootstrap being slow.

I have some suggestions/feedback:

• Streaming Cargo commands (which are the most expensive) ones are not recorded. Could you also add support for profiling these?
• The execution and cache hit timestamps are not very useful. I thought they would be, but in this aggregated output they aren't. Also outputting them as UNIX timestamp is not very useful, and we'd have to depend on e.g. time or chrono to improve that, and that's not worth it. You were right when you said that for the trace itself Chrome will be better, I agree now. Sorry! So let's just remove the timestamps and only remember the cache hit counts and the execution duration(s).
• Some aggregated stats at the end of the report would be nice. Like the total number of unique commands (fingerprints) that were recorded, the total number of executions (and the aggregated duration of all executions), the total time of bootstrap outside of command executions (so that we can see how large % of bootstrap time was spent on commands specifically - just take a timestamp at the start of bootstrap and when writing the summary, compute the duration, and subtract the sum of command execution durations), the total number of cache hits, and the estimated amount of time saved due to cache hits (take avg. duration of each cached command and multiply it by the number of cache hits it had, and sum that up).

Taking this a bit further, it would be nice to add I/O operations tracing:

• Add trace! calls to I/O operations (there is a lot of methods that do file/dir copy, symlinking, network downloads, etc.), so that it can be visualized in Chrome. Also ideally find places where I/O is done ad-hoc, and port it to the I/O helper functions on Builder.
• Add these I/O operations to the profile summary, so that we can compare the total durations of I/O and command execution.

But that should be left for a follow-up PR.

[rustbot]

The rustc-dev-guide subtree was changed. If this PR only touches the dev guide consider submitting a PR directly to rust-lang/rustc-dev-guide otherwise thank you for updating the dev guide with your changes.

cc @BoxyUwU, @jieyouxu, @Kobzol, @tshepang

[Kobzol]

Thanks! Now the output is much cleaner. Some more thoughts:

• In addition to max_duration, also print total_duration per command (in most cases, it will be the same as max_duration), and print the % of total bootstrap execution time. So e.g. if bootstrap ran for 5s, and a single command was executed three times and in total it took 3s, it should print 60%. E.g. max_duration=2.06s, total_duration=4.5s (60% of total)

Looks like some of our command parallelization can make the aggregated summary a bit weird :D I thought about this, but haven't expected it to be an issue in practice.

Total time spent in command executions: 2.45s
Total bootstrap time: 2.33s
Time spent outside command executions: 0.00ns

I think it's fine though, no need to handle concurrency here.

[Kobzol]

Looks good! Please squash and we can merge this. Great work!

[Kobzol]

Thank you!

@bors r+

[bors]

📌 Commit 7de1174 has been approved by Kobzol

It is now in the queue for this repository.