-
Notifications
You must be signed in to change notification settings - Fork 13.7k
Add tracing to various miscellaneous functions #145306
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Merged
Merged
+15
−5
Conversation
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
RalfJung
reviewed
Aug 18, 2025
RalfJung
reviewed
Aug 18, 2025
Thanks for the review, I addressed the comments |
LGTM. :) Please squash this into a single commit. |
Reminder, once the PR becomes ready for a review, use |
Also use tracing macro syntax instead of format()
@rustbot ready |
@bors r+ rollup |
jhpratt
added a commit
to jhpratt/rust
that referenced
this pull request
Aug 18, 2025
Add tracing to various miscellaneous functions This PR adds tracing to: - `ty.fn_sig()`. There is only one place where `fn_sig` is called for real within `rustc_const_eval`. There are three other places where it's called, but one is inside `ConstCx::fn_sig` (which does not seem to be used anywhere), another is under `if cfg!(debug_assertions)`, and the last is within `call_main` and thus gets called only once. - the two possible things `find_mir_or_eval_fn` can do: "emulate_foreign_item" and "load_mir" - all calls to `Const.eval()` within the Miri or the `rustc_const_eval` codebase. - a separate commit also fixes the style of some tracing macros Those are all quite long-lived operations, that in total make up for 6-7% of the total time spent in the program. I found out about them by looking for long periods of time that were previously not traced at all, using this SQL query in ui.perfetto.dev: ```sql with ordered as (select s1.*, row_number() over (order by s1.ts) as rn from slices as s1 where s1.parent_id is null and s1.dur > 0 and s1.name != "frame" and s1.name != "step" and s1.name != "backtrace") select a.ts+a.dur as ts, b.ts-a.ts-a.dur as dur, a.id, a.track_id, a.category, a.depth, a.stack_id, a.parent_stack_id, a.parent_id, a.arg_set_id, a.thread_ts, a.thread_instruction_count, a.thread_instruction_delta, a.cat, a.slice_id, "empty" as name from ordered as a inner join ordered as b on a.rn=b.rn-1 /*where b.ts-a.ts-a.dur > 5000*/ order by b.ts-a.ts-a.dur desc ``` <details> <summary>How the table was obtained</summary> The above image was obtained in ui.perfetto.dev with the following SQL query after obtaining a trace file by running Miri on the following Rust code with `n=100`. ```sql select "TOTAL PROGRAM DURATION" as name, count(*), max(ts + dur) as "sum(dur)", 100.0 as "%", null as "min(dur)", null as "max(dur)", null as "avg(dur)", null as "stddev(dur)" from slices union select "TOTAL OVER ALL SPANS (excluding events)" as name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" and dur > 0 union select name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" group by name order by sum(dur) desc, count(*) desc ``` ```rust fn main() { let n: usize = std::env::args().nth(1).unwrap().parse().unwrap(); let mut v = (0..n).into_iter().collect::<Vec<_>>(); for i in &mut v { *i += 1; } } ``` </details> <img width="1689" height="317" alt="image" src="https://github.com/user-attachments/assets/ee2c81f5-d74a-4da5-b4b6-ab2770175b14" />
jhpratt
added a commit
to jhpratt/rust
that referenced
this pull request
Aug 18, 2025
Add tracing to various miscellaneous functions This PR adds tracing to: - `ty.fn_sig()`. There is only one place where `fn_sig` is called for real within `rustc_const_eval`. There are three other places where it's called, but one is inside `ConstCx::fn_sig` (which does not seem to be used anywhere), another is under `if cfg!(debug_assertions)`, and the last is within `call_main` and thus gets called only once. - the two possible things `find_mir_or_eval_fn` can do: "emulate_foreign_item" and "load_mir" - all calls to `Const.eval()` within the Miri or the `rustc_const_eval` codebase. - a separate commit also fixes the style of some tracing macros Those are all quite long-lived operations, that in total make up for 6-7% of the total time spent in the program. I found out about them by looking for long periods of time that were previously not traced at all, using this SQL query in ui.perfetto.dev: ```sql with ordered as (select s1.*, row_number() over (order by s1.ts) as rn from slices as s1 where s1.parent_id is null and s1.dur > 0 and s1.name != "frame" and s1.name != "step" and s1.name != "backtrace") select a.ts+a.dur as ts, b.ts-a.ts-a.dur as dur, a.id, a.track_id, a.category, a.depth, a.stack_id, a.parent_stack_id, a.parent_id, a.arg_set_id, a.thread_ts, a.thread_instruction_count, a.thread_instruction_delta, a.cat, a.slice_id, "empty" as name from ordered as a inner join ordered as b on a.rn=b.rn-1 /*where b.ts-a.ts-a.dur > 5000*/ order by b.ts-a.ts-a.dur desc ``` <details> <summary>How the table was obtained</summary> The above image was obtained in ui.perfetto.dev with the following SQL query after obtaining a trace file by running Miri on the following Rust code with `n=100`. ```sql select "TOTAL PROGRAM DURATION" as name, count(*), max(ts + dur) as "sum(dur)", 100.0 as "%", null as "min(dur)", null as "max(dur)", null as "avg(dur)", null as "stddev(dur)" from slices union select "TOTAL OVER ALL SPANS (excluding events)" as name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" and dur > 0 union select name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" group by name order by sum(dur) desc, count(*) desc ``` ```rust fn main() { let n: usize = std::env::args().nth(1).unwrap().parse().unwrap(); let mut v = (0..n).into_iter().collect::<Vec<_>>(); for i in &mut v { *i += 1; } } ``` </details> <img width="1689" height="317" alt="image" src="https://github.com/user-attachments/assets/ee2c81f5-d74a-4da5-b4b6-ab2770175b14" />
bors
added a commit
that referenced
this pull request
Aug 19, 2025
Rollup of 33 pull requests Successful merges: - #139345 (Extend `QueryStability` to handle `IntoIterator` implementations) - #140740 (Add `-Zindirect-branch-cs-prefix`) - #142079 (nll-relate: improve hr opaque types support) - #142938 (implement std::fs::set_permissions_nofollow on unix) - #144767 (Correct some grammar in integer documentation) - #144906 (Require approval from t-infra instead of t-release on tier bumps) - #144983 (Rehome 37 `tests/ui/issues/` tests to other subdirectories under `tests/ui/`) - #145025 (run spellcheck as a tidy extra check in ci) - #145166 (suggest using `pub(crate)` for E0364) - #145255 (dec2flt: Provide more valid inputs examples) - #145306 (Add tracing to various miscellaneous functions) - #145336 (Hide docs for `core::unicode`) - #145429 (Couple of codegen_fn_attrs improvements) - #145452 (Do not strip binaries in bootstrap everytime if they are unchanged) - #145464 (Stabilize `const_pathbuf_osstring_new` feature) - #145474 (Properly recover from parenthesized use-bounds (precise capturing lists) plus small cleanups) - #145486 (Fix `unicode_data.rs` mention message) - #145493 (remove `should_render` in `PrintAttribute` derive) - #145505 (Simplify span caches) - #145510 (Visit and print async_fut local for async drop.) - #145511 (Rust build fails on OpenBSD after using file_lock feature) - #145532 (resolve: debug for block module) - #145533 (Reorder `lto` options from most to least optimizing) - #145537 (Do not consider a `T: !Sized` candidate to satisfy a `T: !MetaSized` obligation.) - #145538 (bufreader::Buffer::backshift: don't move the uninit bytes) - #145542 (triagebot: Don't warn no-mentions on subtree updates) - #145549 (Update rust maintainers in openharmony.md) - #145550 (Avoid using `()` in `derive(From)` output.) - #145556 (Allow stability attributes on extern crates) - #145560 (Remove unused `PartialOrd`/`Ord` from bootstrap) - #145568 (ignore frontmatters in `TokenStream::new`) - #145571 (remove myself from some adhoc-groups and pings) - #145576 (Add change tracker entry for `--timings`) r? `@ghost` `@rustbot` modify labels: rollup
jieyouxu
added a commit
to jieyouxu/rust
that referenced
this pull request
Aug 19, 2025
Add tracing to various miscellaneous functions This PR adds tracing to: - `ty.fn_sig()`. There is only one place where `fn_sig` is called for real within `rustc_const_eval`. There are three other places where it's called, but one is inside `ConstCx::fn_sig` (which does not seem to be used anywhere), another is under `if cfg!(debug_assertions)`, and the last is within `call_main` and thus gets called only once. - the two possible things `find_mir_or_eval_fn` can do: "emulate_foreign_item" and "load_mir" - all calls to `Const.eval()` within the Miri or the `rustc_const_eval` codebase. - a separate commit also fixes the style of some tracing macros Those are all quite long-lived operations, that in total make up for 6-7% of the total time spent in the program. I found out about them by looking for long periods of time that were previously not traced at all, using this SQL query in ui.perfetto.dev: ```sql with ordered as (select s1.*, row_number() over (order by s1.ts) as rn from slices as s1 where s1.parent_id is null and s1.dur > 0 and s1.name != "frame" and s1.name != "step" and s1.name != "backtrace") select a.ts+a.dur as ts, b.ts-a.ts-a.dur as dur, a.id, a.track_id, a.category, a.depth, a.stack_id, a.parent_stack_id, a.parent_id, a.arg_set_id, a.thread_ts, a.thread_instruction_count, a.thread_instruction_delta, a.cat, a.slice_id, "empty" as name from ordered as a inner join ordered as b on a.rn=b.rn-1 /*where b.ts-a.ts-a.dur > 5000*/ order by b.ts-a.ts-a.dur desc ``` <details> <summary>How the table was obtained</summary> The above image was obtained in ui.perfetto.dev with the following SQL query after obtaining a trace file by running Miri on the following Rust code with `n=100`. ```sql select "TOTAL PROGRAM DURATION" as name, count(*), max(ts + dur) as "sum(dur)", 100.0 as "%", null as "min(dur)", null as "max(dur)", null as "avg(dur)", null as "stddev(dur)" from slices union select "TOTAL OVER ALL SPANS (excluding events)" as name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" and dur > 0 union select name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" group by name order by sum(dur) desc, count(*) desc ``` ```rust fn main() { let n: usize = std::env::args().nth(1).unwrap().parse().unwrap(); let mut v = (0..n).into_iter().collect::<Vec<_>>(); for i in &mut v { *i += 1; } } ``` </details> <img width="1689" height="317" alt="image" src="https://github.com/user-attachments/assets/ee2c81f5-d74a-4da5-b4b6-ab2770175b14" />
This was referenced Aug 19, 2025
bors
added a commit
that referenced
this pull request
Aug 19, 2025
Rollup of 15 pull requests Successful merges: - #139345 (Extend `QueryStability` to handle `IntoIterator` implementations) - #140740 (Add `-Zindirect-branch-cs-prefix`) - #142079 (nll-relate: improve hr opaque types support) - #142938 (implement std::fs::set_permissions_nofollow on unix) - #143730 (fmt of non-decimal radix untangled) - #144767 (Correct some grammar in integer documentation) - #144906 (Require approval from t-infra instead of t-release on tier bumps) - #144983 (Rehome 37 `tests/ui/issues/` tests to other subdirectories under `tests/ui/`) - #145025 (run spellcheck as a tidy extra check in ci) - #145099 (rustc_target: Add the `32s` target feature for LoongArch) - #145166 (suggest using `pub(crate)` for E0364) - #145255 (dec2flt: Provide more valid inputs examples) - #145306 (Add tracing to various miscellaneous functions) - #145336 (Hide docs for `core::unicode`) - #145585 (Miri: fix handling of in-place argument and return place handling) r? `@ghost` `@rustbot` modify labels: rollup
rust-timer
added a commit
that referenced
this pull request
Aug 19, 2025
Rollup merge of #145306 - Stypox:tracing-misc, r=RalfJung Add tracing to various miscellaneous functions This PR adds tracing to: - `ty.fn_sig()`. There is only one place where `fn_sig` is called for real within `rustc_const_eval`. There are three other places where it's called, but one is inside `ConstCx::fn_sig` (which does not seem to be used anywhere), another is under `if cfg!(debug_assertions)`, and the last is within `call_main` and thus gets called only once. - the two possible things `find_mir_or_eval_fn` can do: "emulate_foreign_item" and "load_mir" - all calls to `Const.eval()` within the Miri or the `rustc_const_eval` codebase. - a separate commit also fixes the style of some tracing macros Those are all quite long-lived operations, that in total make up for 6-7% of the total time spent in the program. I found out about them by looking for long periods of time that were previously not traced at all, using this SQL query in ui.perfetto.dev: ```sql with ordered as (select s1.*, row_number() over (order by s1.ts) as rn from slices as s1 where s1.parent_id is null and s1.dur > 0 and s1.name != "frame" and s1.name != "step" and s1.name != "backtrace") select a.ts+a.dur as ts, b.ts-a.ts-a.dur as dur, a.id, a.track_id, a.category, a.depth, a.stack_id, a.parent_stack_id, a.parent_id, a.arg_set_id, a.thread_ts, a.thread_instruction_count, a.thread_instruction_delta, a.cat, a.slice_id, "empty" as name from ordered as a inner join ordered as b on a.rn=b.rn-1 /*where b.ts-a.ts-a.dur > 5000*/ order by b.ts-a.ts-a.dur desc ``` <details> <summary>How the table was obtained</summary> The above image was obtained in ui.perfetto.dev with the following SQL query after obtaining a trace file by running Miri on the following Rust code with `n=100`. ```sql select "TOTAL PROGRAM DURATION" as name, count(*), max(ts + dur) as "sum(dur)", 100.0 as "%", null as "min(dur)", null as "max(dur)", null as "avg(dur)", null as "stddev(dur)" from slices union select "TOTAL OVER ALL SPANS (excluding events)" as name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" and dur > 0 union select name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts + dur) from slices) * 1000 as int) / 10.0 as "%", min(dur), max(dur), cast(avg(dur) as int) as "avg(dur)", cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as "stddev(dur)" from slices where parent_id is null and name != "frame" and name != "step" group by name order by sum(dur) desc, count(*) desc ``` ```rust fn main() { let n: usize = std::env::args().nth(1).unwrap().parse().unwrap(); let mut v = (0..n).into_iter().collect::<Vec<_>>(); for i in &mut v { *i += 1; } } ``` </details> <img width="1689" height="317" alt="image" src="https://github.com/user-attachments/assets/ee2c81f5-d74a-4da5-b4b6-ab2770175b14" />
Kobzol
pushed a commit
to Kobzol/rust
that referenced
this pull request
Aug 19, 2025
Rollup of 15 pull requests Successful merges: - rust-lang#139345 (Extend `QueryStability` to handle `IntoIterator` implementations) - rust-lang#140740 (Add `-Zindirect-branch-cs-prefix`) - rust-lang#142079 (nll-relate: improve hr opaque types support) - rust-lang#142938 (implement std::fs::set_permissions_nofollow on unix) - rust-lang#143730 (fmt of non-decimal radix untangled) - rust-lang#144767 (Correct some grammar in integer documentation) - rust-lang#144906 (Require approval from t-infra instead of t-release on tier bumps) - rust-lang#144983 (Rehome 37 `tests/ui/issues/` tests to other subdirectories under `tests/ui/`) - rust-lang#145025 (run spellcheck as a tidy extra check in ci) - rust-lang#145099 (rustc_target: Add the `32s` target feature for LoongArch) - rust-lang#145166 (suggest using `pub(crate)` for E0364) - rust-lang#145255 (dec2flt: Provide more valid inputs examples) - rust-lang#145306 (Add tracing to various miscellaneous functions) - rust-lang#145336 (Hide docs for `core::unicode`) - rust-lang#145585 (Miri: fix handling of in-place argument and return place handling) r? `@ghost` `@rustbot` modify labels: rollup
github-actions bot
pushed a commit
to rust-lang/miri
that referenced
this pull request
Aug 20, 2025
Rollup of 15 pull requests Successful merges: - rust-lang/rust#139345 (Extend `QueryStability` to handle `IntoIterator` implementations) - rust-lang/rust#140740 (Add `-Zindirect-branch-cs-prefix`) - rust-lang/rust#142079 (nll-relate: improve hr opaque types support) - rust-lang/rust#142938 (implement std::fs::set_permissions_nofollow on unix) - rust-lang/rust#143730 (fmt of non-decimal radix untangled) - rust-lang/rust#144767 (Correct some grammar in integer documentation) - rust-lang/rust#144906 (Require approval from t-infra instead of t-release on tier bumps) - rust-lang/rust#144983 (Rehome 37 `tests/ui/issues/` tests to other subdirectories under `tests/ui/`) - rust-lang/rust#145025 (run spellcheck as a tidy extra check in ci) - rust-lang/rust#145099 (rustc_target: Add the `32s` target feature for LoongArch) - rust-lang/rust#145166 (suggest using `pub(crate)` for E0364) - rust-lang/rust#145255 (dec2flt: Provide more valid inputs examples) - rust-lang/rust#145306 (Add tracing to various miscellaneous functions) - rust-lang/rust#145336 (Hide docs for `core::unicode`) - rust-lang/rust#145585 (Miri: fix handling of in-place argument and return place handling) r? `@ghost` `@rustbot` modify labels: rollup
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Labels
S-waiting-on-bors
Status: Waiting on bors to run and complete tests. Bors will change the label on completion.
T-compiler
Relevant to the compiler team, which will review and decide on the PR/issue.
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.
This PR adds tracing to:
ty.fn_sig()
. There is only one place wherefn_sig
is called for real withinrustc_const_eval
. There are three other places where it's called, but one is insideConstCx::fn_sig
(which does not seem to be used anywhere), another is underif cfg!(debug_assertions)
, and the last is withincall_main
and thus gets called only once.find_mir_or_eval_fn
can do: "emulate_foreign_item" and "load_mir"Const.eval()
within the Miri or therustc_const_eval
codebase.Those are all quite long-lived operations, that in total make up for 6-7% of the total time spent in the program. I found out about them by looking for long periods of time that were previously not traced at all, using this SQL query in ui.perfetto.dev:
How the table was obtained
The above image was obtained in ui.perfetto.dev with the following SQL query after obtaining a trace file by running Miri on the following Rust code with
n=100
.r? @RalfJung