Stream: t-compiler/const-eval

Topic: miri-debug-output


RalfJ (Oct 17 2018 at 09:08, on Zulip):

@Oli I'd like to improve readability of our debug traces at least a bit. I want to have a trace that shows all statements, and prints the current function whenever that changes. I see several options:

What do you think?

RalfJ (Oct 17 2018 at 09:09, on Zulip):

I still tend towards the first thing: debug! is what everybody doing miri debugging ought to find useful, trace! then can be enabled only on a dedicated module to get even more details there

oli (Oct 17 2018 at 09:10, on Zulip):

I don't think RUST_LOG gives us the kind of tracing capabilities we really want. Changing the levels by their modules is too large grained

oli (Oct 17 2018 at 09:11, on Zulip):

I'm fine with going the debug! route

oli (Oct 17 2018 at 09:11, on Zulip):

basically this won't include memory dumps anymore I presume?

RalfJ (Oct 17 2018 at 09:12, on Zulip):

yeah memory dumps are already not on debug!

RalfJ (Oct 17 2018 at 09:13, on Zulip):

they could also be a hell of a lot more useful, often I have no clue why it is dumping what

RalfJ (Oct 17 2018 at 09:13, on Zulip):

but that's more complicated^^

oli (Oct 17 2018 at 09:13, on Zulip):

yea :D

RalfJ (Oct 17 2018 at 09:14, on Zulip):

this is what I mean: https://github.com/RalfJung/rust/commit/21f80dab7c2457677c0f2094e78054309131340e

RalfJ (Oct 17 2018 at 09:14, on Zulip):

in some minutes I'll copy-paste you an example of how it looks like

oli (Oct 17 2018 at 09:16, on Zulip):

oh wow, yes I've wanted that "continuing" message so much!

RalfJ (Oct 17 2018 at 09:17, on Zulip):

btw, are these indentation changes actually doing anything?

RalfJ (Oct 17 2018 at 09:17, on Zulip):

if yes, I can't see it^^

RalfJ (Oct 17 2018 at 09:17, on Zulip):

I mean these: ::log_settings::settings().indentation -= 1;

RalfJ (Oct 17 2018 at 09:19, on Zulip):

oh lol. this ICEs in the to_string...

RalfJ (Oct 17 2018 at 09:20, on Zulip):
error: internal compiler error: librustc/util/ppaux.rs:310: finding type for DefId(4/0:2175 ~ alloc[af40]::vec[0]), encountered def-id DefId(4/0:0 ~ alloc[af40]) with no parent
RalfJ (Oct 17 2018 at 09:23, on Zulip):

@Oli so... how do I print an instance nicely without panicking the compiler?^^

oli (Oct 17 2018 at 09:24, on Zulip):

O_o

oli (Oct 17 2018 at 09:24, on Zulip):

the indentation changes don't work in the miri engine

RalfJ (Oct 17 2018 at 09:24, on Zulip):

panic is here: https://github.com/rust-lang/rust/blob/9d7f0da367bae7587ed0ef69bd4384392099fc9e/src/librustc/util/ppaux.rs#L310

oli (Oct 17 2018 at 09:25, on Zulip):

can you try debug printing the instance's Def?

oli (Oct 17 2018 at 09:25, on Zulip):

it's probably not a regular def

oli (Oct 17 2018 at 09:25, on Zulip):

maybe a closure or something

RalfJ (Oct 17 2018 at 09:25, on Zulip):

isn't that what is shows in the panic? will do

oli (Oct 17 2018 at 09:25, on Zulip):

but even so, it should probably not panic :D

RalfJ (Oct 17 2018 at 09:26, on Zulip):

^^

oli (Oct 17 2018 at 09:26, on Zulip):

huh... alloc obviously has no parent, it's the crate root

RalfJ (Oct 17 2018 at 09:27, on Zulip):

And DefId(4/0:2175 ~ alloc[af40]::vec[0]) seems to be what it wants to print?

oli (Oct 17 2018 at 09:27, on Zulip):

https://github.com/rust-lang/rust/blob/9d7f0da367bae7587ed0ef69bd4384392099fc9e/src/librustc/util/ppaux.rs#L293 seems wrong

oli (Oct 17 2018 at 09:27, on Zulip):

we should not try to get the parent of a crate root

RalfJ (Oct 17 2018 at 09:28, on Zulip):

^^

RalfJ (Oct 17 2018 at 09:28, on Zulip):

but what should we do instead?

oli (Oct 17 2018 at 09:29, on Zulip):

something is wrong here... why do you have an instance that points to a module?

RalfJ (Oct 17 2018 at 09:35, on Zulip):

