Stream: wg-traits

Topic: tracing in chalk


David Barsky (Dec 31 2019 at 00:14, on Zulip):

tracing, as I've been pitching to @nikomatsakis:

David Barsky (Dec 31 2019 at 00:15, on Zulip):

here are some neat libraries atop of tracing, for what it's worth:

David Barsky (Dec 31 2019 at 00:20, on Zulip):

now that i've pitched the benefits, feel free to explain your needs and i can tell you what's ready and what need a bit of work :)

matklad (Dec 31 2019 at 00:23, on Zulip):

@David Barsky would you recommend switching rust-analyzer's hierarchical profiling from a hand-written thing to tracing? The metrics I am interested most is the amount of code I need to maintain and compile times.

Jack Huey (Dec 31 2019 at 02:28, on Zulip):

So right now, chalk doesn't make use of log I don't think. Instead it uses the debug, debug_heading, info, and info_heading macros in chalk-macros (I think)

Jack Huey (Dec 31 2019 at 02:29, on Zulip):

@David Barsky It would be super awesome if you sent a PR introducing tracing. From what I can tell, that would be immediately helpful when looking at performance with tracing-timing, right?

David Barsky (Dec 31 2019 at 02:45, on Zulip):

@matklad if it’s _just_ the hierarchal profiling, _maybe_ not. if you’d like to start to replace other instrumentation systems, like logging or whatever, then i’m inclined to say yes. I’ve found tracing-like systems as a great way to onboard new engineers and debug complex systems at work, and that could be handy for rust-analyzer.

David Barsky (Dec 31 2019 at 02:47, on Zulip):

@Jack Huey gotcha, those macros look decently similar to log’s, i think. i think tracing could be used to replace those, but in terms of global performance overviews, you’ll need to instrument with the spans to note units of work. the #[instrument] macro helps.

David Barsky (Dec 31 2019 at 02:47, on Zulip):

i’m also on vacation so i’ll be a bit slow to respond, i’m sorry.

Jack Huey (Dec 31 2019 at 03:59, on Zulip):

Really, the existing macros essentially just output with eprintln and also manage indentation too

Jack Huey (Dec 31 2019 at 04:00, on Zulip):

Haven't really looked at tracing much, only briefly. So really don't know how perf overviews could be checked

Jack Huey (Dec 31 2019 at 04:00, on Zulip):

Also on vacation, so I understand :)

David Barsky (Dec 31 2019 at 04:23, on Zulip):

perf-related views would really be a thing once tracing has a sufficiently comprehensive view of a program’s execution graph, which is comes much more quickly than you’d expect.

David Barsky (Dec 31 2019 at 04:27, on Zulip):

you can think of spans as nodes in graph, but it’s up to you to you demarcate the different nodes. we’re trying to reduce the amount of effort needed to mark different sections. it’s less than say, metrics libraries, but more than what some folks might be used to.

David Barsky (Dec 31 2019 at 04:33, on Zulip):

for what it’s worth @matklad, i wanted something like the profiling tools you have in ra_prof to live in tracing (would be super handy for debugging/profiling services) but never got around it to writing that integration. too little time.

the main win of having something like ra_prof in tracing is that existing annotations can be reused for the the style of profiling you have. not sure compile times would really decrease, but they won’t increase, and you might end up owning less code.

David Barsky (Dec 31 2019 at 05:16, on Zulip):

anyways, i’ll dump the last few thoughts: if you need an incremental, graph-based instrumentation system, tracing’s a great fit. it’s great for debugging and understanding complex systems. if your current approach to instrumentation and debugging works well enough, tracing will still be there when you do start to need it. that being said, the benefits of tracing-like systems are surprisingly large, even early on & when it might feel like overkill. i think it might be a formalization of what’s currently in chalk and ra_prof, but i can’t say if the formalization is right for you now.

i’ll post a screenshot of the sort of data it can collect after i sleep (8-9 hours from now).

David Barsky (Dec 31 2019 at 16:43, on Zulip):

phew, last one for now: here's _one_ tracing output for the example in: https://github.com/tokio-rs/tracing/pull/496/ Screen-Shot-2019-12-31-at-11.40.20-AM.png.

David Barsky (Jan 07 2020 at 01:32, on Zulip):

Screen-Shot-2020-01-06-at-8.29.42-PM.png a formatter that attempts to mimic ra-prof, but is also inspired by what tracing already has + slog

Jack Huey (Jan 08 2020 at 18:54, on Zulip):

Are these times the diff between current event and last? Or current event and last event or span?

David Barsky (Jan 08 2020 at 20:55, on Zulip):

@Jack Huey these times are the difference between the current event and the last event/span, whichever was the last one.

David Barsky (Jan 08 2020 at 20:58, on Zulip):

so the top-level span ("server") doesn't have an attached elapsed timer, because it lives for the lifetime of the program

