diff options
| author | Guillaume Gomez <guillaume1.gomez@gmail.com> | 2025-08-14 11:39:35 +0200 |
|---|---|---|
| committer | GitHub <noreply@github.com> | 2025-08-14 11:39:35 +0200 |
| commit | 6ac5c28412bebe7c15f0738c032cfb8333c25e46 (patch) | |
| tree | ce18eedbe0ee7fc473a54f9b1278d438f42f0e48 | |
| parent | 31d8277abe4957e01437f40d1136c6760081751b (diff) | |
| parent | 99769bc301d6e9187d0e7881bb36162fd48fd573 (diff) | |
| download | rust-6ac5c28412bebe7c15f0738c032cfb8333c25e46.tar.gz rust-6ac5c28412bebe7c15f0738c032cfb8333c25e46.zip | |
Rollup merge of #144727 - Stypox:add-tracing-to-resolve, r=RalfJung
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;
}
}
```
| -rw-r--r-- | compiler/rustc_const_eval/src/interpret/call.rs | 23 | ||||
| -rw-r--r-- | compiler/rustc_const_eval/src/interpret/cast.rs | 34 | ||||
| -rw-r--r-- | compiler/rustc_const_eval/src/interpret/eval_context.rs | 1 | ||||
| -rw-r--r-- | compiler/rustc_const_eval/src/interpret/step.rs | 6 | ||||
| -rw-r--r-- | src/tools/miri/src/helpers.rs | 2 |
5 files changed, 43 insertions, 23 deletions
diff --git a/compiler/rustc_const_eval/src/interpret/call.rs b/compiler/rustc_const_eval/src/interpret/call.rs index b1cc0cc2878..a61cb7f2b09 100644 --- a/compiler/rustc_const_eval/src/interpret/call.rs +++ b/compiler/rustc_const_eval/src/interpret/call.rs @@ -736,13 +736,16 @@ 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 concrete_method = Instance::expect_resolve_for_vtable( - tcx, - self.typing_env, - def_id, - virtual_instance.args.rebase_onto(tcx, trait_def_id, concrete_trait_ref.args), - self.cur_span(), - ); + let concrete_method = { + let _trace = enter_trace_span!(M, resolve::expect_resolve_for_vtable, ?def_id); + Instance::expect_resolve_for_vtable( + tcx, + self.typing_env, + def_id, + virtual_instance.args.rebase_onto(tcx, trait_def_id, concrete_trait_ref.args), + self.cur_span(), + ) + }; assert_eq!(concrete_instance, concrete_method); } @@ -825,7 +828,11 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { place } }; - let instance = ty::Instance::resolve_drop_in_place(*self.tcx, place.layout.ty); + let instance = { + let _trace = + enter_trace_span!(M, resolve::resolve_drop_in_place, ty = ?place.layout.ty); + ty::Instance::resolve_drop_in_place(*self.tcx, place.layout.ty) + }; let fn_abi = self.fn_abi_of_instance(instance, ty::List::empty())?; let arg = self.mplace_to_ref(&place)?; diff --git a/compiler/rustc_const_eval/src/interpret/cast.rs b/compiler/rustc_const_eval/src/interpret/cast.rs index de4fbc7b475..e3afeda5b7c 100644 --- a/compiler/rustc_const_eval/src/interpret/cast.rs +++ b/compiler/rustc_const_eval/src/interpret/cast.rs @@ -16,8 +16,8 @@ use super::{ FnVal, ImmTy, Immediate, InterpCx, Machine, OpTy, PlaceTy, err_inval, interp_ok, throw_ub, throw_ub_custom, }; -use crate::fluent_generated as fluent; use crate::interpret::Writeable; +use crate::{enter_trace_span, fluent_generated as fluent}; impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { pub fn cast( @@ -81,13 +81,16 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { // The src operand does not matter, just its type match *src.layout.ty.kind() { ty::FnDef(def_id, args) => { - let instance = ty::Instance::resolve_for_fn_ptr( - *self.tcx, - self.typing_env, - def_id, - args, - ) - .ok_or_else(|| err_inval!(TooGeneric))?; + let instance = { + let _trace = enter_trace_span!(M, resolve::resolve_for_fn_ptr, ?def_id); + ty::Instance::resolve_for_fn_ptr( + *self.tcx, + self.typing_env, + def_id, + args, + ) + .ok_or_else(|| err_inval!(TooGeneric))? + }; let fn_ptr = self.fn_ptr(FnVal::Instance(instance)); self.write_pointer(fn_ptr, dest)?; @@ -114,12 +117,15 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { // The src operand does not matter, just its type match *src.layout.ty.kind() { ty::Closure(def_id, args) => { - let instance = ty::Instance::resolve_closure( - *self.tcx, - def_id, - args, - ty::ClosureKind::FnOnce, - ); + let instance = { + let _trace = enter_trace_span!(M, resolve::resolve_closure, ?def_id); + ty::Instance::resolve_closure( + *self.tcx, + def_id, + args, + ty::ClosureKind::FnOnce, + ) + }; let fn_ptr = self.fn_ptr(FnVal::Instance(instance)); self.write_pointer(fn_ptr, dest)?; } diff --git a/compiler/rustc_const_eval/src/interpret/eval_context.rs b/compiler/rustc_const_eval/src/interpret/eval_context.rs index d4f2bb8257d..a8a1ac1c980 100644 --- a/compiler/rustc_const_eval/src/interpret/eval_context.rs +++ b/compiler/rustc_const_eval/src/interpret/eval_context.rs @@ -344,6 +344,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { def: DefId, args: GenericArgsRef<'tcx>, ) -> InterpResult<'tcx, ty::Instance<'tcx>> { + let _trace = enter_trace_span!(M, resolve::try_resolve, def = ?def); trace!("resolve: {:?}, {:#?}", def, args); trace!("typing_env: {:#?}", self.typing_env); trace!("args: {:#?}", args); diff --git a/compiler/rustc_const_eval/src/interpret/step.rs b/compiler/rustc_const_eval/src/interpret/step.rs index 76e470b69dc..f1995b3f132 100644 --- a/compiler/rustc_const_eval/src/interpret/step.rs +++ b/compiler/rustc_const_eval/src/interpret/step.rs @@ -560,7 +560,11 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { "Async Drop must be expanded or reset to sync in runtime MIR" ); let place = self.eval_place(place)?; - let instance = Instance::resolve_drop_in_place(*self.tcx, place.layout.ty); + let instance = { + let _trace = + enter_trace_span!(M, resolve::resolve_drop_in_place, ty = ?place.layout.ty); + Instance::resolve_drop_in_place(*self.tcx, place.layout.ty) + }; if let ty::InstanceKind::DropGlue(_, None) = instance.def { // This is the branch we enter if and only if the dropped type has no drop glue // whatsoever. This can happen as a result of monomorphizing a drop of a diff --git a/src/tools/miri/src/helpers.rs b/src/tools/miri/src/helpers.rs index a8e2151afe6..1b5d9d50996 100644 --- a/src/tools/miri/src/helpers.rs +++ b/src/tools/miri/src/helpers.rs @@ -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 _trace = enter_trace_span!("try_resolve_did", ?path); + /// Yield all children of the given item, that have the given name. fn find_children<'tcx: 'a, 'a>( tcx: TyCtxt<'tcx>, |