@Oli the def is Item(DefId(4/1:2606 ~ alloc[af40]::vec[0]::{{impl}}[150]::{{constant}}[0]))

oli (Oct 17 2018 at 09:43, on Zulip):

Hm. How did we end up with that other output then?

oli (Oct 17 2018 at 09:43, on Zulip):

Do you have a stacktrace?

RalfJ (Oct 17 2018 at 09:43, on Zulip):

that's from printing it

RalfJ (Oct 17 2018 at 09:43, on Zulip):

no I don't :/ for now I'll just not do the debug printing for the topmost stack frame...^^ this is blocking me debugging stacked borrows so I wanted it to just go away.
I'll build a 2nd compiler but it'll take a bit.

oli (Oct 17 2018 at 09:44, on Zulip):

It's probably when printing the part the path which corresponds to the vec

RalfJ (Oct 17 2018 at 09:46, on Zulip):

well it's walking up the parent relationship, so it might have started anywhere

RalfJ (Oct 17 2018 at 11:13, on Zulip):

@Oli here's your backtrace:

error: internal compiler error: librustc/util/ppaux.rs:310: finding type for DefId(4/0:2175 ~ alloc[af40]::vec[0]), encountered def-id DefId(4/0:0 ~ alloc[af40]) with no parent

thread 'main' panicked at 'Box<Any>', librustc_errors/lib.rs:599:9
stack backtrace:
   0: std::sys::unix::backtrace::tracing::imp::unwind_backtrace
             at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::print
             at libstd/sys_common/backtrace.rs:71
             at libstd/sys_common/backtrace.rs:59
   2: std::panicking::default_hook::{{closure}}
             at libstd/panicking.rs:211
   3: std::panicking::default_hook
             at libstd/panicking.rs:227
   4: rustc::util::common::panic_hook
             at librustc/util/common.rs:51
   5: std::panicking::rust_panic_with_hook
             at libstd/panicking.rs:480
   6: std::panicking::begin_panic
             at /home/r/src/rust/rustc.2/src/libstd/panicking.rs:410
   7: rustc_errors::Handler::bug
             at librustc_errors/lib.rs:599
   8: rustc::ty::context::tls::with_opt::{{closure}}
             at librustc/util/bug.rs:46
             at librustc/ty/context.rs:2160
   9: rustc::ty::context::tls::with_context_opt
             at librustc/ty/context.rs:2097
  10: rustc::ty::context::tls::with_opt
             at librustc/ty/context.rs:2160
  11: rustc::util::bug::opt_span_bug_fmt
             at librustc/util/bug.rs:42
  12: rustc::util::bug::bug_fmt
             at librustc/util/bug.rs:22
  13: rustc::util::ppaux::PrintContext::parameterized::{{closure}}::{{closure}}
             at librustc/util/ppaux.rs:310
  14: rustc::ty::context::tls::with
             at /home/r/src/rust/rustc.2/src/libcore/option.rs:396
             at librustc/util/ppaux.rs:309
             at librustc/ty/context.rs:2152
             at librustc/ty/context.rs:2106
             at librustc/ty/context.rs:2097
             at librustc/ty/context.rs:2106
             at librustc/ty/context.rs:2152
  15: rustc::util::ppaux::PrintContext::parameterized
             at librustc/util/ppaux.rs:273
  16: rustc::util::ppaux::PrintContext::parameterized
             at librustc/util/ppaux.rs:264
  17: rustc::util::ppaux::PrintContext::parameterized
             at librustc/util/ppaux.rs:264
  18: rustc::util::ppaux::parameterized
             at librustc/util/ppaux.rs:571
  19: <rustc::ty::instance::Instance<'tcx> as core::fmt::Display>::fmt
             at librustc/ty/instance.rs:120
  20: core::fmt::write
             at libcore/fmt/mod.rs:1102
             at libcore/fmt/mod.rs:1049
  21: <core::fmt::Arguments<'_> as core::fmt::Debug>::fmt
             at libcore/fmt/mod.rs:447
             at libcore/fmt/mod.rs:440
  22: core::fmt::write
             at libcore/fmt/mod.rs:1102
             at libcore/fmt/mod.rs:1049
  23: std::io::Write::write_fmt
             at /home/r/src/rust/rustc.2/src/libstd/io/mod.rs:1139
  24: env_logger::Format::into_boxed_fn::{{closure}}
             at /home/r/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.5.12/src/lib.rs:357
  25: <std::thread::local::LocalKey<T>>::with
             at /home/r/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.5.12/src/lib.rs:858
             at /home/r/src/rust/rustc.2/src/libstd/thread/local.rs:300
             at /home/r/src/rust/rustc.2/src/libstd/thread/local.rs:254
  26: <env_logger::Logger as log::Log>::log
             at /home/r/.cargo/registry/src/github.com-1ecc6299db9ec823/env_logger-0.5.12/src/lib.rs:829
  27: log::__private_api_log
             at /home/r/.cargo/registry/src/github.com-1ecc6299db9ec823/log-0.4.4/src/lib.rs:1232
  28: <rustc_mir::interpret::eval_context::EvalContext<'a, 'mir, 'tcx, M>>::push_stack_frame
             at librustc_mir/interpret/eval_context.rs:499
  29: rustc_mir::const_eval::eval_body_using_ecx
             at librustc_mir/const_eval.rs:187
  30: rustc_mir::const_eval::const_eval_provider
             at librustc_mir/const_eval.rs:159
             at librustc_mir/const_eval.rs:559
  31: rustc::ty::query::__query_compute::const_eval
             at librustc/ty/query/plumbing.rs:834
             at librustc/ty/query/plumbing.rs:796
  32: rustc::ty::query::<impl rustc::ty::query::config::QueryAccessors<'tcx> for rustc::ty::query::queries::const_eval<'tcx>>::compute
             at librustc/ty/query/plumbing.rs:826
  33: rustc::dep_graph::graph::DepGraph::with_task_impl
             at librustc/dep_graph/graph.rs:342
  34: rustc::ty::context::tls::with_related_context
             at librustc/dep_graph/graph.rs:208
             at librustc/ty/query/plumbing.rs:550
             at librustc/ty/query/plumbing.rs:208
             at librustc/ty/context.rs:2022
             at librustc/ty/context.rs:1961
             at librustc/ty/context.rs:2021
             at librustc/ty/query/plumbing.rs:207
             at librustc/ty/context.rs:2122
             at librustc/ty/context.rs:2106
             at librustc/ty/context.rs:2097
             at librustc/ty/context.rs:2106
             at librustc/ty/context.rs:2117
  35: rustc::ty::query::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::force_query_with_job
             at librustc/ty/query/plumbing.rs:197
             at librustc/ty/query/plumbing.rs:543
  36: rustc::ty::query::plumbing::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::get_query
             at librustc/ty/query/plumbing.rs:383
             at librustc/ty/query/plumbing.rs:629
             at librustc/ty/query/plumbing.rs:640
  37: <rustc::traits::project::AssociatedTypeNormalizer<'a, 'b, 'gcx, 'tcx> as rustc::ty::fold::TypeFolder<'gcx, 'tcx>>::fold_const
             at librustc/ty/query/plumbing.rs:888
             at librustc/ty/query/plumbing.rs:881
             at librustc/traits/project.rs:451
  38: rustc::ty::structural_impls::<impl rustc::ty::fold::TypeFoldable<'tcx> for &'tcx rustc::ty::TyS<'tcx>>::super_fold_with
             at librustc/ty/structural_impls.rs:1186
             at librustc/ty/structural_impls.rs:855
  39: <rustc::traits::project::AssociatedTypeNormalizer<'a, 'b, 'gcx, 'tcx> as rustc::ty::fold::TypeFolder<'gcx, 'tcx>>::fold_ty
             at librustc/traits/project.rs:367
  40: rustc::ty::structural_impls::<impl rustc::ty::fold::TypeFoldable<'tcx> for &'tcx rustc::ty::TyS<'tcx>>::super_fold_with
             at librustc/ty/structural_impls.rs:894
             at librustc/ty/structural_impls.rs:866
  41: <rustc::traits::project::AssociatedTypeNormalizer<'a, 'b, 'gcx, 'tcx> as rustc::ty::fold::TypeFolder<'gcx, 'tcx>>::fold_ty
             at librustc/traits/project.rs:367
  42: <smallvec::SmallVec<A> as core::iter::traits::FromIterator<<A as smallvec::Array>::Item>>::from_iter
             at librustc/ty/structural_impls.rs:894
             at librustc/ty/subst.rs:146
             at librustc/ty/fold.rs:58
             at librustc/ty/subst.rs:310
             at /home/r/src/rust/rustc.2/src/libcore/ops/function.rs:286
             at /home/r/src/rust/rustc.2/src/libcore/option.rs:424
             at /home/r/src/rust/rustc.2/src/libcore/iter/mod.rs:1394
             at /home/r/.cargo/registry/src/github.com-1ecc6299db9ec823/smallvec-0.6.5/lib.rs:1238
             at /home/r/.cargo/registry/src/github.com-1ecc6299db9ec823/smallvec-0.6.5/lib.rs:1222
  43: rustc::ty::fold::TypeFoldable::fold_with
             at /home/r/src/rust/rustc.2/src/libcore/iter/iterator.rs:1415
             at librustc/ty/subst.rs:310
             at librustc/ty/fold.rs:58
  44: rustc::traits::project::normalize_with_depth
             at librustc/macros.rs:327
             at librustc/ty/fold.rs:58
             at librustc/traits/project.rs:345
             at librustc/traits/project.rs:304
  45: rustc::traits::select::SelectionContext::match_impl
             at librustc/traits/select.rs:3504
  46: rustc::infer::InferCtxt::probe
             at librustc/traits/select.rs:1981
             at librustc/traits/select.rs:556
             at librustc/infer/mod.rs:854
  47: rustc::ty::trait_def::<impl rustc::ty::context::TyCtxt<'a, 'gcx, 'tcx>>::for_each_relevant_impl
             at librustc/traits/select.rs:556
             at librustc/traits/select.rs:1980
             at librustc/ty/trait_def.rs:137
  48: rustc::traits::select::SelectionContext::assemble_candidates_from_impls
             at librustc/traits/select.rs:1976
  49: rustc::traits::select::SelectionContext::assemble_candidates
             at librustc/traits/select.rs:1636
  50: rustc::traits::select::SelectionContext::candidate_from_obligation_no_cache
             at librustc/traits/select.rs:1326
