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

oli-obk · 2020-08-04T13:46:26Z

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.

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

davidbarsky · 2020-08-04T15:00:57Z

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.

I think I can get tracing-tree to not be a nightmare when used with concurrent programs if I introduce a fine-grained, per-span (or per-span parentage hierarchy) locking behavior.

I also think it should be possible to get something that can be dynamically switched between tracing_subscriber::fmt::Layer and tracing_tree::Layer using the reload layer. I can talk a bit more about that, if you'd like.

oli-obk · 2020-08-04T15:57:09Z

Oh interesting! So we could turn on tracing-tree if we're running without concurrency (or when another flag is set that just disables it even without concurrency)?

locking behavior.

Uh, so... logs would not show until a thread is done with a span? So the entire span content would be buffered? That seems ok to me in most cases. We just need to turn all that off when debugging threading issues.

Mark-Simulacrum · 2020-08-04T16:05:22Z

I think I would personally prefer that we not try to introduce locks or anything into rustc itself but rather have a separate tool that parses and re-shuffles logger output -- is that feasible? Too hard?

hawkw · 2020-08-04T16:14:53Z

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.

You should be able to use a filter like debug,[frame]=off (although I've not tried it). If that doesn't work, let me know — the filter implementation is quite complex and we're still trying to work out some of the kinks with more complex filtering.

oli-obk · 2020-08-04T16:26:22Z

is that feasible? Too hard?

I was considering that, too. Shouldn't be too hard to just prepend all log messages with a thread index (only if rustc is configured to use threads), then you can easily filter with just ripgrep.

oli-obk · 2020-08-04T16:30:40Z

If that doesn't work, let me know — the filter implementation is quite complex and we're still trying to work out some of the kinks with more complex filtering.

I tried RUSTC_LOG=rustc_mir::interpret=debug,[frame]=off, but I'm seeing frame{some::path::stuff} in the output (with the present PR, no other local changes)

Mark-Simulacrum · 2020-08-04T16:47:20Z

rustc always uses threads for LLVM, at least, so it probably makes sense to just always include a thread ID.

hawkw · 2020-08-04T16:56:08Z

If that doesn't work, let me know — the filter implementation is quite complex and we're still trying to work out some of the kinks with more complex filtering.

I tried RUSTC_LOG=rustc_mir::interpret=debug,[frame]=off, but I'm seeing frame{some::path::stuff} in the output (with the present PR, no other local changes)

Ugh, that's a bummer...I guess the "static" (target-based) filter takes priority. As I mentioned, the filtering code is pretty hairy...we need to make some changes so it behaves more reasonably with complex filters.

I was considering that, too. Shouldn't be too hard to just prepend all log messages with a thread index (only if rustc is configured to use threads), then you can easily filter with just ripgrep.

https://docs.rs/tracing-subscriber/0.2.10/tracing_subscriber/fmt/format/struct.Format.html#method.with_thread_ids :)

davidbarsky · 2020-08-04T17:51:28Z

@oli-obk:

Oh interesting! So we could turn on tracing-tree if we're running without concurrency (or when another flag is set that just disables it even without concurrency)?

Maybe?

Uh, so... logs would not show until a thread is done with a span? So the entire span content would be buffered? That seems ok to me in most cases. We just need to turn all that off when debugging threading issues.

I think so!

@Mark-Simulacrum:

I think I would personally prefer that we not try to introduce locks or anything into rustc itself but rather have a separate tool that parses and re-shuffles logger output.

Fair enough, that's a good point!

is that feasible? Too hard?
I suppose there are a few options:

Revive https://github.com/tokio-rs/console
Build something similar to https://github.com/jonathanj/eliottree.
Direct folks use something like Jaeger in a container with https://docs.rs/tracing-opentelemetry/0.5.0/tracing_opentelemetry/, but that might be a bit heavyweight.

In either case, I'll hold off on any changes. Do you mind commenting on tokio-rs/tracing#884 with your needs and requirements?

RalfJung · 2020-08-05T17:24:34Z

So regarding this concrete PR, that's very interesting! But I feel like having the entire stacktrace on every line is way too verbose. Consider what this will look like in Miri where stacks are at least 10 frames high from the libstd start stuff, and can reach 50 frames easily.

But I agree that our traces could be made easier to read. Some random ideas:

Increase indentation by 2 for each frame, but in a way that actually helps. I know there is existing code for that but at least for Miri output I never visually "saw" this, it just wasn't helpful. I am not sure why. I think part of it is that Miri's logging is entirely separate from the core engine logging, and doesn't indent with it -- is that fixable with tracing?
Print the full stack trace occasionally. Like maybe each time it changes (function call/return)?

RalfJung · 2020-08-05T17:29:30Z

src/librustc_mir/interpret/eval_context.rs

+        // 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);


Wow this is super confusing and IMO needs more comments.^^

So the thing we do here is that SpanGuard calls "enter" on something in log::dispacher inside SpanGuard::enter, and it calls exit on drop. But we call the exit after the enter, and somehow it still works? And what if we create a SpanGaurd and never enter it, then we exit something that was never entered?

It doesn't help that Span is already something very different in rustc so my brain just makes all the wrong connections all the time.^^

Yea, the ordering wasn't ideal (I changed it), but also technically irrelevant as enter never gets called twice, but if it were, this would be sane.

I documented all this on the new´ and enter` methods

src/librustc_mir/interpret/eval_context.rs

oli-obk · 2020-08-06T08:44:01Z

I played around a bit with tracing-tree, what do you think of something like ? That doesn't repeat the current stack every now and then, but it makes it fairly easy to track. I could also add something at the closing of a span. This way we basically get back today's behaviour with the start/end logs of a stack frame, but we also have the tree structure

RalfJung · 2020-08-06T08:59:40Z

Hm... that looks promising yes. Is there some way to cap this so that when we have 70 nested frames we don't have a terminal full of vertical bars? Maybe after depth 50, reset to 0 and start over with the nesting or so?

oli-obk · 2020-08-06T09:18:00Z

Is there some way to cap this so that when we have 70 nested frames we don't have a terminal full of vertical bars? Maybe after depth 50, reset to 0 and start over with the nesting or so?

I'll have a look, that should be doable

oli-obk · 2020-08-06T09:26:38Z

Note that with the appropriate filters we can hide arbitrary levels. So we could set it up that the logs only start after a specific frame has been pushed and stop after that frame is popped. We'd could build a list of useful filters for ppl to pass to RUSTC_LOG.

oli-obk · 2020-08-11T10:35:34Z

All the features discussed in this PR have been merged into tracing_tree, here's a picture of how the logs look with colors and other formatting:

In textual form:

2:rustc INFO rustc_mir::interpret::eval_context PAUSING
2:rustcrustc_mir::interpret::eval_context::frame{message=unwind::libunwind::_Unwind_Exception::private::{{constant}}#0}
2:rustc├─0ms  INFO rustc_mir::interpret::eval_context ENTERING
2:rustc├─0ms  INFO rustc_mir::interpret::step _0 = const unwind::libunwind::unwinder_private_data_size
2:rustc├─0ms  INFO rustc_mir::interpret::eval_context PAUSING
2:rustc├─rustc_mir::interpret::eval_context::frame{message=unwind::libunwind::unwinder_private_data_size}
2:rustc│ ├─0ms  INFO rustc_mir::interpret::eval_context ENTERING
2:rustc│ ├─0ms  INFO rustc_mir::interpret::step _0 = const 6_usize
2:rustc│ ├─0ms  INFO rustc_mir::interpret::step return
2:rustc│ ├─0ms  INFO rustc_mir::interpret::eval_context LEAVING(0) unwind::libunwind::unwinder_private_data_size (unwinding = false)
2:rustc├─0ms  INFO rustc_mir::interpret::step return
2:rustc├─0ms  INFO rustc_mir::interpret::eval_context LEAVING(0) unwind::libunwind::_Unwind_Exception::private::{{constant}}#0 (unwinding = false)

RalfJung · 2020-08-12T12:05:49Z

I like that rendering, except for this part

rustc_mir::interpret::eval_context::frame{message=unwind::libunwind::unwinder_private_data_size}

Is there any way to make the function name more prominent here? I feel it drowns a bit in the noise, with the {message=...} around it.

Also the ENTERING is rather redundant, isn't it? (LEAVING is nice because it repeats the function name.)

RalfJung · 2020-08-12T12:08:03Z

Also PAUSING doesnt have the function name any more (not sure why) and looks very different than the other messages? It has no timing and the "INFO" is before the module instzad of after.

And what about CONTINUING?

src/librustc_mir/interpret/eval_context.rs

RalfJung · 2020-08-12T12:11:24Z

Also my question is still open of how this looks like in Miri, when there are also Miri log messages between the core engine log messages.

oli-obk · 2020-08-12T12:41:30Z

with the {message=...} around it.

oops, I didn't notice that. I'm gonna remove all that. This wrapping isn't necessary for hierarchical printing

oli-obk · 2020-09-28T07:30:43Z

Ideally with an extra marker for whenever basic::server is repeated, indicating that this is not a new thing but a repetition of old data.

The extra marker is ┐ ;)

If you come up with better symbols, I'm very open to other things, but I'd rather get something merged and bikeshed symbols in the tracing-tree bugtracker

RalfJung · 2020-09-28T07:34:52Z

If you come up with better symbols, I'm very open to other things, but I'd rather get something merged and bikeshed symbols in the tracing-tree bugtracker

Sure.

davidbarsky · 2020-09-28T16:30:37Z

This is now just waiting on davidbarsky/tracing-tree#19 getting merged and @davidbarsky publishing a new version after that.

Sorry about that! Totally slipped my mind—I read the notification on GitHub and left it in my tabs. Taking care of that now; I'll update y'all when I publish a new version in about 30 minutes.

oli-obk · 2020-09-28T16:39:19Z

No worries! Thanks for taking care of it now.

davidbarsky · 2020-09-28T16:52:31Z

Done, @oli-obk! https://github.com/davidbarsky/tracing-tree/releases/tag/v0.1.6

oli-obk · 2020-09-28T17:58:49Z

New output:

RalfJung · 2020-09-30T19:22:21Z

Yes that rendering looks great. :)

RalfJung · 2020-09-30T19:24:33Z

compiler/rustc_mir/src/interpret/eval_context.rs

-                self.frame().instance,
-                unwinding
-            );
+            info!(unwinding);


Why is info!(unwinding) run twice? Also just having unwinding=true/false in the log without much context is not very clear...

The duplication is gone, and we now inform about the stack popping again

Ooh, maybe we should try out #[instrument] next 😆

Ooh, maybe we should try out #[instrument] next laughing

No idea what that means.^^

RalfJung · 2020-10-03T10:12:40Z

@bors r+

bors · 2020-10-03T10:12:41Z

📌 Commit 8f9472c has been approved by RalfJung

@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

Rollup of 11 pull requests Successful merges: - rust-lang#75143 (Use `tracing` spans to trace the entire MIR interp stack) - rust-lang#75699 (Uplift drop-bounds lint from clippy) - rust-lang#76768 (Test and reject out-of-bounds shuffle vectors) - rust-lang#77190 (updated p! macro to accept literals) - rust-lang#77388 (Add some regression tests) - rust-lang#77419 (Create E0777 error code for invalid argument in derive) - rust-lang#77447 (BTreeMap: document DrainFilterInner better) - rust-lang#77468 (Fix test name) - rust-lang#77469 (Improve rustdoc error for failed intra-doc link resolution) - rust-lang#77473 (Make --all-targets in x.py check opt-in) - rust-lang#77508 (Fix capitalization in blog post name) Failed merges: r? `@ghost`

…-obk logging: add env var to control verbose scope entry/exit logging ~~This got removed in rust-lang#75143, and I find this makes long traces a lot harder to read, so I propose we add this back.~~ Example trace: ``` │ │ ├─0ms INFO rustc_const_eval::interpret::step return │ │ ├─0ms INFO rustc_const_eval::interpret::eval_context popping stack frame (returning from function) │ │┌┘rustc_const_eval::interpret::eval_context::frame std::ptr::mut_ptr::<impl *mut u8>::guaranteed_eq │ ├┘rustc_const_eval::interpret::eval_context::frame std::ptr::mut_ptr::<impl *mut u8>::is_null │ ├─1ms INFO rustc_const_eval::interpret::step // executing bb2 │ ├─1ms INFO rustc_const_eval::interpret::step StorageDead(_4) │ ├─1ms INFO rustc_const_eval::interpret::step StorageDead(_2) │ ├─1ms INFO rustc_const_eval::interpret::step return │ ├─1ms INFO rustc_const_eval::interpret::eval_context popping stack frame (returning from function) │┌┘rustc_const_eval::interpret::eval_context::frame std::ptr::mut_ptr::<impl *mut u8>::is_null ├┘rustc_const_eval::interpret::eval_context::frame std::sys_common::thread_local_dtor::register_dtor_fallback::run_dtors ├─178ms INFO rustc_const_eval::interpret::step // executing bb2 ├─178ms INFO rustc_const_eval::interpret::step StorageDead(_5) ``` r? `@oli-obk`

rust-highfive assigned RalfJung Aug 4, 2020

rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Aug 4, 2020

RalfJung reviewed Aug 5, 2020

View reviewed changes

hawkw reviewed Aug 5, 2020

View reviewed changes

RalfJung added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Aug 10, 2020

oli-obk added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Aug 11, 2020

oli-obk force-pushed the tracing branch from 7939615 to 0197848 Compare August 11, 2020 11:06

RalfJung reviewed Aug 12, 2020

View reviewed changes

src/librustc_mir/interpret/eval_context.rs Outdated Show resolved Hide resolved

RalfJung reviewed Aug 12, 2020

View reviewed changes

src/librustc_mir/interpret/eval_context.rs Outdated Show resolved Hide resolved

RalfJung mentioned this pull request Sep 28, 2020

Better indicate which log entries are repeated davidbarsky/tracing-tree#22

Open

oli-obk force-pushed the tracing branch from 030e4bb to 29fc2e2 Compare September 28, 2020 17:58

Use tracing spans to trace the entire MIR interp stack

43c181b

oli-obk force-pushed the tracing branch from 29fc2e2 to 43c181b Compare September 28, 2020 18:08

oli-obk mentioned this pull request Sep 30, 2020

Update logging for tracing rust-lang/rustc-dev-guide#892

Closed

RalfJung reviewed Sep 30, 2020

View reviewed changes

Only mention that a stack frame is being popped when starting to do so

8f9472c

bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Oct 3, 2020

Dylan-DPC-zz mentioned this pull request Oct 3, 2020

Rollup of 9 pull requests #77483

Closed

jonas-schievink mentioned this pull request Oct 3, 2020

Rollup of 12 pull requests #77509

Closed

JohnTitor mentioned this pull request Oct 4, 2020

Rollup of 11 pull requests #77517

Merged

bors merged commit 6e25418 into rust-lang:master Oct 4, 2020

rustbot added this to the 1.49.0 milestone Oct 4, 2020

oli-obk deleted the tracing branch October 5, 2020 08:16

RalfJung mentioned this pull request May 10, 2022

logging: add env var to control verbose scope entry/exit logging #96898

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

oli-obk commented Aug 4, 2020

davidbarsky commented Aug 4, 2020

oli-obk commented Aug 4, 2020

Mark-Simulacrum commented Aug 4, 2020

hawkw commented Aug 4, 2020

oli-obk commented Aug 4, 2020

oli-obk commented Aug 4, 2020

Mark-Simulacrum commented Aug 4, 2020

hawkw commented Aug 4, 2020

davidbarsky commented Aug 4, 2020

RalfJung commented Aug 5, 2020

RalfJung Aug 5, 2020

oli-obk Aug 11, 2020

oli-obk commented Aug 6, 2020

RalfJung commented Aug 6, 2020

oli-obk commented Aug 6, 2020

oli-obk commented Aug 6, 2020

oli-obk commented Aug 11, 2020

RalfJung commented Aug 12, 2020

RalfJung commented Aug 12, 2020

RalfJung commented Aug 12, 2020

oli-obk commented Aug 12, 2020

oli-obk commented Sep 28, 2020

RalfJung commented Sep 28, 2020

davidbarsky commented Sep 28, 2020

oli-obk commented Sep 28, 2020

davidbarsky commented Sep 28, 2020

oli-obk commented Sep 28, 2020 •

edited

Loading

RalfJung commented Sep 30, 2020

RalfJung Sep 30, 2020

oli-obk Oct 1, 2020

RalfJung Oct 3, 2020

RalfJung commented Oct 3, 2020

bors commented Oct 3, 2020

Use tracing spans to trace the entire MIR interp stack #75143

Use tracing spans to trace the entire MIR interp stack #75143

Conversation

oli-obk commented Aug 4, 2020

davidbarsky commented Aug 4, 2020

oli-obk commented Aug 4, 2020

Mark-Simulacrum commented Aug 4, 2020

hawkw commented Aug 4, 2020

oli-obk commented Aug 4, 2020

oli-obk commented Aug 4, 2020

Mark-Simulacrum commented Aug 4, 2020

hawkw commented Aug 4, 2020

davidbarsky commented Aug 4, 2020

RalfJung commented Aug 5, 2020

RalfJung Aug 5, 2020

Choose a reason for hiding this comment

oli-obk Aug 11, 2020

Choose a reason for hiding this comment

oli-obk commented Aug 6, 2020

RalfJung commented Aug 6, 2020

oli-obk commented Aug 6, 2020

oli-obk commented Aug 6, 2020

oli-obk commented Aug 11, 2020

RalfJung commented Aug 12, 2020

RalfJung commented Aug 12, 2020

RalfJung commented Aug 12, 2020

oli-obk commented Aug 12, 2020

oli-obk commented Sep 28, 2020

RalfJung commented Sep 28, 2020

davidbarsky commented Sep 28, 2020

oli-obk commented Sep 28, 2020

davidbarsky commented Sep 28, 2020

oli-obk commented Sep 28, 2020 • edited Loading

RalfJung commented Sep 30, 2020

RalfJung Sep 30, 2020

Choose a reason for hiding this comment

oli-obk Oct 1, 2020

Choose a reason for hiding this comment

RalfJung Oct 3, 2020

Choose a reason for hiding this comment

RalfJung commented Oct 3, 2020

bors commented Oct 3, 2020

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

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

oli-obk commented Sep 28, 2020 •

edited

Loading