diff options
| author | 许杰友 Jieyou Xu (Joe) <39484203+jieyouxu@users.noreply.github.com> | 2025-08-19 19:42:09 +0800 |
|---|---|---|
| committer | GitHub <noreply@github.com> | 2025-08-19 19:42:09 +0800 |
| commit | ba20d77a444a7125a764e9d69024c6377023b45f (patch) | |
| tree | f89462bb41412f1cdb279cf911ab6c320625527b /compiler | |
| parent | 0b378a7108e550b6edb7ee0669a64f24dac364f1 (diff) | |
| parent | dc72692591c937e15cb016c57d4dee6a81340bbd (diff) | |
| download | rust-ba20d77a444a7125a764e9d69024c6377023b45f.tar.gz rust-ba20d77a444a7125a764e9d69024c6377023b45f.zip | |
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" />
Diffstat (limited to 'compiler')
4 files changed, 13 insertions, 5 deletions
diff --git a/compiler/rustc_const_eval/src/interpret/eval_context.rs b/compiler/rustc_const_eval/src/interpret/eval_context.rs index a8a1ac1c980..9681d89ce35 100644 --- a/compiler/rustc_const_eval/src/interpret/eval_context.rs +++ b/compiler/rustc_const_eval/src/interpret/eval_context.rs @@ -325,8 +325,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { let _trace = enter_trace_span!( M, "instantiate_from_frame_and_normalize_erasing_regions", - "{}", - frame.instance + %frame.instance ); frame .instance @@ -583,6 +582,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { span: Span, layout: Option<TyAndLayout<'tcx>>, ) -> InterpResult<'tcx, OpTy<'tcx, M::Provenance>> { + let _trace = enter_trace_span!(M, const_eval::eval_mir_constant, ?val); let const_val = val.eval(*self.tcx, self.typing_env, span).map_err(|err| { if M::ALL_CONSTS_ARE_PRECHECKED { match err { diff --git a/compiler/rustc_const_eval/src/interpret/stack.rs b/compiler/rustc_const_eval/src/interpret/stack.rs index 73cc87508ef..7cabfd96121 100644 --- a/compiler/rustc_const_eval/src/interpret/stack.rs +++ b/compiler/rustc_const_eval/src/interpret/stack.rs @@ -20,7 +20,7 @@ use super::{ MemoryKind, Operand, PlaceTy, Pointer, Provenance, ReturnAction, Scalar, from_known_layout, interp_ok, throw_ub, throw_unsup, }; -use crate::errors; +use crate::{enter_trace_span, errors}; // The Phantomdata exists to prevent this type from being `Send`. If it were sent across a thread // boundary and dropped in the other thread, it would exit the span in the other thread. @@ -386,6 +386,9 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { // Make sure all the constants required by this frame evaluate successfully (post-monomorphization check). for &const_ in body.required_consts() { + // We can't use `eval_mir_constant` here as that assumes that all required consts have + // already been checked, so we need a separate tracing call. + let _trace = enter_trace_span!(M, const_eval::required_consts, ?const_.const_); let c = self.instantiate_from_current_frame_and_normalize_erasing_regions(const_.const_)?; c.eval(*self.tcx, self.typing_env, const_.span).map_err(|err| { diff --git a/compiler/rustc_const_eval/src/interpret/step.rs b/compiler/rustc_const_eval/src/interpret/step.rs index f1995b3f132..5143278e69a 100644 --- a/compiler/rustc_const_eval/src/interpret/step.rs +++ b/compiler/rustc_const_eval/src/interpret/step.rs @@ -436,7 +436,10 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { .map(|arg| self.eval_fn_call_argument(&arg.node)) .collect::<InterpResult<'tcx, Vec<_>>>()?; - let fn_sig_binder = func.layout.ty.fn_sig(*self.tcx); + let fn_sig_binder = { + let _trace = enter_trace_span!(M, "fn_sig", ty = ?func.layout.ty.kind()); + func.layout.ty.fn_sig(*self.tcx) + }; let fn_sig = self.tcx.normalize_erasing_late_bound_regions(self.typing_env, fn_sig_binder); let extra_args = &args[fn_sig.inputs().len()..]; let extra_args = diff --git a/compiler/rustc_const_eval/src/interpret/validity.rs b/compiler/rustc_const_eval/src/interpret/validity.rs index 5e8bee65706..02e3d90f4af 100644 --- a/compiler/rustc_const_eval/src/interpret/validity.rs +++ b/compiler/rustc_const_eval/src/interpret/validity.rs @@ -1418,7 +1418,9 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> { let _trace = enter_trace_span!( M, "validate_operand", - "recursive={recursive}, reset_provenance_and_padding={reset_provenance_and_padding}, val={val:?}" + recursive, + reset_provenance_and_padding, + ?val, ); // Note that we *could* actually be in CTFE here with `-Zextra-const-ub-checks`, but it's |
