Skip to content

Commit 43c181b

Browse files
committed
Use tracing spans to trace the entire MIR interp stack
1 parent 535d27a commit 43c181b

File tree

6 files changed

+75
-40
lines changed

6 files changed

+75
-40
lines changed

Cargo.lock

+3-12
Original file line numberDiff line numberDiff line change
@@ -1723,15 +1723,6 @@ dependencies = [
17231723
"cfg-if",
17241724
]
17251725

1726-
[[package]]
1727-
name = "log_settings"
1728-
version = "0.1.2"
1729-
source = "registry+https://github.com/rust-lang/crates.io-index"
1730-
checksum = "19af41f0565d7c19b2058153ad0b42d4d5ce89ec4dbf06ed6741114a8b63e7cd"
1731-
dependencies = [
1732-
"lazy_static",
1733-
]
1734-
17351726
[[package]]
17361727
name = "lsp-codec"
17371728
version = "0.1.2"
@@ -3520,6 +3511,7 @@ dependencies = [
35203511
"rustc_target",
35213512
"tracing",
35223513
"tracing-subscriber",
3514+
"tracing-tree",
35233515
"winapi 0.3.9",
35243516
]
35253517

@@ -3807,7 +3799,6 @@ version = "0.0.0"
38073799
dependencies = [
38083800
"either",
38093801
"itertools 0.9.0",
3810-
"log_settings",
38113802
"polonius-engine",
38123803
"regex",
38133804
"rustc_apfloat",
@@ -5102,9 +5093,9 @@ dependencies = [
51025093

51035094
[[package]]
51045095
name = "tracing-tree"
5105-
version = "0.1.5"
5096+
version = "0.1.6"
51065097
source = "registry+https://github.com/rust-lang/crates.io-index"
5107-
checksum = "e1a3dc4774db3a6b2d66a4f8d8de670e874ec3ed55615860c994927419b32c5f"
5098+
checksum = "43aac8afb493b08e1e1904956f7407c1e671b9c83b26a17e1bd83d6a3520e350"
51085099
dependencies = [
51095100
"ansi_term 0.12.1",
51105101
"atty",

compiler/rustc_driver/Cargo.toml

+1
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@ crate-type = ["dylib"]
1111
libc = "0.2"
1212
tracing = { version = "0.1.18" }
1313
tracing-subscriber = { version = "0.2.10", default-features = false, features = ["fmt", "env-filter", "smallvec", "parking_lot", "ansi"] }
14+
tracing-tree = "0.1.6"
1415
rustc_middle = { path = "../rustc_middle" }
1516
rustc_ast_pretty = { path = "../rustc_ast_pretty" }
1617
rustc_target = { path = "../rustc_target" }

compiler/rustc_driver/src/lib.rs

+15-5
Original file line numberDiff line numberDiff line change
@@ -1241,11 +1241,21 @@ pub fn init_env_logger(env: &str) {
12411241
Ok(s) if s.is_empty() => return,
12421242
Ok(_) => {}
12431243
}
1244-
let builder = tracing_subscriber::FmtSubscriber::builder();
1245-
1246-
let builder = builder.with_env_filter(tracing_subscriber::EnvFilter::from_env(env));
1247-
1248-
builder.init()
1244+
let filter = tracing_subscriber::EnvFilter::from_env(env);
1245+
let layer = tracing_tree::HierarchicalLayer::default()
1246+
.with_indent_lines(true)
1247+
.with_ansi(true)
1248+
.with_targets(true)
1249+
.with_thread_ids(true)
1250+
.with_thread_names(true)
1251+
.with_wraparound(10)
1252+
.with_verbose_exit(true)
1253+
.with_verbose_entry(true)
1254+
.with_indent_amount(2);
1255+
1256+
use tracing_subscriber::layer::SubscriberExt;
1257+
let subscriber = tracing_subscriber::Registry::default().with(filter).with(layer);
1258+
tracing::subscriber::set_global_default(subscriber).unwrap();
12491259
}
12501260

12511261
pub fn main() -> ! {

compiler/rustc_mir/Cargo.toml

-1
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,6 @@ either = "1.5.0"
1212
rustc_graphviz = { path = "../rustc_graphviz" }
1313
itertools = "0.9"
1414
tracing = "0.1"
15-
log_settings = "0.1.1"
1615
polonius-engine = "0.12.0"
1716
regex = "1"
1817
rustc_middle = { path = "../rustc_middle" }

compiler/rustc_mir/src/interpret/eval_context.rs

+56-21
Original file line numberDiff line numberDiff line change
@@ -48,8 +48,41 @@ pub struct InterpCx<'mir, 'tcx, M: Machine<'mir, 'tcx>> {
4848
FxHashMap<(Ty<'tcx>, Option<ty::PolyExistentialTraitRef<'tcx>>), Pointer<M::PointerTag>>,
4949
}
5050

51+
// The Phantomdata exists to prevent this type from being `Send`. If it were sent across a thread
52+
// boundary and dropped in the other thread, it would exit the span in the other thread.
53+
struct SpanGuard(tracing::Span, std::marker::PhantomData<*const u8>);
54+
55+
impl SpanGuard {
56+
/// By default a `SpanGuard` does nothing.
57+
fn new() -> Self {
58+
Self(tracing::Span::none(), std::marker::PhantomData)
59+
}
60+
61+
/// If a span is entered, we exit the previous span (if any, normally none) and enter the
62+
/// new span. This is mainly so we don't have to use `Option` for the `tracing_span` field of
63+
/// `Frame` by creating a dummy span to being with and then entering it once the frame has
64+
/// been pushed.
65+
fn enter(&mut self, span: tracing::Span) {
66+
// This executes the destructor on the previous instance of `SpanGuard`, ensuring that
67+
// we never enter or exit more spans than vice versa. Unless you `mem::leak`, then we
68+
// can't protect the tracing stack, but that'll just lead to weird logging, no actual
69+
// problems.
70+
*self = Self(span, std::marker::PhantomData);
71+
self.0.with_subscriber(|(id, dispatch)| {
72+
dispatch.enter(id);
73+
});
74+
}
75+
}
76+
77+
impl Drop for SpanGuard {
78+
fn drop(&mut self) {
79+
self.0.with_subscriber(|(id, dispatch)| {
80+
dispatch.exit(id);
81+
});
82+
}
83+
}
84+
5185
/// A stack frame.
52-
#[derive(Clone)]
5386
pub struct Frame<'mir, 'tcx, Tag = (), Extra = ()> {
5487
////////////////////////////////////////////////////////////////////////////////
5588
// Function and callsite information
@@ -80,6 +113,11 @@ pub struct Frame<'mir, 'tcx, Tag = (), Extra = ()> {
80113
/// can either directly contain `Scalar` or refer to some part of an `Allocation`.
81114
pub locals: IndexVec<mir::Local, LocalState<'tcx, Tag>>,
82115

116+
/// The span of the `tracing` crate is stored here.
117+
/// When the guard is dropped, the span is exited. This gives us
118+
/// a full stack trace on all tracing statements.
119+
tracing_span: SpanGuard,
120+
83121
////////////////////////////////////////////////////////////////////////////////
84122
// Current position within the function
85123
////////////////////////////////////////////////////////////////////////////////
@@ -184,6 +222,7 @@ impl<'mir, 'tcx, Tag> Frame<'mir, 'tcx, Tag> {
184222
locals: self.locals,
185223
loc: self.loc,
186224
extra,
225+
tracing_span: self.tracing_span,
187226
}
188227
}
189228
}
@@ -637,11 +676,6 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
637676
return_place: Option<PlaceTy<'tcx, M::PointerTag>>,
638677
return_to_block: StackPopCleanup,
639678
) -> InterpResult<'tcx> {
640-
if !self.stack().is_empty() {
641-
info!("PAUSING({}) {}", self.frame_idx(), self.frame().instance);
642-
}
643-
::log_settings::settings().indentation += 1;
644-
645679
// first push a stack frame so we have access to the local substs
646680
let pre_frame = Frame {
647681
body,
@@ -652,6 +686,7 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
652686
// all methods actually know about the frame
653687
locals: IndexVec::new(),
654688
instance,
689+
tracing_span: SpanGuard::new(),
655690
extra: (),
656691
};
657692
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> {
696731
self.frame_mut().locals = locals;
697732
M::after_stack_push(self)?;
698733
self.frame_mut().loc = Ok(mir::Location::START);
699-
info!("ENTERING({}) {}", self.frame_idx(), self.frame().instance);
734+
735+
let span = info_span!("frame", "{}", instance);
736+
self.frame_mut().tracing_span.enter(span);
700737

701738
Ok(())
702739
}
@@ -746,12 +783,7 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
746783
/// The cleanup block ends with a special `Resume` terminator, which will
747784
/// cause us to continue unwinding.
748785
pub(super) fn pop_stack_frame(&mut self, unwinding: bool) -> InterpResult<'tcx> {
749-
info!(
750-
"LEAVING({}) {} (unwinding = {})",
751-
self.frame_idx(),
752-
self.frame().instance,
753-
unwinding
754-
);
786+
info!(unwinding);
755787

756788
// Sanity check `unwinding`.
757789
assert_eq!(
@@ -766,7 +798,6 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
766798
throw_ub_format!("unwinding past the topmost frame of the stack");
767799
}
768800

769-
::log_settings::settings().indentation -= 1;
770801
let frame =
771802
self.stack_mut().pop().expect("tried to pop a stack frame, but there were none");
772803

@@ -824,12 +855,7 @@ impl<'mir, 'tcx: 'mir, M: Machine<'mir, 'tcx>> InterpCx<'mir, 'tcx, M> {
824855
}
825856

826857
if !self.stack().is_empty() {
827-
info!(
828-
"CONTINUING({}) {} (unwinding = {})",
829-
self.frame_idx(),
830-
self.frame().instance,
831-
unwinding
832-
);
858+
info!(unwinding);
833859
}
834860

835861
Ok(())
@@ -995,7 +1021,16 @@ where
9951021
{
9961022
fn hash_stable(&self, hcx: &mut StableHashingContext<'ctx>, hasher: &mut StableHasher) {
9971023
// Exhaustive match on fields to make sure we forget no field.
998-
let Frame { body, instance, return_to_block, return_place, locals, loc, extra } = self;
1024+
let Frame {
1025+
body,
1026+
instance,
1027+
return_to_block,
1028+
return_place,
1029+
locals,
1030+
loc,
1031+
extra,
1032+
tracing_span: _,
1033+
} = self;
9991034
body.hash_stable(hcx, hasher);
10001035
instance.hash_stable(hcx, hasher);
10011036
return_to_block.hash_stable(hcx, hasher);

src/tools/tidy/src/deps.rs

-1
Original file line numberDiff line numberDiff line change
@@ -116,7 +116,6 @@ const PERMITTED_DEPENDENCIES: &[&str] = &[
116116
"libz-sys",
117117
"lock_api",
118118
"log",
119-
"log_settings",
120119
"maybe-uninit",
121120
"md-5",
122121
"measureme",

0 commit comments

Comments
 (0)