RalfJ (Oct 17 2018 at 11:17, on Zulip):

that kind of makes sense... starting at https://github.com/rust-lang/rust/blob/9d7f0da367bae7587ed0ef69bd4384392099fc9e/src/librustc/util/ppaux.rs#L571 we walk up 2 levels through https://github.com/rust-lang/rust/blob/9d7f0da367bae7587ed0ef69bd4384392099fc9e/src/librustc/util/ppaux.rs#L264, and then we are at the vec module

Jake Goulding (Oct 17 2018 at 13:22, on Zulip):

Changing the levels by their modules is too large grained

Can't you make up your own "modules" for logging?

Jake Goulding (Oct 17 2018 at 13:23, on Zulip):
debug!(target: "statements", "New position: x: {}, y: {}", pos.x, pos.y);
oli (Oct 17 2018 at 13:29, on Zulip):

huh?

oli (Oct 17 2018 at 13:29, on Zulip):

I didn't know that

nikomatsakis (Oct 17 2018 at 13:34, on Zulip):

ooh, neat, I also did not know that

RalfJ (Oct 17 2018 at 13:40, on Zulip):

@Jake Goulding is that then scoped inside the module, or is this the full target name?

Jake Goulding (Oct 17 2018 at 13:42, on Zulip):

IIRC it's the full name, but I'm not 100% sure

