Rollup merge of #144688 - Stypox:better-enter-trace-span, r=RalfJung

Uniform `enter_trace_span!` and add documentation

1. The latest changes to `enter_trace_span!` were ported from Miri (see rust-lang/miri#4452 (comment)), so now both the `rustc_const_eval` and the Miri macro accept the same syntax. Furthermore, the Miri macro was changed to just call rustc_const_eval`'s, to avoid duplication.
2. I made the `layout_of` (& friends) calls use that new syntax, e.g. `enter_trace_span!(layouting::layout_of, ...)`
3. I made sure the macro specifies all types/traits/macros it refers to using `$crate::`, so the macro works anywhere independently of which types/traits/macros are imported in the context it is used in.
4. I added documentation, examples and tips to the macro's doc. To make the rustdoc compile I had to add some hidden lines (`#`), but now it acts as a compilation test which will avoid reintroducing issue 3. in the future. I will also create a documentation file with everything one needs to know about tracing at a later point, but I figured adding some of that info directly on the tracing macro makes it more discoverable.
5. In `stack.rs` I made it so that the `"frame"` span has a field named "frame" (instead of "message") with the data about the frame. This field used to be called "message" (tracing's default) since it was previously formatted using `"{}", instance`, and now I replaced it with `frame = %instance`.

Author: jdonszelmann

compiler/rustc_const_eval/src/interpret/eval_context.rs

@@ -113,7 +113,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
     /// See [LayoutOf::layout_of] for the original documentation.
     #[inline(always)]
     pub fn layout_of(&self, ty: Ty<'tcx>) -> <Self as LayoutOfHelpers<'tcx>>::LayoutOfResult {
-        let _span = enter_trace_span!(M, "InterpCx::layout_of", ty = ?ty.kind());
+        let _span = enter_trace_span!(M, layouting::layout_of, ty = ?ty.kind());
         LayoutOf::layout_of(self, ty)
     }
 
@@ -126,7 +126,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
         sig: ty::PolyFnSig<'tcx>,
         extra_args: &'tcx ty::List<Ty<'tcx>>,
     ) -> <Self as FnAbiOfHelpers<'tcx>>::FnAbiOfResult {
-        let _span = enter_trace_span!(M, "InterpCx::fn_abi_of_fn_ptr", ?sig, ?extra_args);
+        let _span = enter_trace_span!(M, layouting::fn_abi_of_fn_ptr, ?sig, ?extra_args);
         FnAbiOf::fn_abi_of_fn_ptr(self, sig, extra_args)
     }
 
@@ -139,7 +139,7 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
         instance: ty::Instance<'tcx>,
         extra_args: &'tcx ty::List<Ty<'tcx>>,
     ) -> <Self as FnAbiOfHelpers<'tcx>>::FnAbiOfResult {
-        let _span = enter_trace_span!(M, "InterpCx::fn_abi_of_instance", ?instance, ?extra_args);
+        let _span = enter_trace_span!(M, layouting::fn_abi_of_instance, ?instance, ?extra_args);
         FnAbiOf::fn_abi_of_instance(self, instance, extra_args)
     }
 }

compiler/rustc_const_eval/src/interpret/stack.rs

@@ -397,11 +397,11 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
         // Finish things up.
         M::after_stack_push(self)?;
         self.frame_mut().loc = Left(mir::Location::START);
-        // `tracing_separate_thread` is used to instruct the chrome_tracing [tracing::Layer] in Miri
+        // `tracing_separate_thread` is used to instruct the tracing_chrome [tracing::Layer] in Miri
         // to put the "frame" span on a separate trace thread/line than other spans, to make the
-        // visualization in https://ui.perfetto.dev easier to interpret. It is set to a value of
+        // visualization in <https://ui.perfetto.dev> easier to interpret. It is set to a value of
         // [tracing::field::Empty] so that other tracing layers (e.g. the logger) will ignore it.
-        let span = info_span!("frame", tracing_separate_thread = Empty, "{}", instance);
+        let span = info_span!("frame", tracing_separate_thread = Empty, frame = %instance);
         self.frame_mut().tracing_span.enter(span);
 
         interp_ok(())

