Add tracing to step.rs and friends

[Stypox]

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]

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]

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?

[Stypox]

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?

[RalfJung]

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.

[Stypox]

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]

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.

[Stypox]

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]

That's nice!

[Stypox]

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]

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]

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]

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

[RalfJung]

@bors r+ rollup

[bors]

📌 Commit 88c9a25 has been approved by RalfJung

It is now in the queue for this repository.