Jake Goulding (Oct 17 2018 at 13:43, on Zulip):

This is in the 3rd paragraph of the docs, y'all :wink:

A log request consists of a target, a level, and a body. A target is a string which defaults to the module path of the location of the log request, though that default may be overridden. Logger implementations typically use the target to filter requests based on some user configuration.

RalfJ (Oct 17 2018 at 13:47, on Zulip):

@Jake Goulding I cant use this excuse any more, but for a long while I didnt have any idea which crate these macros are even coming from^^

RalfJ (Oct 17 2018 at 13:47, on Zulip):

it's not like that's clear, when you just look at some rustc code

Jake Goulding (Oct 17 2018 at 13:50, on Zulip):

I guess that's a subtle benefit of making macros imported like the rest of the code, should be easier to track!

nikomatsakis (Oct 17 2018 at 13:51, on Zulip):

who reads docs

nikomatsakis (Oct 17 2018 at 13:52, on Zulip):

yeah, I've been enjoying the new "friendly absolute paths" so much, and I now find I always write log::debug!(..)

nikomatsakis (Oct 17 2018 at 13:52, on Zulip):

what I really want are "indentation levels" -- does "stock log" support those yet?

nikomatsakis (Oct 17 2018 at 13:52, on Zulip):

I was looking at slog recently

nikomatsakis (Oct 17 2018 at 13:52, on Zulip):

it..might be nice? I can't 100% tell. I like the idea of structured data

Jake Goulding (Oct 17 2018 at 13:52, on Zulip):

My usual excuse is "I've been using X crate from before they had docs", that earns extra street cred.

Jake Goulding (Oct 17 2018 at 13:54, on Zulip):

Structured logs are wonderful, especially when you have multiple threads and a big system (I used it to debug some concurrency issues in a Rails app recently).

The big problem is that you really want a tool to help view them in the most effective manner.

RalfJ (Oct 17 2018 at 13:54, on Zulip):

