Rollup merge of #75143 - oli-obk:tracing, r=RalfJung

Use `tracing` spans to trace the entire MIR interp stack

r? @RalfJung

While being very verbose, this allows really good tracking of what's going on. While I considered schemes like the previous indenter that we had (which we could get by using the `tracing-tree` crate), this will break down horribly with things like multithreaded rustc. Instead, we can now use `RUSTC_LOG` to restrict the things being traced. You could specify a filter in a way that only shows the logging of a specific frame.

![screenshot of command line output of the new formatting](https://user-images.githubusercontent.com/332036/89291343-aa40de00-d65a-11ea-9f6c-ea06c1806327.png)

If we lower the span's level to `debug`, then in `info` level logging we'd not see the frames, but in `debug` level we would see them. The filtering rules in `tracing` are super powerful, but  I'm not sure if we can specify a filter so we do see `debug` level events, but *not* the `frame` spans. The documentation at https://docs.rs/tracing-subscriber/0.2.10/tracing_subscriber/struct.EnvFilter.html makes me think that we can only turn on things, not turn off things at a more precise level.

cc @hawkw

Cargo.lock

@@ -1726,15 +1726,6 @@ dependencies = [
  "cfg-if",
 ]
 
-[[package]]
-name = "log_settings"
-version = "0.1.2"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "19af41f0565d7c19b2058153ad0b42d4d5ce89ec4dbf06ed6741114a8b63e7cd"
-dependencies = [
- "lazy_static",
-]
-
 [[package]]
 name = "lsp-codec"
 version = "0.1.2"
@@ -3523,6 +3514,7 @@ dependencies = [
  "rustc_target",
  "tracing",
  "tracing-subscriber",
+ "tracing-tree",
  "winapi 0.3.9",
 ]
 
@@ -3810,7 +3802,6 @@ version = "0.0.0"
 dependencies = [
  "either",
  "itertools 0.9.0",
- "log_settings",
  "polonius-engine",
  "regex",
  "rustc_apfloat",
@@ -5105,9 +5096,9 @@ dependencies = [
 
 [[package]]
 name = "tracing-tree"
-version = "0.1.5"
+version = "0.1.6"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "e1a3dc4774db3a6b2d66a4f8d8de670e874ec3ed55615860c994927419b32c5f"
+checksum = "43aac8afb493b08e1e1904956f7407c1e671b9c83b26a17e1bd83d6a3520e350"
 dependencies = [
  "ansi_term 0.12.1",
  "atty",

compiler/rustc_driver/Cargo.toml

@@ -11,6 +11,7 @@ crate-type = ["dylib"]
 libc = "0.2"
 tracing = { version = "0.1.18" }
 tracing-subscriber = { version = "0.2.10", default-features = false, features = ["fmt", "env-filter", "smallvec", "parking_lot", "ansi"] }
+tracing-tree = "0.1.6"
 rustc_middle = { path = "../rustc_middle" }
 rustc_ast_pretty = { path = "../rustc_ast_pretty" }
 rustc_target = { path = "../rustc_target" }

compiler/rustc_driver/src/lib.rs

@@ -1251,11 +1251,21 @@ pub fn init_env_logger(env: &str) {
         Ok(s) if s.is_empty() => return,
         Ok(_) => {}
     }
-    let builder = tracing_subscriber::FmtSubscriber::builder();
+    let filter = tracing_subscriber::EnvFilter::from_env(env);
+    let layer = tracing_tree::HierarchicalLayer::default()
+        .with_indent_lines(true)
+        .with_ansi(true)
+        .with_targets(true)
+        .with_thread_ids(true)
+        .with_thread_names(true)
+        .with_wraparound(10)
+        .with_verbose_exit(true)
+        .with_verbose_entry(true)
+        .with_indent_amount(2);
 
-    let builder = builder.with_env_filter(tracing_subscriber::EnvFilter::from_env(env));
+    use tracing_subscriber::layer::SubscriberExt;
-
+    let subscriber = tracing_subscriber::Registry::default().with(filter).with(layer);
-    builder.init()
+    tracing::subscriber::set_global_default(subscriber).unwrap();
 }
 
 pub fn main() -> ! {

compiler/rustc_mir/Cargo.toml

@@ -12,7 +12,6 @@ either = "1.5.0"
 rustc_graphviz = { path = "../rustc_graphviz" }
 itertools = "0.9"
 tracing = "0.1"
-log_settings = "0.1.1"
 polonius-engine = "0.12.0"
 regex = "1"
 rustc_middle = { path = "../rustc_middle" }

compiler/rustc_mir/src/interpret/eval_context.rs

@@ -48,8 +48,41 @@ pub struct InterpCx<'mir, 'tcx, M: Machine<'mir, 'tcx>> {
         FxHashMap<(Ty<'tcx>, Option<ty::PolyExistentialTraitRef<'tcx>>), Pointer<M::PointerTag>>,
 }
 
+// The Phantomdata exists to prevent this type from being `Send`. If it were sent across a thread
+// boundary and dropped in the other thread, it would exit the span in the other thread.
+struct SpanGuard(tracing::Span, std::marker::PhantomData<*const u8>);
+
+impl SpanGuard {
+    /// By default a `SpanGuard` does nothing.
+    fn new() -> Self {
+        Self(tracing::Span::none(), std::marker::PhantomData)
+    }
+
+    /// If a span is entered, we exit the previous span (if any, normally none) and enter the
+    /// new span. This is mainly so we don't have to use `Option` for the `tracing_span` field of
+    /// `Frame` by creating a dummy span to being with and then entering it once the frame has
+    /// been pushed.
+    fn enter(&mut self, span: tracing::Span) {
+        // This executes the destructor on the previous instance of `SpanGuard`, ensuring that
+        // we never enter or exit more spans than vice versa. Unless you `mem::leak`, then we
+        // can't protect the tracing stack, but that'll just lead to weird logging, no actual
+        // problems.
+        *self = Self(span, std::marker::PhantomData);
+        self.0.with_subscriber(|(id, dispatch)| {
+            dispatch.enter(id);
+        });
+    }
+}
+
+impl Drop for SpanGuard {
+    fn drop(&mut self) {
+        self.0.with_subscriber(|(id, dispatch)| {
+            dispatch.exit(id);
+        });
+    }
+}
+
 /// A stack frame.
-#[derive(Clone)]
 pub struct Frame<'mir, 'tcx, Tag = (), Extra = ()> {
     ////////////////////////////////////////////////////////////////////////////////
     // Function and callsite information
@@ -80,6 +113,11 @@ pub struct Frame<'mir, 'tcx, Tag = (), Extra = ()> {
     /// can either directly contain `Scalar` or refer to some part of an `Allocation`.
     pub locals: IndexVec<mir::Local, LocalState<'tcx, Tag>>,
 
+    /// The span of the `tracing` crate is stored here.
+    /// When the guard is dropped, the span is exited. This gives us
+    /// a full stack trace on all tracing statements.
+    tracing_span: SpanGuard,
+
     ////////////////////////////////////////////////////////////////////////////////
     // Current position within the function
     ////////////////////////////////////////////////////////////////////////////////
@@ -184,6 +222,7 @@ impl<'mir, 'tcx, Tag> Frame<'mir, 'tcx, Tag> {
             locals: self.locals,
             loc: self.loc,
             extra,
+            tracing_span: self.tracing_span,
         }
     }
 }
@@ -637,11 +676,6 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
         return_place: Option<PlaceTy<'tcx, M::PointerTag>>,
         return_to_block: StackPopCleanup,
     ) -> InterpResult<'tcx> {
-        if !self.stack().is_empty() {
-            info!("PAUSING({}) {}", self.frame_idx(), self.frame().instance);
-        }
-        ::log_settings::settings().indentation += 1;
-
         // first push a stack frame so we have access to the local substs
         let pre_frame = Frame {
             body,
@@ -652,6 +686,7 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
             // all methods actually know about the frame
             locals: IndexVec::new(),
             instance,
+            tracing_span: SpanGuard::new(),
             extra: (),
         };
         let frame = M::init_frame_extra(self, pre_frame)?;
@@ -696,7 +731,9 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
         self.frame_mut().locals = locals;
         M::after_stack_push(self)?;
         self.frame_mut().loc = Ok(mir::Location::START);
-        info!("ENTERING({}) {}", self.frame_idx(), self.frame().instance);
+
+        let span = info_span!("frame", "{}", instance);
+        self.frame_mut().tracing_span.enter(span);
 
         Ok(())
     }
@@ -747,10 +784,8 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
     /// cause us to continue unwinding.
     pub(super) fn pop_stack_frame(&mut self, unwinding: bool) -> InterpResult<'tcx> {
         info!(
-            "LEAVING({}) {} (unwinding = {})",
+            "popping stack frame ({})",
-            self.frame_idx(),
+            if unwinding { "during unwinding" } else { "returning from function" }
-            self.frame().instance,
-            unwinding
         );
 
         // Sanity check `unwinding`.
@@ -766,7 +801,6 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
             throw_ub_format!("unwinding past the topmost frame of the stack");
         }
 
-        ::log_settings::settings().indentation -= 1;
         let frame =
             self.stack_mut().pop().expect("tried to pop a stack frame, but there were none");
 
@@ -823,15 +857,6 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
             }
         }
 
-        if !self.stack().is_empty() {
-            info!(
-                "CONTINUING({}) {} (unwinding = {})",
-                self.frame_idx(),
-                self.frame().instance,
-                unwinding
-            );
-        }
-
         Ok(())
     }
 
@@ -995,7 +1020,16 @@ where
 {
     fn hash_stable(&self, hcx: &mut StableHashingContext<'ctx>, hasher: &mut StableHasher) {
         // Exhaustive match on fields to make sure we forget no field.
-        let Frame { body, instance, return_to_block, return_place, locals, loc, extra } = self;
+        let Frame {
+            body,
+            instance,
+            return_to_block,
+            return_place,
+            locals,
+            loc,
+            extra,
+            tracing_span: _,
+        } = self;
         body.hash_stable(hcx, hasher);
         instance.hash_stable(hcx, hasher);
         return_to_block.hash_stable(hcx, hasher);

src/tools/tidy/src/deps.rs

@@ -116,7 +116,6 @@ const PERMITTED_DEPENDENCIES: &[&str] = &[
     "libz-sys",
     "lock_api",
     "log",
-    "log_settings",
     "maybe-uninit",
     "md-5",
     "measureme",