Stream: t-compiler/major changes

Topic: Use `tracing` instead of `log` compiler-team#331


nagisa (Jul 11 2020 at 11:46, on Zulip):

tracing is great. Recently we ported the code-base at my $DAYJOB and being able to just register a new subscriber such as tracing-tracy to quickly expose the codebase to a full blown profiling tool has proved to be super helpful. I don’t think there exists yet a subscriber that outputs traces in e.g. a format that measureme or chromium devtools/firefox profiler understand, but that's something that will inevitably happen.

That said, once we have some experience with tracing I suspect that we might want to port various ways to produce trace data (-Zself-profile) to tracing as well.

nagisa (Jul 11 2020 at 11:46, on Zulip):

@rustbot thirded ^^

simulacrum (Jul 11 2020 at 14:35, on Zulip):

Do we have a plan for which subscriber to use? Cc @oli

Step 2 looks like a lot of work too - maybe we don't need to make that replacement immediately and can do it as needed/wanted? It's not clear to me when a value is preferred over inclusion in the format string explicitly

Tshepang Lekhonkhobe (Jul 11 2020 at 16:26, on Zulip):

how this issue is presented seems to suggest there was a discussion about this, because it does not say why tracing should be adopted

Jack Huey (Jul 11 2020 at 17:30, on Zulip):

There has been some discussion, most recently https://rust-lang.zulipchat.com/#narrow/stream/146212-t-compiler.2Fconst-eval/topic/anon_const_instance_printing/near/203584713 but also over in wg-traits at https://rust-lang.zulipchat.com/#narrow/stream/144729-wg-traits/topic/tracing-tree/near/203605486 and https://rust-lang.zulipchat.com/#narrow/stream/144729-wg-traits/topic/tracing.20in.20chalk/near/192424178 (a bit older)

Jack Huey (Jul 11 2020 at 17:31, on Zulip):

To summarize the general idea of it:

Jack Huey (Jul 11 2020 at 17:31, on Zulip):

Tracing offers a lot of support for being able to capture hierarchical data

Jack Huey (Jul 11 2020 at 17:32, on Zulip):

In Chalk, this is super helpful if we consider that we trying recursively try to solve goals

Jack Huey (Jul 11 2020 at 17:32, on Zulip):

In rustc, this kind of patterns comes up a lot too

Jack Huey (Jul 11 2020 at 17:35, on Zulip):

But as @nagisa said, tracing also offers a lot in terms of the subscribers that you can use

nagisa (Jul 11 2020 at 19:49, on Zulip):

One benefit of tracing is that with some subscribers you get an ability to combine events (e.g. log messages) and spans in a single unified infrastructure. I don’t know if measureme currently drains the log messages as events for exposition in those same chrome devtools, but its definitely something that I would find super useful if I ever needed to spelunk logs.

oli (Jul 12 2020 at 09:51, on Zulip):

simulacrum said:

Do we have a plan for which subscriber to use? Cc oli

Hmm... I was just gonna use the official tracing_subscriber::fmt::Subscriber with the env filter, which gives us the existing behaviour. Then we can fine tune it. Likely once we start using spans, we'll need to figure out something better, because otherwise each log message becomes very long

Step 2 looks like a lot of work too - maybe we don't need to make that replacement immediately and can do it as needed/wanted? It's not clear to me when a value is preferred over inclusion in the format string explicitly

simulacrum (Jul 12 2020 at 15:35, on Zulip):

hmm

simulacrum (Jul 12 2020 at 15:36, on Zulip):

I'm still not quite sold on the value printing, to be honest -- it seems useful in theory, I guess, but I don't know that I'd want to rewrite existing code to use it (vs. doing so when we actually have use cases)

simulacrum (Jul 12 2020 at 15:38, on Zulip):

to take a concrete example that I just randomly found, for https://github.com/rust-lang/rust/blob/e59b08e62ea691916d2f063cac5aab4634128022/src/librustc_parse/lexer/mod.rs#L125 -- it seems like it's not obvious that we want to pull those values out separately, because it makes reading the log possibly harder

oli (Jul 12 2020 at 16:37, on Zulip):

yea, that case doesn't look like a case we should change mechanically

oli (Jul 12 2020 at 16:39, on Zulip):

this is a case I would change though

simulacrum (Jul 12 2020 at 16:46, on Zulip):

hm okay -- maybe it makes sense to say a bit more about that in the proposal? I do think we might want something like a proc macro which to start would do the standard function and args logging and eventually maybe span-ify the function call

Jake Goulding (Jul 12 2020 at 17:49, on Zulip):

That sounds awfully like the #[instrument] macro, if I understand you correctly

