diff --git a/Cargo.lock b/Cargo.lock index 28bd57ef673..fb7d2a4ac2f 100644 --- a/Cargo.lock +++ b/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", diff --git a/compiler/rustc_driver/Cargo.toml b/compiler/rustc_driver/Cargo.toml index adfce1008e1..f610e88b7fc 100644 --- a/compiler/rustc_driver/Cargo.toml +++ b/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" } diff --git a/compiler/rustc_driver/src/lib.rs b/compiler/rustc_driver/src/lib.rs index 544efc124e1..3f50c68e3eb 100644 --- a/compiler/rustc_driver/src/lib.rs +++ b/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)); - - builder.init() + use tracing_subscriber::layer::SubscriberExt; + let subscriber = tracing_subscriber::Registry::default().with(filter).with(layer); + tracing::subscriber::set_global_default(subscriber).unwrap(); } pub fn main() -> ! { diff --git a/compiler/rustc_mir/Cargo.toml b/compiler/rustc_mir/Cargo.toml index a6d22243d6d..487668cfa11 100644 --- a/compiler/rustc_mir/Cargo.toml +++ b/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" } diff --git a/compiler/rustc_mir/src/interpret/eval_context.rs b/compiler/rustc_mir/src/interpret/eval_context.rs index f97096984fa..93da6e3d38a 100644 --- a/compiler/rustc_mir/src/interpret/eval_context.rs +++ b/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>), Pointer>, } +// 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>, + /// 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>, 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 = {})", - self.frame_idx(), - self.frame().instance, - unwinding + "popping stack frame ({})", + if unwinding { "during unwinding" } else { "returning from function" } ); // 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); diff --git a/src/tools/tidy/src/deps.rs b/src/tools/tidy/src/deps.rs index 356705305d7..0c52fee68a9 100644 --- a/src/tools/tidy/src/deps.rs +++ b/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",