Jack Huey (Jan 08 2020 at 21:06, on Zulip):

so the 8.8.8.8 messaged received elapsed is to the beginning of the conn span, not to the previous disconnect?

David Barsky (Jan 08 2020 at 21:21, on Zulip):

yes, the beginning of the conn span

David Barsky (Jan 08 2020 at 21:21, on Zulip):

that can change easily

David Barsky (Jan 08 2020 at 21:28, on Zulip):

to be entirely honest, I'm not entirely sure how the "elapsed" time should be counted

Jack Huey (Jan 08 2020 at 21:31, on Zulip):

I would say beginning of the span

David Barsky (Jan 08 2020 at 22:02, on Zulip):

so the current behavior?

Jack Huey (Jan 08 2020 at 23:04, on Zulip):

Yea, current behavior seems most correct

David Barsky (Feb 02 2020 at 21:59, on Zulip):

Screen-Shot-2020-02-02-at-4.57.19-PM.png

alright, so I said this would be done at some point, and now it is: https://github.com/davidbarsky/tracing-tree/

Laurențiu Nicola (Feb 03 2020 at 10:03, on Zulip):

This is not a feature request, but have you thought about the Chromium profiler as a target format? E.g. https://github.com/rust-lang/measureme/blob/master/crox/Readme.md

David Barsky (Feb 03 2020 at 14:27, on Zulip):

I have! I mostly haven’t had the time—it’s a matter of prioritization. looking at https://github.com/rust-lang/measureme/blob/master/crox/src/main.rs; it does seem to be too bad?

David Barsky (Feb 03 2020 at 16:44, on Zulip):

This is a somewhat uniformed question, but does Chrome's profiler or Firefox's profile support streaming in trace data, or can it only view a static file?

David Barsky (Feb 03 2020 at 16:47, on Zulip):

Excuse me: Chrome profiler support doesn't seem to be too difficult to add/support atop of `tracing.

Laurențiu Nicola (Feb 03 2020 at 20:28, on Zulip):

This is a somewhat uniformed question, but does Chrome's profiler or Firefox's profile support streaming in trace data, or can it only view a static file?

Only files AFAIK

David Barsky (Feb 03 2020 at 21:41, on Zulip):

gotcha, thanks

David Barsky (Feb 07 2020 at 22:38, on Zulip):

looked a bit at strands in chalk-engine (cc: @Jack Huey). I think if I were place tracing _anywhere_ in chalk, it'd be in here, alongside the timestamp: https://github.com/rust-lang/chalk/blob/master/chalk-engine/src/strand.rs#L13. it'd be a bit similar to how tracing-futures work, minus the feature flags and annotations: https://github.com/tokio-rs/tracing/blob/master/tracing-futures/src/lib.rs#L223-L230

David Barsky (Feb 07 2020 at 22:39, on Zulip):

I the "entry" of the span (for tracking work) could occur at strand activation here: https://github.com/rust-lang/chalk/blob/master/chalk-engine/src/table.rs#L83

David Barsky (Feb 07 2020 at 22:40, on Zulip):

at least some closure would happen here: https://github.com/rust-lang/chalk/blob/master/chalk-engine/src/table.rs#L120

David Barsky (Feb 07 2020 at 22:44, on Zulip):

Chalk engine is also more approachable than I thought! Kudos to whoever wrote the docs.

Jack Huey (Feb 07 2020 at 23:03, on Zulip):

I think that mostly sounds good to me

Jack Huey (Feb 07 2020 at 23:04, on Zulip):

I think I would be the entry for a span here: https://github.com/rust-lang/chalk/blob/af48f302a1f571b3ca418f7c5aa639a144a34f75/chalk-engine/src/logic.rs#L173

Jack Huey (Feb 07 2020 at 23:04, on Zulip):

But also curious what your thoughts are on have a Table having a span

Jack Huey (Feb 07 2020 at 23:05, on Zulip):

(in addition to Strand)

Jack Huey (Feb 07 2020 at 23:08, on Zulip):

Chalk engine is also more approachable than I thought! Kudos to whoever wrote the docs.

The docs indeed have been quite solid, even since I first started with chalk. When I refactored to make it iterative, I made it a point to even more thoroughly document it. So I'm glad you found them helpful

David Barsky (Feb 07 2020 at 23:10, on Zulip):

I think table can have a span, there's a pattern where we have a "server" span in asynchronous servers

David Barsky (Feb 07 2020 at 23:11, on Zulip):

yeah, I think that's a good spot to put span entry.

David Barsky (Feb 07 2020 at 23:12, on Zulip):

now, if I wanted to _run_ chalk engine and emit this data, what would the best way to do that be?

David Barsky (Feb 07 2020 at 23:14, on Zulip):