funny that you say that, miri actually has some code to increase and decrease indentation levels when stack frames come and go, but I think it doesnt do anything any more since the move into rustc

RalfJ (Oct 17 2018 at 13:55, on Zulip):

and it was useless before, because the indentation was after the variable-length module names, so it wasnt actually visible on the screen

Jake Goulding (Oct 17 2018 at 13:55, on Zulip):

e.g. I want less to have a button for "show all log lines from the same thread the cursor is on"

nikomatsakis (Oct 17 2018 at 13:57, on Zulip):

My usual excuse is "I've been using X crate from before they had docs", that earns extra street cred.

I think in this case "I've been using debug! since it was a keyword" would apply

nikomatsakis (Oct 17 2018 at 13:57, on Zulip):

oh btw I just discovered the most amazing thing

nikomatsakis (Oct 17 2018 at 13:57, on Zulip):

I've yet to use it though :)

nikomatsakis (Oct 17 2018 at 13:57, on Zulip):

if you run rr replay -a -M then every stdout/err output line is stamped with a tid and an rr event number; then you can do rr replay -g to jump to that event number

nikomatsakis (Oct 17 2018 at 13:57, on Zulip):

I've been dying to try this to get a "stamped log"

nikomatsakis (Oct 17 2018 at 13:58, on Zulip):

although debugging the compiler is .. iffy

oli (Oct 17 2018 at 14:46, on Zulip):

I wrote the log_settings crate for logging with indentation levels

oli (Oct 17 2018 at 14:47, on Zulip):

works together with the regular log crate without any effort in crates that don't want/need/know about it

RalfJ (Oct 17 2018 at 14:59, on Zulip):

oh, I had no idea it was an add-on crate^^

RalfJ (Oct 17 2018 at 15:00, on Zulip):

@Oli any thoughts on the backtrace at https://rust-lang.zulipchat.com/#narrow/stream/146212-t-compiler.2Fconst-eval/subject/miri-debug-output/near/135964824 ?

oli (Oct 17 2018 at 15:09, on Zulip):

Yea, that code is super weird. There's a condition basically saying "if you have a printable name, use that, else recurse to the parent" https://github.com/rust-lang/rust/blob/1dceaddfbe163e2d916c904b98923342730ba970/src/librustc/util/ppaux.rs#L258

RalfJ (Oct 17 2018 at 15:09, on Zulip):

yes

RalfJ (Oct 17 2018 at 15:09, on Zulip):

no idea why that makes sense

RalfJ (Oct 17 2018 at 15:09, on Zulip):

but in case of constants it seemingly doesnt^^

oli (Oct 17 2018 at 15:10, on Zulip):

maybe it's an associated constant?

RalfJ (Oct 17 2018 at 15:12, on Zulip):

well, its value seems to be 25

RalfJ (Oct 17 2018 at 15:13, on Zulip):

can't see any 25 in that module though...

RalfJ (Oct 17 2018 at 15:14, on Zulip):

unless it's the array_impls!

RalfJ (Oct 17 2018 at 15:16, on Zulip):

there are a lot of these constants being computed

RalfJ (Oct 17 2018 at 15:16, on Zulip):

not sure why that only happens when the vec! macro is used though?

RalfJ (Oct 17 2018 at 15:19, on Zulip):

yeah, there are 66 constants like this

RalfJ (Oct 17 2018 at 15:19, on Zulip):

that matches the impls for sizes 0..=32, 2 impls for each size

RalfJ (Oct 17 2018 at 15:20, on Zulip):

so @Oli it's not an assoc const, it's... an array length?

oli (Oct 17 2018 at 15:21, on Zulip):

O_o well... that's probably it. Noone ever tried to print the path of an array length...

oli (Oct 17 2018 at 15:22, on Zulip):

Since they have no name, they go into the None arm, which is wrong

oli (Oct 17 2018 at 15:22, on Zulip):

we should invent a name like LEN for it

RalfJ (Oct 17 2018 at 15:22, on Zulip):

where would that happen?

oli (Oct 17 2018 at 15:24, on Zulip):

I'd assume in get_opt_name

oli (Oct 17 2018 at 15:24, on Zulip):

but I haven't checked

RalfJ (Oct 17 2018 at 15:29, on Zulip):

I guess that would be AnonConst

RalfJ (Oct 17 2018 at 15:30, on Zulip):

but not all AnonConst might be array lengths?

nikomatsakis (Oct 17 2018 at 15:30, on Zulip):

I wrote the log_settings crate for logging with indentation levels

nice, I will take a look

Last update: Nov 15 2019 at 21:00UTC