compiler/rustc_const_eval/src/interpret/util.rs

@@ -53,13 +53,72 @@ pub trait EnteredTraceSpan {}
 impl EnteredTraceSpan for () {}
 impl EnteredTraceSpan for tracing::span::EnteredSpan {}
 
-/// Shortand for calling [crate::interpret::Machine::enter_trace_span] on a [tracing::info_span].
+/// 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
 /// default implementation (i.e. when it does not actually enter the span but instead returns `()`).
+/// This macro takes a type implementing the [crate::interpret::Machine] trait as its first argument
+/// and otherwise accepts the same syntax as [tracing::span!] (see some tips below).
 /// Note: the result of this macro **must be used** because the span is exited when it's dropped.
+///
+/// ### Syntax accepted by this macro
+///
+/// The full documentation for the [tracing::span!] syntax can be found at [tracing] under "Using the
+/// Macros". A few possibly confusing syntaxes are listed here:
+/// ```rust
+/// # use rustc_const_eval::enter_trace_span;
+/// # type M = rustc_const_eval::const_eval::CompileTimeMachine<'static>;
+/// # let my_display_var = String::new();
+/// # let my_debug_var = String::new();
+/// // logs a span named "hello" with a field named "arg" of value 42 (works only because
+/// // 42 implements the tracing::Value trait, otherwise use one of the options below)
+/// let _span = enter_trace_span!(M, "hello", arg = 42);
+/// // logs a field called "my_display_var" using the Display implementation
+/// let _span = enter_trace_span!(M, "hello", %my_display_var);
+/// // logs a field called "my_debug_var" using the Debug implementation
+/// let _span = enter_trace_span!(M, "hello", ?my_debug_var);
+///  ```
+///
+/// ### `NAME::SUBNAME` syntax
+///
+/// In addition to the syntax accepted by [tracing::span!], this macro optionally allows passing
+/// the span name (i.e. the first macro argument) in the form `NAME::SUBNAME` (without quotes) to
+/// indicate that the span has name "NAME" (usually the name of the component) and has an additional
+/// more specific name "SUBNAME" (usually the function name). The latter is passed to the [tracing]
+/// infrastructure as a span field with the name "NAME". This allows not being distracted by
+/// subnames when looking at the trace in <https://ui.perfetto.dev>, but when deeper introspection
+/// is needed within a component, it's still possible to view the subnames directly in the UI by
+/// selecting a span, clicking on the "NAME" argument on the right, and clicking on "Visualize
+/// argument values".
+/// ```rust
+/// # use rustc_const_eval::enter_trace_span;
+/// # type M = rustc_const_eval::const_eval::CompileTimeMachine<'static>;
+/// // for example, the first will expand to the second
+/// let _span = enter_trace_span!(M, borrow_tracker::on_stack_pop, /* ... */);
+/// let _span = enter_trace_span!(M, "borrow_tracker", borrow_tracker = "on_stack_pop", /* ... */);
+/// ```
+///
+/// ### `tracing_separate_thread` parameter
+///
+/// This macro was introduced to obtain better traces of Miri without impacting release performance.
+/// Miri saves traces using the the `tracing_chrome` `tracing::Layer` so that they can be visualized
+/// in <https://ui.perfetto.dev>. To instruct `tracing_chrome` to put some spans on a separate trace
+/// thread/line than other spans when viewed in <https://ui.perfetto.dev>, you can pass
+/// `tracing_separate_thread = tracing::field::Empty` to the tracing macros. This is useful to
+/// separate out spans which just indicate the current step or program frame being processed by the
+/// interpreter. You should use a value of [tracing::field::Empty] so that other tracing layers
+/// (e.g. the logger) will ignore the `tracing_separate_thread` field. For example:
+/// ```rust
+/// # use rustc_const_eval::enter_trace_span;
+/// # type M = rustc_const_eval::const_eval::CompileTimeMachine<'static>;
+/// let _span = enter_trace_span!(M, step::eval_statement, tracing_separate_thread = tracing::field::Empty);
+/// ```
 #[macro_export]
 macro_rules! enter_trace_span {
-    ($machine:ident, $($tt:tt)*) => {
-        $machine::enter_trace_span(|| tracing::info_span!($($tt)*))
-    }
+    ($machine:ty, $name:ident :: $subname:ident $($tt:tt)*) => {
+        $crate::enter_trace_span!($machine, stringify!($name), $name = %stringify!($subname) $($tt)*)
+    };
+
+    ($machine:ty, $($tt:tt)*) => {
+        <$machine as $crate::interpret::Machine>::enter_trace_span(|| tracing::info_span!($($tt)*))
+    };
 }