lemme look, actually. i think some sort of tests would be a good start.

David Barsky (Feb 07 2020 at 23:20, on Zulip):

yeah, i think i can do something in the test! macro

Jack Huey (Feb 08 2020 at 00:11, on Zulip):

yeah, i think i can do something in the test! macro

Yeah, either the test! macro or the chalk REPL would be good places to start looking at how to run

Jack Huey (Feb 08 2020 at 00:11, on Zulip):

(probably test)

Jack Huey (Feb 27 2020 at 03:30, on Zulip):

@David Barsky are you still planning/working on this? If so, would you consider it "part of the current sprint"? If not, that's cool too; just wondering because I created an issue

Jack Huey (Feb 27 2020 at 03:31, on Zulip):

https://github.com/rust-lang/chalk/issues/337

David Barsky (Feb 27 2020 at 15:09, on Zulip):

@Jack Huey I'd be happy to work on it, but if someone gets there first, they should do so.

David Barsky (Feb 27 2020 at 15:09, on Zulip):

let's say that it is part of the current sprint—i'll let you know soon (next week) if it won't be.

Jack Huey (Feb 27 2020 at 15:10, on Zulip):

Ok, I'll mark it

nikomatsakis (Mar 06 2020 at 16:19, on Zulip):

is someone actively working on this?

nikomatsakis (Mar 06 2020 at 16:19, on Zulip):

I'm adding it to the roadmap

nikomatsakis (Mar 06 2020 at 16:19, on Zulip):

under a heading like "improve debugability of chalk"

Jane Lusby (Mar 06 2020 at 16:20, on Zulip):

I can go ping David

Jane Lusby (Mar 06 2020 at 16:20, on Zulip):

Also if he doesn't get around to it I can do it ( also contributor to tracing)

nikomatsakis (Mar 06 2020 at 16:20, on Zulip):

I think @David Barsky monitors Zulip too

Jane Lusby (Mar 06 2020 at 16:21, on Zulip):

Ack

Jack Huey (Mar 06 2020 at 16:22, on Zulip):

David said he is working on it for the sprint

nikomatsakis (Mar 06 2020 at 16:22, on Zulip):

can we assign him to the issue?

nikomatsakis (Mar 06 2020 at 16:23, on Zulip):

I wonder if rustbot is monitoring wg-traits, maybe @Pietro Albini or @simulacrum knows

simulacrum (Mar 06 2020 at 16:23, on Zulip):

rustbot monitors all of rust-lang org, but may need to be enabled

simulacrum (Mar 06 2020 at 16:24, on Zulip):

i.e. add the triagebot.toml to the repository and enable specific features

Jack Huey (Mar 06 2020 at 16:24, on Zulip):

That would be useful

simulacrum (Mar 06 2020 at 16:25, on Zulip):

See the wiki on the triagebot repo

David Barsky (Mar 06 2020 at 16:30, on Zulip):

yeah, i’m working on it. add it to the sprint; been handling a bit of paperwork this week.

David Barsky (Mar 14 2020 at 22:52, on Zulip):

Screen-Shot-2020-03-14-at-6.51.45-PM.png started noodling around by introducing tracing into chalk. no clue if this information is all useless!

David Barsky (Mar 14 2020 at 22:53, on Zulip):

leaning towards saying yes :)

Jack Huey (Mar 16 2020 at 16:38, on Zulip):

I don't think that's useless :)

Jane Lusby (Mar 24 2020 at 21:05, on Zulip):
    debug_heading!(
        "program_clauses_for_goal(goal={:?}, environment={:?})",
        goal,
        environment
    );
Jane Lusby (Mar 24 2020 at 21:05, on Zulip):

wondering if these should be replaced with something like

Jane Lusby (Mar 24 2020 at 21:05, on Zulip):

#[instrument(skip(db))]

Jane Lusby (Mar 24 2020 at 21:06, on Zulip):

this looks like a locally scoped tracing span

Jack Huey (Mar 24 2020 at 21:06, on Zulip):

Yeah, I think anywhere there is a debug, debug_heading, info, or info_heading, those should be replaced with tracing, to start

Jack Huey (Mar 24 2020 at 21:06, on Zulip):

and we can get that infra landed

Jack Huey (Mar 24 2020 at 21:07, on Zulip):

then, we can work on fine tuning what more/less needs to be added/removed

Jane Lusby (Mar 24 2020 at 21:07, on Zulip):

_nod_

Jane Lusby (Mar 24 2020 at 21:07, on Zulip):

the main difference with spans is that it will apply to all events logged within that span's scope

Jane Lusby (Mar 24 2020 at 21:07, on Zulip):

so this debug_heading only applys to the log in the function

Jack Huey (Mar 24 2020 at 21:08, on Zulip):

well, sort of

Jane Lusby (Mar 24 2020 at 21:08, on Zulip):

