Skip to content
Merged
Show file tree
Hide file tree
Changes from 3 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions compiler/rustc_const_eval/src/interpret/eval_context.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}

Expand All @@ -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)
}

Expand All @@ -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)
}
}
Expand Down
6 changes: 3 additions & 3 deletions compiler/rustc_const_eval/src/interpret/stack.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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(())
Expand Down
63 changes: 61 additions & 2 deletions compiler/rustc_const_eval/src/interpret/util.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we duplicate this macro between Miri and rustc? Can we reuse the rustc definition in Miri?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because from Miri we use #[cfg(feature = "tracing")] to decide whether to do tracing or not, and from rustc_const_eval we instead have to call Machine::enter_trace_span and let it decide whether to do tracing or not. I guess we could make the Miri macro pass MiriMachine<'static> as $machine to this macro and then it would work, but #[cfg(feature = "tracing")] will probably optimize things out better than a call to Machine::enter_trace_span.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm... then please add that as a comment in the Miri version of the macro.

It may be worth briefly benchmarking (./miri bench, not the option to save/load a baseline file) whether it makes any difference to use the rustc version from Miri -- but that doesn't have to block this PR.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did the benchmarks in the end and it seems like there is no difference (the differences are all within statistical significance, and some are higher some lower). So I pushed a commit that makes the Miri one just call the rustc_const_eval one.

Benchmark of #[cfg(feature = "tracing")]
# benchmark of miri with tracing disabled when enter_trace_span! is disabled using #[cfg(feature = "tracing")]

$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/backtraces/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/backtraces/Cargo.toml"
  Time (mean ± σ):      2.642 s ±  0.024 s    [User: 2.557 s, System: 0.088 s]
  Range (min … max):    2.591 s …  2.697 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/big-allocs/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/big-allocs/Cargo.toml"
  Time (mean ± σ):     184.2 ms ±   2.6 ms    [User: 109.8 ms, System: 80.3 ms]
  Range (min … max):   179.3 ms … 189.6 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/mse/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/mse/Cargo.toml"
  Time (mean ± σ):     815.5 ms ±   8.0 ms    [User: 740.9 ms, System: 80.3 ms]
  Range (min … max):   804.8 ms … 834.1 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/range-iteration/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/range-iteration/Cargo.toml"
  Time (mean ± σ):      4.724 s ±  0.049 s    [User: 4.647 s, System: 0.080 s]
  Range (min … max):    4.619 s …  4.829 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/serde1/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/serde1/Cargo.toml"
  Time (mean ± σ):      2.884 s ±  0.046 s    [User: 2.800 s, System: 0.087 s]
  Range (min … max):    2.821 s …  3.057 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/serde2/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/serde2/Cargo.toml"
  Time (mean ± σ):      6.402 s ±  0.055 s    [User: 6.313 s, System: 0.090 s]
  Range (min … max):    6.303 s …  6.565 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/slice-chunked/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/slice-chunked/Cargo.toml"
  Time (mean ± σ):     511.5 ms ±   7.8 ms    [User: 435.7 ms, System: 81.3 ms]
  Range (min … max):   494.6 ms … 530.7 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/slice-get-unchecked/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/slice-get-unchecked/Cargo.toml"
  Time (mean ± σ):     856.6 ms ±  12.1 ms    [User: 780.5 ms, System: 81.3 ms]
  Range (min … max):   834.9 ms … 886.5 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/string-replace/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/string-replace/Cargo.toml"
  Time (mean ± σ):     545.8 ms ±   9.9 ms    [User: 464.7 ms, System: 86.6 ms]
  Range (min … max):   528.4 ms … 572.6 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/unicode/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/unicode/Cargo.toml"
  Time (mean ± σ):      3.766 s ±  0.052 s    [User: 3.688 s, System: 0.081 s]
  Range (min … max):    3.679 s …  3.898 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/zip-equal/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/zip-equal/Cargo.toml"
  Time (mean ± σ):      3.304 s ±  0.037 s    [User: 3.221 s, System: 0.086 s]
  Range (min … max):    3.250 s …  3.421 s    50 runs
