Rollup merge of rust-lang#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" />

Author: RalfJung

compiler/rustc_const_eval/src/interpret/call.rs

@@ -11,14 +11,16 @@ use rustc_middle::ty::{self, AdtDef, Instance, Ty, VariantDef};
 use rustc_middle::{bug, mir, span_bug};
 use rustc_span::sym;
 use rustc_target::callconv::{ArgAbi, FnAbi, PassMode};
+use tracing::field::Empty;
 use tracing::{info, instrument, trace};
 
 use super::{
     CtfeProvenance, FnVal, ImmTy, InterpCx, InterpResult, MPlaceTy, Machine, OpTy, PlaceTy,
     Projectable, Provenance, ReturnAction, ReturnContinuation, Scalar, StackPopInfo, interp_ok,
     throw_ub, throw_ub_custom, throw_unsup_format,
 };
-use crate::fluent_generated as fluent;
+use crate::interpret::EnteredTraceSpan;
+use crate::{enter_trace_span, fluent_generated as fluent};
 
 /// An argument passed to a function.
 #[derive(Clone, Debug)]
@@ -344,6 +346,8 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
         destination: &PlaceTy<'tcx, M::Provenance>,
         mut cont: ReturnContinuation,
     ) -> InterpResult<'tcx> {
+        let _span = enter_trace_span!(M, step::init_stack_frame, %instance, tracing_separate_thread = Empty);
+
         // Compute callee information.
         // FIXME: for variadic support, do we have to somehow determine callee's extra_args?
         let callee_fn_abi = self.fn_abi_of_instance(instance, ty::List::empty())?;
@@ -523,7 +527,9 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
         target: Option<mir::BasicBlock>,
         unwind: mir::UnwindAction,
     ) -> InterpResult<'tcx> {
