Add tracing to various miscellaneous functions by Stypox · Pull Request #145306 · rust-lang/rust
rustbot
added
S-waiting-on-review
labels
Aug 12, 2025
rustbot
added
S-waiting-on-author
and removed S-waiting-on-review
Status: Awaiting review from the assignee but also interested parties.labels
Aug 18, 2025
rustbot
added
S-waiting-on-review
and removed S-waiting-on-author
Status: This is awaiting some action (such as code changes or more information) from the author.labels
Aug 18, 2025
bors
added
S-waiting-on-bors
and removed S-waiting-on-review
Status: Awaiting review from the assignee but also interested parties.labels
Aug 18, 2025jhpratt added a commit to jhpratt/rust that referenced this pull request
Aug 18, 2025Add 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, 2025Add 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, 2025Rollup 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, 2025Add 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, 2025bors added a commit that referenced this pull request
Aug 19, 2025Rollup 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, 2025Rollup 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" />
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