but if we turned it into a span it would be prepended on every event in every function that that function calls and so on

Jack Huey (Mar 24 2020 at 21:08, on Zulip):

debug_heading "indents" the logging within a function

Jane Lusby (Mar 24 2020 at 21:08, on Zulip):

but you can have levels on spans so it would only show up if that log level is enabled

Jack Huey (Mar 24 2020 at 21:08, on Zulip):

so, function calls are also indented

Jane Lusby (Mar 24 2020 at 21:08, on Zulip):

oh interesting

Jane Lusby (Mar 24 2020 at 21:09, on Zulip):

ooh it does apply to subfunction calls

Jane Lusby (Mar 24 2020 at 21:09, on Zulip):

okay so cool its the same thing

Jane Lusby (Mar 24 2020 at 21:09, on Zulip):

i tihnk theres a logger for tracing that indents events inside of spans

Jane Lusby (Mar 24 2020 at 21:09, on Zulip):

so we should be able to preserve that functionality as well

Jane Lusby (Mar 24 2020 at 21:09, on Zulip):

yea this seems like it will translate nicely

Jane Lusby (Mar 24 2020 at 21:09, on Zulip):

coool

Jack Huey (Mar 24 2020 at 21:10, on Zulip):

yeah, it translates well as is

Jack Huey (Mar 24 2020 at 21:10, on Zulip):

but what we don't have currently is a way to only "cover" parts of the function

Jack Huey (Mar 24 2020 at 21:11, on Zulip):

(so like, a Strand being active)

nikomatsakis (Mar 24 2020 at 21:12, on Zulip):

we can always extract sub-functions potentially

nikomatsakis (Mar 24 2020 at 21:12, on Zulip):

it woudl be so great, @Jane Lusby, to have some procedural macro support so that it automatically "dumps" the arguments

Jane Lusby (Mar 24 2020 at 21:12, on Zulip):

i dont think thats necessary

Jane Lusby (Mar 24 2020 at 21:13, on Zulip):

yea tracing::instrument does that

Jane Lusby (Mar 24 2020 at 21:13, on Zulip):

it creates a span for the given function and uses every arg as a field in the span it generates

Jane Lusby (Mar 24 2020 at 21:13, on Zulip):

chalk doesnt use async right?

Jack Huey (Mar 24 2020 at 21:14, on Zulip):

no

Jane Lusby (Mar 24 2020 at 21:14, on Zulip):

k cool cool

Jane Lusby (Mar 24 2020 at 21:16, on Zulip):

re tracing in chalk + chalk perf I'm currently working on a tracing layer for generating flamegraphs from spans and I'd love to play with it + chalk

Jack Huey (Mar 24 2020 at 21:16, on Zulip):

that would be fantastic

Jack Huey (Mar 27 2020 at 19:01, on Zulip):

@David Barsky thinking about adding your tracing screenshot into the sprint blog post. Would you be opposed? Still not sure yet, but a little visual flair might not be terrible

David Barsky (Mar 27 2020 at 19:17, on Zulip):

not opposed!

David Barsky (Mar 27 2020 at 19:17, on Zulip):

go for it, @Jack Huey. I can also push my very WIP branch

Jack Huey (Mar 27 2020 at 19:18, on Zulip):

Please do :) Would love to work towards getting an initial PR in

Jane Lusby (Mar 27 2020 at 19:22, on Zulip):

so here's a question

David Barsky (Mar 27 2020 at 19:22, on Zulip):

yup

Jane Lusby (Mar 27 2020 at 19:22, on Zulip):

if tracing becomes normalized in chalk and chalk is getting integrated with rustc

Jane Lusby (Mar 27 2020 at 19:22, on Zulip):

does that mean tracing is on the table for rustc?

David Barsky (Mar 27 2020 at 19:23, on Zulip):

it might be, yes

nikomatsakis (Mar 27 2020 at 19:33, on Zulip):

I would personally like to see tracing used in rustc -- but it'd be good to tinker with it first in chalk

nikomatsakis (Mar 27 2020 at 19:34, on Zulip):

where is the branch again? there's an open PR?

Jack Huey (Mar 27 2020 at 19:38, on Zulip):

No open PR yet, @David Barsky said he's going to

David Barsky (Mar 27 2020 at 19:38, on Zulip):

just gotta finish a doc, but I can push something _very_ wip rn

David Barsky (Mar 27 2020 at 19:38, on Zulip):

hold on

David Barsky (Mar 27 2020 at 19:55, on Zulip):

https://github.com/rust-lang/chalk/pull/362

Jack Huey (Mar 27 2020 at 19:56, on Zulip):

awesome

eddyb (Mar 31 2020 at 05:32, on Zulip):

nikomatsakis said:

I would personally like to see tracing used in rustc -- but it'd be good to tinker with it first in chalk