src/tools/miri/src/helpers.rs

@@ -1245,43 +1245,14 @@ impl ToU64 for usize {
     }
 }
 
-/// This struct is needed to enforce `#[must_use]` on values produced by [enter_trace_span] even
-/// when the "tracing" feature is not enabled.
-#[must_use]
-pub struct MaybeEnteredTraceSpan {
-    #[cfg(feature = "tracing")]
-    pub _entered_span: tracing::span::EnteredSpan,
-}
-
 /// Enters a [tracing::info_span] only if the "tracing" feature is enabled, otherwise does nothing.
-/// This is like [rustc_const_eval::enter_trace_span] except that it does not depend on the
-/// [Machine] trait to check if tracing is enabled, because from the Miri codebase we can directly
-/// check whether the "tracing" feature is enabled, unlike from the rustc_const_eval codebase.
-///
-/// In addition to the syntax accepted by [tracing::span!], this macro optionally allows passing
-/// the span name (i.e. the first macro argument) in the form `NAME::SUBNAME` (without quotes) to
-/// indicate that the span has name "NAME" (usually the name of the component) and has an additional
-/// more specific name "SUBNAME" (usually the function name). The latter is passed to the [tracing]
-/// infrastructure as a span field with the name "NAME". This allows not being distracted by
-/// subnames when looking at the trace in <https://ui.perfetto.dev>, but when deeper introspection
-/// is needed within a component, it's still possible to view the subnames directly in the UI by
-/// selecting a span, clicking on the "NAME" argument on the right, and clicking on "Visualize
-/// argument values".
-/// ```rust
-/// // for example, the first will expand to the second
-/// enter_trace_span!(borrow_tracker::on_stack_pop, /* ... */)
-/// enter_trace_span!("borrow_tracker", borrow_tracker = "on_stack_pop", /* ... */)
-/// ```
+/// This calls [rustc_const_eval::enter_trace_span] with [MiriMachine] as the first argument, which
+/// will in turn call [MiriMachine::enter_trace_span], which takes care of determining at compile
+/// time whether to trace or not (and supposedly the call is compiled out if tracing is disabled).
+/// Look at [rustc_const_eval::enter_trace_span] for complete documentation, examples and tips.
 #[macro_export]
 macro_rules! enter_trace_span {
-    ($name:ident :: $subname:ident $($tt:tt)*) => {{
-        enter_trace_span!(stringify!($name), $name = %stringify!($subname) $($tt)*)
-    }};
-
     ($($tt:tt)*) => {
-        $crate::MaybeEnteredTraceSpan {
-            #[cfg(feature = "tracing")]
-            _entered_span: tracing::info_span!($($tt)*).entered()
-        }
+        rustc_const_eval::enter_trace_span!($crate::MiriMachine<'static>, $($tt)*)
     };
 }

src/tools/miri/src/lib.rs

@@ -143,9 +143,7 @@ pub use crate::eval::{
     AlignmentCheck, BacktraceStyle, IsolatedOp, MiriConfig, MiriEntryFnType, RejectOpWith,
     ValidationMode, create_ecx, eval_entry,
 };
-pub use crate::helpers::{
-    AccessKind, EvalContextExt as _, MaybeEnteredTraceSpan, ToU64 as _, ToUsize as _,
-};
+pub use crate::helpers::{AccessKind, EvalContextExt as _, ToU64 as _, ToUsize as _};
 pub use crate::intrinsics::EvalContextExt as _;
 pub use crate::machine::{
     AllocExtra, DynMachineCallback, FrameExtra, MachineCallback, MemoryKind, MiriInterpCx,