Skip to content

Add tracing to resolve-related functions #144727

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

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

Stypox
Copy link
Contributor

@Stypox Stypox commented Jul 31, 2025

Resolve-related functions are not called often but still make up for ~3% of execution time for non-repetitive programs (as seen in the first table below, obtained from running the rust snippet at the bottom with n=1). On the other hand, for repetitive programs they become less relevant (I tested the same snippet but with n=100 and got ~1.5%), and it appears that only try_resolve is called more often (see the last two tables).

The first table was obtained by opening the trace file in https://ui.perfetto.dev and running the following query:

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
image

The following two tables show how many resolve spans there per subname/subcategory, and how much time is spent in each. The first is for n=1 and the second for n=100. The query that was used is:

select args.string_value as name, count(*), max(dur), avg(dur), sum(dur) from slices inner join args USING (arg_set_id) where args.key = "args." || slices.name and name = "resolve" group by args.string_value
image image

The snippet I tested with Miri to obtain the above traces is:

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;
    }
}

r? @RalfJung

@rustbot
Copy link
Collaborator

rustbot commented Jul 31, 2025

r? @petrochenkov

rustbot has assigned @petrochenkov.
They will have a look at your PR within the next two weeks and either review your PR or reassign to another reviewer.

Use r? to explicitly pick a reviewer

@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 Jul 31, 2025
@rustbot
Copy link
Collaborator

rustbot commented Jul 31, 2025

Some changes occurred to the CTFE machinery

cc @RalfJung, @oli-obk, @lcnr

The Miri subtree was changed

cc @rust-lang/miri

Some changes occurred to the CTFE / Miri interpreter

cc @rust-lang/miri

@rustbot rustbot assigned RalfJung and unassigned petrochenkov Jul 31, 2025
@Stypox Stypox force-pushed the add-tracing-to-resolve branch from aaed279 to 035e767 Compare July 31, 2025 20:02
@Stypox
Copy link
Contributor Author

Stypox commented Jul 31, 2025

Now that #144688 has been merged I rebased on master

@bors
Copy link
Collaborator

bors commented Aug 1, 2025

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

@RalfJung
Copy link
Member

RalfJung commented Aug 2, 2025

@rustbot author

@rustbot rustbot removed the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Aug 2, 2025
@rustbot
Copy link
Collaborator

rustbot commented Aug 2, 2025

Reminder, once the PR becomes ready for a review, use @rustbot ready.

@rustbot rustbot added the S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. label Aug 2, 2025
@Stypox Stypox force-pushed the add-tracing-to-resolve branch from 035e767 to 99769bc Compare August 11, 2025 12:34
@Stypox
Copy link
Contributor Author

Stypox commented Aug 11, 2025

@rustbot ready

@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 11, 2025
fmease added a commit to fmease/rust that referenced this pull request Aug 11, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
fmease added a commit to fmease/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
fmease added a commit to fmease/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
fmease added a commit to fmease/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
fmease added a commit to fmease/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
Zalathar added a commit to Zalathar/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
Zalathar added a commit to Zalathar/rust that referenced this pull request Aug 12, 2025
…lett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang#144727 (comment).
rust-timer added a commit that referenced this pull request Aug 12, 2025
Rollup merge of #145249 - Stypox:_span-to-_trace, r=joshtriplett

Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in #144727 (comment).
github-actions bot pushed a commit to rust-lang/miri that referenced this pull request Aug 13, 2025
Rename entered trace span variables from `_span` to  `_trace`

This PR just changes the name of `EnteredTraceSpan` variables used to automatically close tracing spans when going out of scope. This renaming was needed because `_span` could possibly be confused with the `Span` type in rustc, so I used `_trace` as suggested in rust-lang/rust#144727 (comment).
@RalfJung
Copy link
Member

@bors r+ rollup

@bors
Copy link
Collaborator

bors commented Aug 14, 2025

📌 Commit 99769bc has been approved by RalfJung

It is now in the queue for this repository.

@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 14, 2025
GuillaumeGomez added a commit to GuillaumeGomez/rust that referenced this pull request Aug 14, 2025
…alfJung

Add tracing to resolve-related functions

Resolve-related functions are not called often but still make up for ~3% of execution time for non-repetitive programs (as seen in the first table below, obtained from running the rust snippet at the bottom with `n=1`). On the other hand, for repetitive programs they become less relevant (I tested the same snippet but with `n=100` and got ~1.5%), and it appears that only `try_resolve` is called more often (see the last two tables).

The first table was obtained by opening the trace file in https://ui.perfetto.dev and running the following query:

```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
```

<img width="1687" height="242" alt="image" src="https://github.com/user-attachments/assets/4d4bd890-869b-40f3-a473-8e4c42b02da4" />

The following two tables show how many `resolve` spans there per subname/subcategory, and how much time is spent in each. The first is for `n=1` and the second for `n=100`. The query that was used is:

```sql
select args.string_value as name, count(*), max(dur), avg(dur), sum(dur) from slices inner join args USING (arg_set_id) where args.key = "args." || slices.name and name = "resolve" group by args.string_value
```

<img width="1688" height="159" alt="image" src="https://github.com/user-attachments/assets/a8749856-c099-492e-a86e-6d67b146af9c" />

<img width="1688" height="159" alt="image" src="https://github.com/user-attachments/assets/ce3ac1b5-5c06-47d9-85a6-9b921aea348e" />

The snippet I tested with Miri to obtain the above traces is:

```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;
    }
}
```
bors added a commit that referenced this pull request Aug 14, 2025
Rollup of 13 pull requests

Successful merges:

 - #140434 (rustdoc: Allow multiple references to a single footnote)
 - #142372 (Improve `--remap-path-prefix` documentation)
 - #142741 (Fix unsoundness in some tests)
 - #144515 (Implement `ptr_cast_array`)
 - #144727 (Add tracing to resolve-related functions)
 - #144959 (fix(unicode-table-generator): fix duplicated unique indices)
 - #145179 (Avoid abbreviating "numerator" as "numer", to allow catching typo "numer" elsewhere)
 - #145250 (Add regression test for a former ICE involving helper attributes containing interpolated tokens)
 - #145266 (Reduce some queries around associated items)
 - #145299 (doc test: fix mpsc.rs try_send doc test)
 - #145323 (Port the `#[linkage]` attribute to the new attribute system)
 - #145361 (Suppress wrapper suggestion when expected and actual ty are the same adt and the variant is unresolved)
 - #145372 (resolve: Miscellaneous cleanups)

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.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants