Add tracing to step.rs and friends #144708

Stypox · 2025-07-30T22:50:15Z

Adds tracing calls to functions in step.rs (01717ff), to friend functions related to evaluation and stepping (cbfa7c4), and adds a new trait method EnteredTraceSpan::or_if_tracing_disabled (f0d0d1f).

Adding EnteredTraceSpan::or_if_tracing_disabled is optional and is only useful to avoid having both tracing::info!() calls (that existed before) and enter_trace_span!() calls (that this PR adds) that would be redundant and would slow down the collection of traces. I say it is optional because it adds some cognitive complexity around EnteredTraceSpan, which is possibly not worth the reduced redundancy. Let me know if I should revert that commit.

The tracing calls added in this PR are meant to make it easier to understand what was being executing at a particular point when looking at a trace. But they are likely not useful for the purpose of understanding which components are fast/slow, hence why I used tracing_separate_thread for them. After opening a trace generated using the code in this PR in https://ui.perfetto.dev, and after executing the following query and then pressing on "Show debug track", you will see something like the following image in the timeline:

select slices.id, ts, dur, track_id, category, args.string_value as name, depth, stack_id, parent_stack_id, parent_id, slices.arg_set_id, thread_ts, thread_instruction_count, thread_instruction_delta, cat, slice_id from slices inner join args USING (arg_set_id) where args.key = "args." || slices.name and name = "step"

r? @RalfJung

rustbot · 2025-07-30T22:50:21Z

Some changes occurred to the CTFE / Miri interpreter

cc @rust-lang/miri

Some changes occurred to the CTFE machinery

cc @RalfJung, @oli-obk, @lcnr

The Miri subtree was changed

cc @rust-lang/miri

RalfJung · 2025-07-31T11:27:28Z

compiler/rustc_const_eval/src/interpret/step.rs

eval_statement and eval_terminator make a lot of sense -- I'm a bit surprised by the others, is that really helpful and worth the overhead?

They do make it easier to understand what is happening at a particular point in my opinion, instead of having to look at the statement/terminator being executed and then guessing which path the execution followed. When I was looking for functions to trace, I found it quite helpful to notice "this init_fn_call took a lot of time, but most of it was outside init_stack_frame" or instead "this init_fn_call spent most of its time in init_stack_frame".

But yeah they do add quite some overhead (the number of spans is ~3x what it would be with only eval_statement and eval_terminator). If we want to prune some of the less useful ones, I'd remove eval_place and eval_place_to_op (they are very short lived, see the table), eval_rvalue_into_place (it's usually just a direct child of eval_statement with nothing else happening around it). This would leave us with just an 1.5x overhead over just eval_statement and eval_terminator. What do you think?

I was referring to the ones in this file only, i.e. eval_rvalue_into_place, eval_fn_call_argument, eval_callee_and_args. My first inclination would be to remove them.

eval_place and eval_place_to_op and eval_operand form a nice group that makes sense together.

eval_rvalue_into_place, eval_fn_call_argument, eval_callee_and_args

Oh ok, I don't have strong opinions about those so we can as well remove them.

RalfJung · 2025-07-31T11:29:07Z

compiler/rustc_const_eval/src/interpret/step.rs

@@ -74,7 +75,8 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
    ///
    /// This does NOT move the statement counter forward, the caller has to do that!
    pub fn eval_statement(&mut self, stmt: &mir::Statement<'tcx>) -> InterpResult<'tcx> {
-        info!("{:?}", stmt);
+        let _span = enter_trace_span!(M, step::eval_statement, stmt = ?stmt, tracing_separate_thread = Empty);


You probably want to only print stmt.kind here as well to match the terminator case (I know that inconsistency is pre-existing but this is a good time to fix it).

Is it worth also adding span = ?stmt.source_info.span? Please check if that produces something useful (should be file, line and column information); if yes, please add it for both statements and terminators.

span seems to work as expected:

select slices.id, ts, dur, track_id, category, SUBSTRING(args.string_value, 45) as name, depth, stack_id, parent_stack_id, parent_id, slices.arg_set_id, thread_ts, thread_instruction_count, thread_instruction_delta, cat, slice_id from slices inner join args USING (arg_set_id) where args.key = "args.span" and name = "step"

_{I used SUBSTRING(args.string_value, 45) to make the path relative to the repository root}

RalfJung · 2025-07-31T11:33:25Z

compiler/rustc_const_eval/src/interpret/util.rs

+/// # use rustc_const_eval::interpret::EnteredTraceSpan;
+/// # type M = rustc_const_eval::const_eval::CompileTimeMachine<'static>;
+/// let _span = enter_trace_span!(M, step::eval_statement)
+///     .or_if_tracing_disabled(|| tracing::info!("eval_statement"));


That's nice!

Stypox · 2025-07-31T14:20:19Z

I pushed a commit adding span, reducing line length, and removing eval_rvalue_into_place, eval_fn_call_argument and eval_callee_and_args. I wonder why fmt check was not complaining about the 165-character long lines xD.

Should I add span also to the alternative info!() calls? I'd say no as it would probably clutter the logs.

RalfJung · 2025-07-31T14:27:05Z

I wonder why fmt check was not complaining about the 165-character long lines xD.

rustfmt accepts such lines when it is unable to break them.

Should I add span also to the alternative info!() calls? I'd say no as it would probably clutter the logs.

Agreed, let's not have a span there.

RalfJung · 2025-07-31T14:28:44Z

This looks good now, thanks! Please squash at least the last commit so we don't have a back-and-forth in the history.

Then we have to wait for #144688 to land.

Stypox · 2025-07-31T19:56:17Z

Done, and I also rebased on master now that #144688 has been merged

RalfJung · 2025-08-01T07:28:04Z

@bors r+ rollup

bors · 2025-08-01T07:28:08Z

📌 Commit 88c9a25 has been approved by RalfJung

It is now in the queue for this repository.

…Jung Add tracing to step.rs and friends Adds tracing calls to functions in `step.rs` (01717ff), to friend functions related to evaluation and stepping (cbfa7c4), and adds a new trait method `EnteredTraceSpan::or_if_tracing_disabled` (f0d0d1f). Adding `EnteredTraceSpan::or_if_tracing_disabled` is optional and is only useful to avoid having both `tracing::info!()` calls (that existed before) and `enter_trace_span!()` calls (that this PR adds) that would be redundant and would slow down the collection of traces. I say it is optional because it adds some cognitive complexity around `EnteredTraceSpan`, which is possibly not worth the reduced redundancy. Let me know if I should revert that commit. The tracing calls added in this PR are meant to make it easier to understand what was being executing at a particular point when looking at a trace. But they are likely not useful for the purpose of understanding which components are fast/slow, hence why I used `tracing_separate_thread` for them. After opening a trace generated using the code in this PR in https://ui.perfetto.dev, and after executing the following query and then pressing on "Show debug track", you will see something like the following image in the timeline: ```sql select slices.id, ts, dur, track_id, category, args.string_value as name, depth, stack_id, parent_stack_id, parent_id, slices.arg_set_id, thread_ts, thread_instruction_count, thread_instruction_delta, cat, slice_id from slices inner join args USING (arg_set_id) where args.key = "args." || slices.name and name = "step" ``` <img width="739" height="87" alt="image" src="https://github.com/user-attachments/assets/74ad9619-9a1f-40e5-9ef4-3db31e33d6e1" />

Rollup of 6 pull requests Successful merges: - #144397 (`tests/ui/issues/`: The Issues Strike Back [2/N]) - #144410 (Make tier 3 musl targets link dynamically by default) - #144708 (Add tracing to step.rs and friends) - #144730 (Create a typed wrapper for codegen backends in bootstrap) - #144771 (Remove some noisy triagebot pings for myself) - #144772 (add unsupported_calling_conventions to lint list) r? `@ghost` `@rustbot` modify labels: rollup

Rollup merge of #144708 - Stypox:add-tracing-to-step, r=RalfJung Add tracing to step.rs and friends Adds tracing calls to functions in `step.rs` (01717ff), to friend functions related to evaluation and stepping (cbfa7c4), and adds a new trait method `EnteredTraceSpan::or_if_tracing_disabled` (f0d0d1f). Adding `EnteredTraceSpan::or_if_tracing_disabled` is optional and is only useful to avoid having both `tracing::info!()` calls (that existed before) and `enter_trace_span!()` calls (that this PR adds) that would be redundant and would slow down the collection of traces. I say it is optional because it adds some cognitive complexity around `EnteredTraceSpan`, which is possibly not worth the reduced redundancy. Let me know if I should revert that commit. The tracing calls added in this PR are meant to make it easier to understand what was being executing at a particular point when looking at a trace. But they are likely not useful for the purpose of understanding which components are fast/slow, hence why I used `tracing_separate_thread` for them. After opening a trace generated using the code in this PR in https://ui.perfetto.dev, and after executing the following query and then pressing on "Show debug track", you will see something like the following image in the timeline: ```sql select slices.id, ts, dur, track_id, category, args.string_value as name, depth, stack_id, parent_stack_id, parent_id, slices.arg_set_id, thread_ts, thread_instruction_count, thread_instruction_delta, cat, slice_id from slices inner join args USING (arg_set_id) where args.key = "args." || slices.name and name = "step" ``` <img width="739" height="87" alt="image" src="https://github.com/user-attachments/assets/74ad9619-9a1f-40e5-9ef4-3db31e33d6e1" />

rustbot assigned RalfJung Jul 30, 2025

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 30, 2025

This comment has been minimized.

Sign in to view

Stypox force-pushed the add-tracing-to-step branch from 01740a8 to f221d7c Compare July 31, 2025 09:28

RalfJung reviewed Jul 31, 2025

View reviewed changes

Stypox force-pushed the add-tracing-to-step branch from b24607a to 120b899 Compare July 31, 2025 14:20

Stypox added 3 commits July 31, 2025 21:51

Add tracing calls to eval_statement/terminator

4e806c8

Add tracing to more functions related to step.rs

188f736

Add EnteredTraceSpan::or_if_tracing_disabled

88c9a25

Stypox force-pushed the add-tracing-to-step branch from 120b899 to 88c9a25 Compare July 31, 2025 19:53

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 1, 2025

RalfJung mentioned this pull request Aug 1, 2025

Rollup of 6 pull requests #144773

Merged

bors merged commit d9f794a into rust-lang:master Aug 1, 2025
10 checks passed

rustbot added this to the 1.90.0 milestone Aug 1, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Add tracing to step.rs and friends #144708

Add tracing to step.rs and friends #144708

Stypox commented Jul 30, 2025 •

edited

Loading

Uh oh!

rustbot commented Jul 30, 2025

Uh oh!

This comment has been minimized.

RalfJung Jul 31, 2025

Uh oh!

Stypox Jul 31, 2025

Uh oh!

RalfJung Jul 31, 2025 •

edited

Loading

Uh oh!

Stypox Jul 31, 2025

Uh oh!

RalfJung Jul 31, 2025

Uh oh!

Stypox Jul 31, 2025

Uh oh!

RalfJung Jul 31, 2025

Uh oh!

Stypox commented Jul 31, 2025

Uh oh!

RalfJung commented Jul 31, 2025

Uh oh!

RalfJung commented Jul 31, 2025 •

edited

Loading

Uh oh!

Stypox commented Jul 31, 2025

Uh oh!

RalfJung commented Aug 1, 2025

Uh oh!

bors commented Aug 1, 2025

Uh oh!

Uh oh!

Uh oh!

Add tracing to step.rs and friends #144708

Add tracing to step.rs and friends #144708

Conversation

Stypox commented Jul 30, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

rustbot commented Jul 30, 2025

Uh oh!

This comment has been minimized.

RalfJung Jul 31, 2025

Choose a reason for hiding this comment

Uh oh!

Stypox Jul 31, 2025

Choose a reason for hiding this comment

Uh oh!

RalfJung Jul 31, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Stypox Jul 31, 2025

Choose a reason for hiding this comment

Uh oh!

RalfJung Jul 31, 2025

Choose a reason for hiding this comment

Uh oh!

Stypox Jul 31, 2025

Choose a reason for hiding this comment

Uh oh!

RalfJung Jul 31, 2025

Choose a reason for hiding this comment

Uh oh!

Stypox commented Jul 31, 2025

Uh oh!

RalfJung commented Jul 31, 2025

Uh oh!

RalfJung commented Jul 31, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Stypox commented Jul 31, 2025

Uh oh!

RalfJung commented Aug 1, 2025

Uh oh!

bors commented Aug 1, 2025

Uh oh!

Uh oh!

Uh oh!

Stypox commented Jul 30, 2025 •

edited

Loading

RalfJung Jul 31, 2025 •

edited

Loading

RalfJung commented Jul 31, 2025 •

edited

Loading