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

@@ -730,6 +730,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
let existential_trait_ref = ty::ExistentialTraitRef::erase_self_ty(tcx, virtual_trait_ref);
let concrete_trait_ref = existential_trait_ref.with_self_ty(tcx, dyn_ty);

let _span = enter_trace_span!(M, resolve::expect_resolve_for_vtable, ?def_id);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Did we call this _span everywhere? I now realize that's confusing because usually that refers to the Span type...

@@ -32,6 +32,8 @@ pub enum AccessKind {
///
/// A `None` namespace indicates we are looking for a module.
fn try_resolve_did(tcx: TyCtxt<'_>, path: &[&str], namespace: Option<Namespace>) -> Option<DefId> {
let _span = enter_trace_span!(resolve::try_resolve_did, ?path);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This isn't the same kind of operation as the others at all, it is using resolve to refer to something else. It's a good idea to trace this but separate from the normal resolve calls.

@@ -730,6 +730,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
let existential_trait_ref = ty::ExistentialTraitRef::erase_self_ty(tcx, virtual_trait_ref);
let concrete_trait_ref = existential_trait_ref.with_self_ty(tcx, dyn_ty);

let _span = enter_trace_span!(M, resolve::expect_resolve_for_vtable, ?def_id);
let concrete_method = Instance::expect_resolve_for_vtable(
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please use the same pattern with a nested block as everywhere else.

@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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. 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