Benchmark of deferring to rustc_const_eval::enter_trace_span!
# benchmark of miri with tracing disabled when enter_trace_span! is disabled by calling Machine::enter_trace_span (i.e. pointing to rustc_const_eval's implementation)

$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/backtraces/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/backtraces/Cargo.toml"
  Time (mean ± σ):      2.651 s ±  0.041 s    [User: 2.566 s, System: 0.088 s]
  Range (min … max):    2.585 s …  2.761 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/big-allocs/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/big-allocs/Cargo.toml"
  Time (mean ± σ):     183.6 ms ±   2.0 ms    [User: 110.2 ms, System: 79.3 ms]
  Range (min … max):   180.5 ms … 188.9 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/mse/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/mse/Cargo.toml"
  Time (mean ± σ):     835.0 ms ±  10.3 ms    [User: 758.1 ms, System: 82.2 ms]
  Range (min … max):   817.5 ms … 857.2 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/range-iteration/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/range-iteration/Cargo.toml"
  Time (mean ± σ):      4.755 s ±  0.043 s    [User: 4.676 s, System: 0.081 s]
  Range (min … max):    4.678 s …  4.878 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/serde1/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/serde1/Cargo.toml"
  Time (mean ± σ):      2.870 s ±  0.055 s    [User: 2.784 s, System: 0.088 s]
  Range (min … max):    2.806 s …  3.056 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/serde2/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/serde2/Cargo.toml"
  Time (mean ± σ):      6.359 s ±  0.080 s    [User: 6.267 s, System: 0.090 s]
  Range (min … max):    6.249 s …  6.537 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/slice-chunked/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/slice-chunked/Cargo.toml"
  Time (mean ± σ):     504.2 ms ±   7.3 ms    [User: 428.1 ms, System: 81.4 ms]
  Range (min … max):   493.3 ms … 526.9 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/slice-get-unchecked/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/slice-get-unchecked/Cargo.toml"
  Time (mean ± σ):     866.2 ms ±  10.2 ms    [User: 790.6 ms, System: 80.6 ms]
  Range (min … max):   849.5 ms … 892.6 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/string-replace/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/string-replace/Cargo.toml"
  Time (mean ± σ):     550.5 ms ±   7.6 ms    [User: 469.2 ms, System: 86.7 ms]
  Range (min … max):   538.0 ms … 572.5 ms    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/unicode/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/unicode/Cargo.toml"
  Time (mean ± σ):      3.724 s ±  0.031 s    [User: 3.646 s, System: 0.080 s]
  Range (min … max):    3.657 s …  3.795 s    50 runs
 
$ hyperfine -w 10 -m 50 --shell=none "cargo +miri miri run  --manifest-path \"bench-cargo-miri/zip-equal/Cargo.toml\""
Benchmark 1: cargo +miri miri run  --manifest-path "bench-cargo-miri/zip-equal/Cargo.toml"
  Time (mean ± σ):      3.268 s ±  0.026 s    [User: 3.186 s, System: 0.085 s]
  Range (min … max):    3.211 s …  3.335 s    50 runs

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, you're just too fast, okay. :D

(It's easier to compare these benchmarks if you use --save-baseline/--load-baseline.)

($machine:ident, $name:ident :: $subname:ident $($tt:tt)*) => {{
$crate::enter_trace_span!($machine, stringify!($name), $name = %stringify!($subname) $($tt)*)
}};

($machine:ident, $($tt:tt)*) => {
$machine::enter_trace_span(|| tracing::info_span!($($tt)*))
<$machine as $crate::interpret::Machine>::enter_trace_span(|| tracing::info_span!($($tt)*))
}
}
18 changes: 2 additions & 16 deletions src/tools/miri/src/helpers.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1257,25 +1257,11 @@ pub struct MaybeEnteredTraceSpan {
/// 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", /* ... */)
/// ```
/// 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)*)
$crate::enter_trace_span!(stringify!($name), $name = %stringify!($subname) $($tt)*)
}};

($($tt:tt)*) => {
Expand Down
Loading