simulacrum (Jul 12 2020 at 17:53, on Zulip):

hm, yes, that looks pretty close

simulacrum (Jul 12 2020 at 17:53, on Zulip):

not sure if it gets 100% of the way there

Jake Goulding (Jul 12 2020 at 17:59, on Zulip):

I know that tracing folk have said that they'd like to have better knobs for what instrument does/how it does it. For example, it doesn't work great for the playground's HTTP endpoints because I don't want to log the user's code but I do want to log every other parameter

eddyb (Jul 13 2020 at 01:26, on Zulip):

@nagisa for -Z self-profile we probably would want to integrate tracing in rustc_data_structures::profiling (which probably should just be rustc_self_profiling or something), and have that integration completely bypassed when using -Z self-profile without tracing

eddyb (Jul 13 2020 at 01:26, on Zulip):

that's because I expect logging (especially string formatting) to have an order of magnitude (or worse) overhead compared to measureme, and it would impact measurements

nagisa (Jul 13 2020 at 01:27, on Zulip):

well yeah, it can be something on top

nagisa (Jul 13 2020 at 01:27, on Zulip):

FWIW I did start https://github.com/rust-lang/measureme/pull/120 though I didn’t benchmark it yet.

eddyb (Jul 13 2020 at 01:27, on Zulip):

we already wrap the measureme API to handle a basic filtering function and whatnot so I think that's the best place to integrate it

eddyb (Jul 13 2020 at 01:28, on Zulip):

@nagisa hmm maybe I should hurry with my rdpmc integration, so we can actually measure that properly :P

eddyb (Jul 13 2020 at 01:28, on Zulip):

measureme is sadly too noisy atm due to using time, which as we all know, is a comfortable lie and nothing more,

nagisa (Jul 13 2020 at 01:28, on Zulip):

ability to integrate the queries that we measure with random #[instrument] spans elsewhere in the codebase would be cool.

eddyb (Jul 13 2020 at 01:29, on Zulip):

I definitely want tracing for getting a very in-depth view of what the compiler does and I'm willing to pay some extra cost for it, but maybe we can do stuff like sampling rdpmc before and after doing string formatting, to subtract that cost

eddyb (Jul 13 2020 at 01:30, on Zulip):

if we can have our cake and measure it too, that'd be really useful

nagisa (Jul 13 2020 at 01:30, on Zulip):

I think its plausible to avoid formatting at the tracing layer entirely (provided we don’t register the stdout/logging subscriber at all unless asked)

eddyb (Jul 13 2020 at 01:30, on Zulip):

completely unrelatedly, I ran cargo rustc -- -C llvm-args=-print-after-all on a crate that takes 14 seconds to compile in non-incremental release mode

eddyb (Jul 13 2020 at 01:32, on Zulip):

and it took almost 4 hours, producing a 17 GB file, with just over 200 million lines in it

eddyb (Jul 13 2020 at 01:32, on Zulip):

(although it's possible -Z no-parallel-llvm, which you need for coherent output, was part of the slowdown)

nagisa (Jul 13 2020 at 01:32, on Zulip):

wow.

eddyb (Jul 13 2020 at 01:33, on Zulip):

the worst part is that the thing I wanted to find in there wasn't even clearly visible (there were two many differences other than the one I was looking for - yeah, I ran 2 builds of 4h each)

eddyb (Jul 13 2020 at 01:33, on Zulip):

but it was only as an experiment / out of curiosity, having already found what I needed by modifying the source to only codegen one function (and its transitive callees)

eddyb (Jul 13 2020 at 01:34, on Zulip):

anyway, all in all, I'm excited for our traceable future :D

eddyb (Jul 13 2020 at 01:34, on Zulip):

oh and maybe we can start replacing boring debug! calls with #[instrument]

David Barsky (Jul 13 2020 at 15:25, on Zulip):

I guess we should prioritize making the breaking change to #[instrument] where you need to _opt-in_ what parameters you want recorded, as opposed to opting out. i'll see how quickly we can get that supported and landed.

Nathan Whitaker (Jul 13 2020 at 16:51, on Zulip):

@David Barsky Perhaps instead of making a breaking change there could be another keyword similar to skip, something like #[instrument(only(a, b)] to only record the listed parameters.

David Barsky (Jul 13 2020 at 16:57, on Zulip):

Can you cut a ticket/suggestion about this on https://github.com/tokio-rs/tracing/issues? it'd help us track that/prioritize it

David Barsky (Jul 13 2020 at 16:58, on Zulip):

(i'm sorry, i've got to run to a work meeting now)

triagebot (Jul 22 2020 at 15:38, on Zulip):

This proposal has been accepted: #331.

Last update: May 07 2021 at 07:30UTC