it's a drop-in replacement for log so we should just do it IMO

eddyb (Mar 31 2020 at 05:34, on Zulip):

but also last I checked tracing lacked something I consider crucial for it to be useful, on the presentation side: a proper nested view

eddyb (Mar 31 2020 at 05:34, on Zulip):

it would make it so much easier to see log messages nested by calls, and that's what I'd call "tracing"

eddyb (Mar 31 2020 at 05:34, on Zulip):

the context stuff is neat but harder to make use of

eddyb (Mar 31 2020 at 05:35, on Zulip):

especially in recursive parts of the codebase

eddyb (Mar 31 2020 at 05:42, on Zulip):

I had a thing in C++ back in the day, but I'm not sure where it is, maybe it's on my external HDD, let me check

eddyb (Mar 31 2020 at 07:18, on Zulip):

oh heh it was in a gist, I'd just forgotten how to search for it https://gist.github.com/eddyb/e727bcb2af8ffc2a32e6

eddyb (Mar 31 2020 at 07:19, on Zulip):

std::cout << u8"╞>" << sFunc << '(';

eddyb (Mar 31 2020 at 07:21, on Zulip):

I even have an example output in a gist, lol https://gist.githubusercontent.com/eddyb/bd193e8ababd144fb8b9/raw/d27d0a76657c1c7e75e0d9105a4f5f28ce856734/trace.cc

eddyb (Mar 31 2020 at 07:24, on Zulip):

so when I hear "tracing", this is what I expect :P

eddyb (Mar 31 2020 at 13:12, on Zulip):

@nikomatsakis ^^ if you didn't see this

nikomatsakis (Mar 31 2020 at 13:31, on Zulip):

I believe tracing has support for nested views, and that is indeed a major selling point that I was expecting. Perhaps @David Barsky or @Jane Lusby can confirm though. Maybe I misunderstood.

Chalk's logging has a notion of nesting, not sure if you've seen it, @eddyb. It has a debug_heading vs debug (and trace_heading vs trace, for really detailed stuff), which right now just dumps to stderr with some spaces in front per heading. I'm assuming that translating this to tracing would imply some support for nesting but..

eddyb (Mar 31 2020 at 13:32, on Zulip):

s/nothing/nesting?

eddyb (Mar 31 2020 at 13:33, on Zulip):

@nikomatsakis back when I talked to @mycoliza, in October last year, she said this:

[9:45 PM] mycoliza: the tracing_fmt implementation is not really intended for printing every single stack frame to stdout

eddyb (Mar 31 2020 at 13:33, on Zulip):

oh but she also linked https://github.com/tokio-rs/console/

eddyb (Mar 31 2020 at 13:34, on Zulip):

@nikomatsakis I'm afraid the focus on (shallow) "context" is at the detriment of actual call tracing, which is the thing I want

eddyb (Mar 31 2020 at 13:35, on Zulip):

I have no idea where the "tracing = logging with context" association comes from, but also my C++ tracing code from almost a decade ago wasn't based on a pre-existing "tracing" notion, and I haven't seen anything mentioning "tracing" between that and the tracing crate :P

nikomatsakis (Mar 31 2020 at 13:38, on Zulip):

That said, I think another useful thing would be able to assemble not just call tracing but things like "show me all the stuff for DefId X, collected"

eddyb (Mar 31 2020 at 13:38, on Zulip):

@nikomatsakis I think that's actually already possible using tracing

eddyb (Mar 31 2020 at 13:38, on Zulip):

more so than call tracing :P

David Barsky (Mar 31 2020 at 16:56, on Zulip):

@eddyb @nikomatsakis I wrote this nested/with context view a bit ago and I feel comfortable publishing an alpha: https://github.com/davidbarsky/tracing-tree/. Docs can absolutely be improved, though!

eddyb (Mar 31 2020 at 16:57, on Zulip):

YESSS

eddyb (Mar 31 2020 at 16:57, on Zulip):

that looks pretty good

David Barsky (Mar 31 2020 at 16:57, on Zulip):

thanks! :)

eddyb (Mar 31 2020 at 16:58, on Zulip):

doesn't have the unicode noisefest my C++ thing did, idk if that's a plus or a minus, but at least it does what rustc would need

David Barsky (Mar 31 2020 at 16:58, on Zulip):

i'd like to get the unicode box drawing in as an option _at some point_, though

David Barsky (Mar 31 2020 at 16:58, on Zulip):

(see: https://github.com/davidbarsky/tracing-tree/issues/4)

Jane Lusby (Mar 31 2020 at 17:11, on Zulip):

show me all the stuff for DefId X, collected

Jane Lusby (Mar 31 2020 at 17:11, on Zulip):

are you envisioning queries against structured log data?

Jane Lusby (Mar 31 2020 at 17:12, on Zulip):

i think all of this is possible but a lot of it isn't implemented, though right now I dont think theres any notion of filtering the logs that are actually output based on queries against the fields

David Barsky (Mar 31 2020 at 17:12, on Zulip):

My understanding is that this would be closer to filtering on fields

Jane Lusby (Mar 31 2020 at 17:12, on Zulip):

but it shouldn't be too hard to dump structured logs like json or something

Jane Lusby (Mar 31 2020 at 17:13, on Zulip):

and then write a tool that reads them in and implements the filtering then re renders them as human readable formatted logs

Jane Lusby (Mar 31 2020 at 17:13, on Zulip):

its something I've wanted to do for a while tbh

David Barsky (Mar 31 2020 at 17:13, on Zulip):

@Jane Lusby I wrote these docs: https://docs.rs/tracing-subscriber/0.2.3/tracing_subscriber/struct.EnvFilter.html :)

Jane Lusby (Mar 31 2020 at 17:13, on Zulip):

oh shit

Jane Lusby (Mar 31 2020 at 17:13, on Zulip):

we already have field filtering???

David Barsky (Mar 31 2020 at 17:14, on Zulip):

yup

Jane Lusby (Mar 31 2020 at 17:14, on Zulip):

thats extremely dope

Jane Lusby (Mar 31 2020 at 17:14, on Zulip):

holy crap

Jane Lusby (Mar 31 2020 at 17:14, on Zulip):

I still think I want the two pass log viewing tho

David Barsky (Mar 31 2020 at 17:14, on Zulip):

oh true, same

Jane Lusby (Mar 31 2020 at 17:14, on Zulip):

because for example

Jane Lusby (Mar 31 2020 at 17:14, on Zulip):

with my cli tools I often dont know what thing I'm going ot need

Jane Lusby (Mar 31 2020 at 17:15, on Zulip):

and they have tons of side effects so its not always possible to run the same cmd over and over

Jane Lusby (Mar 31 2020 at 17:15, on Zulip):

so I've wanted to set it up to dump a verbose structured log into some dir where it rotates logs or something

Jane Lusby (Mar 31 2020 at 17:15, on Zulip):

and then a tool to go back and dig into the logs later

Jane Lusby (Mar 31 2020 at 17:15, on Zulip):

I want this for work more than anything tbh

Jane Lusby (Mar 31 2020 at 17:15, on Zulip):

our logs are so painful :sob:

Jane Lusby (Mar 31 2020 at 17:15, on Zulip):

but that aint gonna happen

Jane Lusby (Mar 31 2020 at 17:16, on Zulip):

thats an old C++ home made logging framework

David Barsky (Mar 31 2020 at 17:17, on Zulip):

we gotta get the per-layer filtering in, then

Jane Lusby (Mar 31 2020 at 17:18, on Zulip):

make it so numba one

David Barsky (Mar 31 2020 at 17:18, on Zulip):

i'm honored

Jane Lusby (Mar 31 2020 at 17:18, on Zulip):

lol

eddyb (Mar 31 2020 at 17:25, on Zulip):

@Jane Lusby did you see my ancient C++ code :P?

Jane Lusby (Mar 31 2020 at 17:25, on Zulip):

no

Jane Lusby (Mar 31 2020 at 17:25, on Zulip):

are you going to make me sad

eddyb (Mar 31 2020 at 17:26, on Zulip):

@Jane Lusby yes https://gist.github.com/eddyb/e727bcb2af8ffc2a32e6

eddyb (Mar 31 2020 at 17:26, on Zulip):

it's from an uhhh something like a SAT solver

eddyb (Mar 31 2020 at 17:26, on Zulip):

before it was drilled into me that NP-complete is real and insurmountable

Jane Lusby (Mar 31 2020 at 17:27, on Zulip):

lol

eddyb (Mar 31 2020 at 17:33, on Zulip):

@David Barsky @Jane Lusby okay posted examples of my unicode antics https://github.com/davidbarsky/tracing-tree/issues/4#issuecomment-606768738

Jane Lusby (Mar 31 2020 at 17:34, on Zulip):

ooo, thats nice

David Barsky (Mar 31 2020 at 17:34, on Zulip):

thanks for the deets! are you okay with this output being completely non-concurrent?

eddyb (Mar 31 2020 at 17:35, on Zulip):

what does that mean :P?

David Barsky (Mar 31 2020 at 17:35, on Zulip):

hmm

David Barsky (Mar 31 2020 at 17:36, on Zulip):

at the moment, you can't have two separate "trees" be printed for units of work that are occurring concurrently (e..g, on different threads or tasks)

eddyb (Mar 31 2020 at 17:37, on Zulip):

shouldn't be a concern for rustc, or we could, idk, print a tread ID on every line, and then have a tool to untangle them

eddyb (Mar 31 2020 at 17:38, on Zulip):

(once we start doing parallelism more commonly. for now we can just turn it off when we want debug logs)

David Barsky (Mar 31 2020 at 17:38, on Zulip):

I think the approach that's needed is:

  1. use the default tracing-subscriber fmt output that prints a "trace" on a per-line basis to narrow yourself down to a unit of work (a strand in chalk, for instance) that you're interested in
  2. reload the tracing config (at runtime!) to use the tracing-tree output
David Barsky (Mar 31 2020 at 17:38, on Zulip):

and that should work well with parallel rustc?

Jane Lusby (Mar 31 2020 at 17:38, on Zulip):

i still think it would be extremely cool to output json and then consume it to generate the untangled indented pretty shit we want

Jane Lusby (Mar 31 2020 at 17:38, on Zulip):

that way you can deal with concurrency after the fact

David Barsky (Mar 31 2020 at 17:38, on Zulip):

totally agreed

eddyb (Mar 31 2020 at 17:39, on Zulip):

@Jane Lusby literally what Cargo does because it runs multiple rustc's :P

eddyb (Mar 31 2020 at 17:39, on Zulip):

I think there used to be a time where errors from multiple rustcs could get interleaved

David Barsky (Mar 31 2020 at 17:39, on Zulip):

there's a neat python library that does whose name i'm forgetting atm

eddyb (Mar 31 2020 at 17:39, on Zulip):

even if each line was intact

David Barsky (Mar 31 2020 at 17:40, on Zulip):

[nods]

eddyb (Mar 31 2020 at 17:40, on Zulip):

I'm pretty sure what it does now is print the "rendered" field in the JSON output

eddyb (Mar 31 2020 at 17:40, on Zulip):

and it can act as an arbiter

David Barsky (Mar 31 2020 at 17:40, on Zulip):

here it is! https://github.com/jonathanj/eliottree

eddyb (Mar 31 2020 at 17:40, on Zulip):

but for tracing you'd have all the rendering done externally, so it's more like an IDE in that regard

eddyb (Mar 31 2020 at 17:41, on Zulip):

btw this is that example with proper two-space indents https://gist.githubusercontent.com/eddyb/05a9490eb50396754cee14967c485567/raw/6c75bf462bf66cc271bc6c4ab6b4ae6313c5a973/tracing-box-drawing-3

David Barsky (Mar 31 2020 at 17:41, on Zulip):

that tracks

David Barsky (Mar 31 2020 at 17:41, on Zulip):

it's good to know cargo ran into this issue first so that we don't need to re-invent this stuff

eddyb (Mar 31 2020 at 17:41, on Zulip):

bonus: we could give users just enough filters so there's not GBs of JSON, then inspect the parts we want, ourselves

David Barsky (Mar 31 2020 at 17:41, on Zulip):

can borrow some of those ideas

eddyb (Mar 31 2020 at 17:42, on Zulip):

sadly we don't have debug_assertions enabled in nightly Q_Q

eddyb (Mar 31 2020 at 17:42, on Zulip):

so the only logging you get is a couple info!s that are important enough

eddyb (Mar 31 2020 at 17:42, on Zulip):

(like the current fn being codegen'd)

David Barsky (Mar 31 2020 at 17:42, on Zulip):

(so the logging story in rustc isn't... great?)

eddyb (Mar 31 2020 at 17:43, on Zulip):

it's debug logging for local builds

eddyb (Mar 31 2020 at 17:43, on Zulip):

as in, while working on rustc

Jane Lusby (Mar 31 2020 at 17:44, on Zulip):

the tracing backend isnt json specific right

Jane Lusby (Mar 31 2020 at 17:44, on Zulip):

its tracing-serde?

Jane Lusby (Mar 31 2020 at 17:45, on Zulip):

also is that a layer or an old style subscriber

Jane Lusby (Mar 31 2020 at 17:46, on Zulip):

i dont even see a subscriber in tracing-serde

Jane Lusby (Mar 31 2020 at 17:46, on Zulip):

well, re the GBs of json, I was wondering if maybe we could use some other serialization format that would be faster/denser on the disk

eddyb (Mar 31 2020 at 17:46, on Zulip):

the solution is to not enable everything :P

eddyb (Mar 31 2020 at 17:47, on Zulip):

plus there's some silly logging that prints every byte in rmeta or w/e

eddyb (Mar 31 2020 at 17:47, on Zulip):

that we could get rid of

Jane Lusby (Mar 31 2020 at 17:48, on Zulip):

thats fair

Jane Lusby (Mar 31 2020 at 17:49, on Zulip):

but I feel like the more logging you can get away with without making your program slow / your logs impenetrable, the better

Jane Lusby (Mar 31 2020 at 17:49, on Zulip):

fuck now I wanna do a tracing-serde layer and a log viewer / query cli

eddyb (Mar 31 2020 at 17:49, on Zulip):

sure, but you hit limitations of scale :P

Jane Lusby (Mar 31 2020 at 17:49, on Zulip):

but I have no idea how to design an ergonomic api for querying logs

eddyb (Mar 31 2020 at 17:50, on Zulip):

a compiler has to do so much

Jane Lusby (Mar 31 2020 at 17:50, on Zulip):

for sure, and that 1% perf matters

eddyb (Mar 31 2020 at 17:50, on Zulip):

not even, the reason nightly doesn't include logging is code size IIRC

Jane Lusby (Mar 31 2020 at 17:50, on Zulip):

code size of the compiler?

Jane Lusby (Mar 31 2020 at 17:50, on Zulip):

like

eddyb (Mar 31 2020 at 17:50, on Zulip):

although I guess checking an atomic in a bunch of places might be costly

Jane Lusby (Mar 31 2020 at 17:50, on Zulip):

too physically big of a binary?

eddyb (Mar 31 2020 at 17:51, on Zulip):

yeah, we can't have even line-only debuginfo, for that reason

eddyb (Mar 31 2020 at 17:51, on Zulip):

it's like 100MB extra. idk how much debug logging is

Jane Lusby (Mar 31 2020 at 17:51, on Zulip):

line-only debuginfo?

eddyb (Mar 31 2020 at 17:51, on Zulip):

yeah to be able to get backtraces

Jane Lusby (Mar 31 2020 at 17:51, on Zulip):

ooh

Jane Lusby (Mar 31 2020 at 17:52, on Zulip):

oh eddy speaking of backtraces

eddyb (Mar 31 2020 at 17:52, on Zulip):

but when I said scale earlier I meant RUSTC_LOG=debug, for a local build where that does anything, produces far too much output

eddyb (Mar 31 2020 at 17:52, on Zulip):

because so much happens

Jane Lusby (Mar 31 2020 at 17:52, on Zulip):

do you wanna see a pre rfc im working on? :eyes:

eddyb (Mar 31 2020 at 17:52, on Zulip):

suuure

Jane Lusby (Mar 31 2020 at 17:52, on Zulip):

https://paper.dropbox.com/doc/Collaborative-Summary-3-Fact-Finding-Pre-RFCs-around-Error-Handling-Reporting--AxN4Vp9FL_YIPyxQq0_Lm24YAQ-dnShKo1SsHtdF4Yheeoco

eddyb (Mar 31 2020 at 17:52, on Zulip):

I think I was fixing a bug 4 hours ago

Jane Lusby (Mar 31 2020 at 17:53, on Zulip):

low key trying to get rid of backtraces

Jack Huey (Mar 31 2020 at 17:53, on Zulip):

speaking of debugging, I could never figure out how to show debug statements in rustc

Jane Lusby (Mar 31 2020 at 17:53, on Zulip):

not sure if good idea

Jack Huey (Mar 31 2020 at 17:53, on Zulip):

:(

eddyb (Mar 31 2020 at 17:53, on Zulip):

@Jack Huey debug-assertions = true

eddyb (Mar 31 2020 at 17:53, on Zulip):

and the env var is RUSTC_LOG not RUST_LOG

Jane Lusby (Mar 31 2020 at 17:53, on Zulip):

at least for errors*

eddyb (Mar 31 2020 at 17:53, on Zulip):

@Jane Lusby have you considering abusing #[track_caller] like @anp wants to?

Jane Lusby (Mar 31 2020 at 17:54, on Zulip):

yes, adam is the person who inspired this whole thing

eddyb (Mar 31 2020 at 17:54, on Zulip):

oh you are mentioning some of that stuff hmm

eddyb (Mar 31 2020 at 17:54, on Zulip):

ah ok

Jane Lusby (Mar 31 2020 at 17:54, on Zulip):

but the only way to do it with track_caller i think would be to encourage ppl to annotate from with it

eddyb (Mar 31 2020 at 17:54, on Zulip):

nope :)

Jane Lusby (Mar 31 2020 at 17:54, on Zulip):

which wouldnt let you get location info on From<T> -> T calls for ?

eddyb (Mar 31 2020 at 17:54, on Zulip):

you can put it on the trait method

Jane Lusby (Mar 31 2020 at 17:54, on Zulip):

which trait method

Jane Lusby (Mar 31 2020 at 17:54, on Zulip):

from_error?

Jane Lusby (Mar 31 2020 at 17:54, on Zulip):

in the try trait?

Jack Huey (Mar 31 2020 at 17:54, on Zulip):

eddyb said:

Jack Huey debug-assertions = true

oh that might be what I'm missing

eddyb (Mar 31 2020 at 17:54, on Zulip):

whatever method you want

Last update: Jun 07 2020 at 10:15UTC