Skip to content

Commit 6ac5c28

Browse files
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; } } ```
2 parents 31d8277 + 99769bc commit 6ac5c28

File tree

5 files changed

+43
-23
lines changed

5 files changed

+43
-23
lines changed

compiler/rustc_const_eval/src/interpret/call.rs

Lines changed: 15 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -736,13 +736,16 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
736736
let existential_trait_ref = ty::ExistentialTraitRef::erase_self_ty(tcx, virtual_trait_ref);
737737
let concrete_trait_ref = existential_trait_ref.with_self_ty(tcx, dyn_ty);
738738

739-
let concrete_method = Instance::expect_resolve_for_vtable(
740-
tcx,
741-
self.typing_env,
742-
def_id,
743-
virtual_instance.args.rebase_onto(tcx, trait_def_id, concrete_trait_ref.args),
744-
self.cur_span(),
745-
);
739+
let concrete_method = {
740+
let _trace = enter_trace_span!(M, resolve::expect_resolve_for_vtable, ?def_id);
741+
Instance::expect_resolve_for_vtable(
742+
tcx,
743+
self.typing_env,
744+
def_id,
745+
virtual_instance.args.rebase_onto(tcx, trait_def_id, concrete_trait_ref.args),
746+
self.cur_span(),
747+
)
748+
};
746749
assert_eq!(concrete_instance, concrete_method);
747750
}
748751

@@ -825,7 +828,11 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
825828
place
826829
}
827830
};
828-
let instance = ty::Instance::resolve_drop_in_place(*self.tcx, place.layout.ty);
831+
let instance = {
832+
let _trace =
833+
enter_trace_span!(M, resolve::resolve_drop_in_place, ty = ?place.layout.ty);
834+
ty::Instance::resolve_drop_in_place(*self.tcx, place.layout.ty)
835+
};
829836
let fn_abi = self.fn_abi_of_instance(instance, ty::List::empty())?;
830837

831838
let arg = self.mplace_to_ref(&place)?;

compiler/rustc_const_eval/src/interpret/cast.rs

Lines changed: 20 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -16,8 +16,8 @@ use super::{
1616
FnVal, ImmTy, Immediate, InterpCx, Machine, OpTy, PlaceTy, err_inval, interp_ok, throw_ub,
1717
throw_ub_custom,
1818
};
19-
use crate::fluent_generated as fluent;
2019
use crate::interpret::Writeable;
20+
use crate::{enter_trace_span, fluent_generated as fluent};
2121

2222
impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
2323
pub fn cast(
@@ -81,13 +81,16 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
8181
// The src operand does not matter, just its type
8282
match *src.layout.ty.kind() {
8383
ty::FnDef(def_id, args) => {
84-
let instance = ty::Instance::resolve_for_fn_ptr(
85-
*self.tcx,
86-
self.typing_env,
87-
def_id,
88-
args,
89-
)
90-
.ok_or_else(|| err_inval!(TooGeneric))?;
84+
let instance = {
85+
let _trace = enter_trace_span!(M, resolve::resolve_for_fn_ptr, ?def_id);
86+
ty::Instance::resolve_for_fn_ptr(
87+
*self.tcx,
88+
self.typing_env,
89+
def_id,
90+
args,
91+
)
92+
.ok_or_else(|| err_inval!(TooGeneric))?
93+
};
9194

9295
let fn_ptr = self.fn_ptr(FnVal::Instance(instance));
9396
self.write_pointer(fn_ptr, dest)?;
@@ -114,12 +117,15 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
114117
// The src operand does not matter, just its type
115118
match *src.layout.ty.kind() {
116119
ty::Closure(def_id, args) => {
117-
let instance = ty::Instance::resolve_closure(
118-
*self.tcx,
119-
def_id,
120-
args,
121-
ty::ClosureKind::FnOnce,
122-
);
120+
let instance = {
121+
let _trace = enter_trace_span!(M, resolve::resolve_closure, ?def_id);
122+
ty::Instance::resolve_closure(
123+
*self.tcx,
124+
def_id,
125+
args,
126+
ty::ClosureKind::FnOnce,
127+
)
128+
};
123129
let fn_ptr = self.fn_ptr(FnVal::Instance(instance));
124130
self.write_pointer(fn_ptr, dest)?;
125131
}

compiler/rustc_const_eval/src/interpret/eval_context.rs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -344,6 +344,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
344344
def: DefId,
345345
args: GenericArgsRef<'tcx>,
346346
) -> InterpResult<'tcx, ty::Instance<'tcx>> {
347+
let _trace = enter_trace_span!(M, resolve::try_resolve, def = ?def);
347348
trace!("resolve: {:?}, {:#?}", def, args);
348349
trace!("typing_env: {:#?}", self.typing_env);
349350
trace!("args: {:#?}", args);

compiler/rustc_const_eval/src/interpret/step.rs

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -560,7 +560,11 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
560560
"Async Drop must be expanded or reset to sync in runtime MIR"
561561
);
562562
let place = self.eval_place(place)?;
563-
let instance = Instance::resolve_drop_in_place(*self.tcx, place.layout.ty);
563+
let instance = {
564+
let _trace =
565+
enter_trace_span!(M, resolve::resolve_drop_in_place, ty = ?place.layout.ty);
566+
Instance::resolve_drop_in_place(*self.tcx, place.layout.ty)
567+
};
564568
if let ty::InstanceKind::DropGlue(_, None) = instance.def {
565569
// This is the branch we enter if and only if the dropped type has no drop glue
566570
// whatsoever. This can happen as a result of monomorphizing a drop of a

src/tools/miri/src/helpers.rs

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,8 @@ pub enum AccessKind {
3232
///
3333
/// A `None` namespace indicates we are looking for a module.
3434
fn try_resolve_did(tcx: TyCtxt<'_>, path: &[&str], namespace: Option<Namespace>) -> Option<DefId> {
35+
let _trace = enter_trace_span!("try_resolve_did", ?path);
36+
3537
/// Yield all children of the given item, that have the given name.
3638
fn find_children<'tcx: 'a, 'a>(
3739
tcx: TyCtxt<'tcx>,

0 commit comments

Comments
 (0)