-        trace!("init_fn_call: {:#?}", fn_val);
+        let _span =
+            enter_trace_span!(M, step::init_fn_call, tracing_separate_thread = Empty, ?fn_val)
+                .or_if_tracing_disabled(|| trace!("init_fn_call: {:#?}", fn_val));
 
         let instance = match fn_val {
             FnVal::Instance(instance) => instance,

compiler/rustc_const_eval/src/interpret/operand.rs

@@ -13,13 +13,15 @@ use rustc_middle::ty::print::{FmtPrinter, PrettyPrinter};
 use rustc_middle::ty::{ConstInt, ScalarInt, Ty, TyCtxt};
 use rustc_middle::{bug, mir, span_bug, ty};
 use rustc_span::DUMMY_SP;
+use tracing::field::Empty;
 use tracing::trace;
 
 use super::{
     CtfeProvenance, Frame, InterpCx, InterpResult, MPlaceTy, Machine, MemPlace, MemPlaceMeta,
     OffsetMode, PlaceTy, Pointer, Projectable, Provenance, Scalar, alloc_range, err_ub,
     from_known_layout, interp_ok, mir_assign_valid_types, throw_ub,
 };
+use crate::enter_trace_span;
 
 /// An `Immediate` represents a single immediate self-contained Rust value.
 ///
@@ -770,6 +772,13 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
         mir_place: mir::Place<'tcx>,
         layout: Option<TyAndLayout<'tcx>>,
     ) -> InterpResult<'tcx, OpTy<'tcx, M::Provenance>> {
+        let _span = enter_trace_span!(
+            M,
+            step::eval_place_to_op,
+            ?mir_place,
+            tracing_separate_thread = Empty
+        );
+
         // Do not use the layout passed in as argument if the base we are looking at
         // here is not the entire place.
         let layout = if mir_place.projection.is_empty() { layout } else { None };
@@ -813,6 +822,9 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
         mir_op: &mir::Operand<'tcx>,
         layout: Option<TyAndLayout<'tcx>>,
     ) -> InterpResult<'tcx, OpTy<'tcx, M::Provenance>> {
+        let _span =
+            enter_trace_span!(M, step::eval_operand, ?mir_op, tracing_separate_thread = Empty);
+
         use rustc_middle::mir::Operand::*;
         let op = match mir_op {
             // FIXME: do some more logic on `move` to invalidate the old location

compiler/rustc_const_eval/src/interpret/place.rs

@@ -9,13 +9,15 @@ use rustc_abi::{BackendRepr, HasDataLayout, Size};
 use rustc_middle::ty::Ty;
 use rustc_middle::ty::layout::TyAndLayout;
 use rustc_middle::{bug, mir, span_bug};
+use tracing::field::Empty;
 use tracing::{instrument, trace};
 
 use super::{
     AllocInit, AllocRef, AllocRefMut, CheckAlignMsg, CtfeProvenance, ImmTy, Immediate, InterpCx,
     InterpResult, Machine, MemoryKind, Misalignment, OffsetMode, OpTy, Operand, Pointer,
     Projectable, Provenance, Scalar, alloc_range, interp_ok, mir_assign_valid_types,
 };
+use crate::enter_trace_span;
 
 #[derive(Copy, Clone, Hash, PartialEq, Eq, Debug)]
 /// Information required for the sound usage of a `MemPlace`.
@@ -524,6 +526,9 @@ where
         &self,
         mir_place: mir::Place<'tcx>,
     ) -> InterpResult<'tcx, PlaceTy<'tcx, M::Provenance>> {
+        let _span =
+            enter_trace_span!(M, step::eval_place, ?mir_place, tracing_separate_thread = Empty);
+
         let mut place = self.local_to_place(mir_place.local)?;
         // Using `try_fold` turned out to be bad for performance, hence the loop.
         for elem in mir_place.projection.iter() {

compiler/rustc_const_eval/src/interpret/step.rs

@@ -9,13 +9,15 @@ use rustc_middle::ty::{self, Instance, Ty};
 use rustc_middle::{bug, mir, span_bug};
 use rustc_span::source_map::Spanned;
 use rustc_target::callconv::FnAbi;
+use tracing::field::Empty;
 use tracing::{info, instrument, trace};
 
 use super::{
     FnArg, FnVal, ImmTy, Immediate, InterpCx, InterpResult, Machine, MemPlaceMeta, PlaceTy,
     Projectable, Scalar, interp_ok, throw_ub, throw_unsup_format,
 };
-use crate::util;
+use crate::interpret::EnteredTraceSpan;
+use crate::{enter_trace_span, util};
 
 struct EvaluatedCalleeAndArgs<'tcx, M: Machine<'tcx>> {
     callee: FnVal<'tcx, M::ExtraFnVal>,
@@ -74,7 +76,14 @@ 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.kind,
+            span = ?stmt.source_info.span,
+            tracing_separate_thread = Empty,
+        )
+        .or_if_tracing_disabled(|| info!(stmt = ?stmt.kind));
 
         use rustc_middle::mir::StatementKind::*;
 
@@ -456,7 +465,14 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
     }
 
     fn eval_terminator(&mut self, terminator: &mir::Terminator<'tcx>) -> InterpResult<'tcx> {
-        info!("{:?}", terminator.kind);
+        let _span = enter_trace_span!(
+            M,
+            step::eval_terminator,
+            terminator = ?terminator.kind,
+            span = ?terminator.source_info.span,
+            tracing_separate_thread = Empty,
+        )
+        .or_if_tracing_disabled(|| info!(terminator = ?terminator.kind));
 
         use rustc_middle::mir::TerminatorKind::*;
         match terminator.kind {

compiler/rustc_const_eval/src/interpret/util.rs

@@ -48,10 +48,24 @@ pub(crate) fn create_static_alloc<'tcx>(
 
 /// A marker trait returned by [crate::interpret::Machine::enter_trace_span], identifying either a
 /// real [tracing::span::EnteredSpan] in case tracing is enabled, or the dummy type `()` when
-/// tracing is disabled.
-pub trait EnteredTraceSpan {}
-impl EnteredTraceSpan for () {}
-impl EnteredTraceSpan for tracing::span::EnteredSpan {}
+/// tracing is disabled. Also see [crate::enter_trace_span!] below.
+pub trait EnteredTraceSpan {
+    /// Allows executing an alternative function when tracing is disabled. Useful for example if you
+    /// want to open a trace span when tracing is enabled, and alternatively just log a line when
+    /// tracing is disabled.
+    fn or_if_tracing_disabled(self, f: impl FnOnce()) -> Self;
+}
+impl EnteredTraceSpan for () {
+    fn or_if_tracing_disabled(self, f: impl FnOnce()) -> Self {
+        f(); // tracing is disabled, execute the function
+        self
+    }
+}
+impl EnteredTraceSpan for tracing::span::EnteredSpan {
+    fn or_if_tracing_disabled(self, _f: impl FnOnce()) -> Self {
+        self // tracing is enabled, don't execute anything
+    }
+}
 
 /// Shortand for calling [crate::interpret::Machine::enter_trace_span] on a [tracing::info_span!].
 /// This is supposed to be compiled out when [crate::interpret::Machine::enter_trace_span] has the
@@ -112,6 +126,19 @@ impl EnteredTraceSpan for tracing::span::EnteredSpan {}
 /// # type M = rustc_const_eval::const_eval::CompileTimeMachine<'static>;
 /// let _span = enter_trace_span!(M, step::eval_statement, tracing_separate_thread = tracing::field::Empty);
 /// ```
+///
+/// ### Executing something else when tracing is disabled
+///
+/// [crate::interpret::Machine::enter_trace_span] returns [EnteredTraceSpan], on which you can call
+/// [EnteredTraceSpan::or_if_tracing_disabled], to e.g. log a line as an alternative to the tracing
+/// span for when tracing is disabled. For example:
+/// ```rust
+/// # use rustc_const_eval::enter_trace_span;
+/// # 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"));
+/// ```
 #[macro_export]
 macro_rules! enter_trace_span {
     ($machine:ty, $name:ident :: $subname:ident $($tt:tt)*) => {