Add tracing to various miscellaneous functions by Stypox · Pull Request #145306 · rust-lang/rust

@rustbot 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

Aug 12, 2025

RalfJung

RalfJung

@rustbot rustbot 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

Aug 18, 2025

@Stypox

Also use tracing macro syntax instead of format()

@rustbot 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

Aug 18, 2025

@bors 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

Aug 18, 2025

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

github-actions bot pushed a commit to rust-lang/miri that referenced this pull request

Aug 20, 2025