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: 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 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

Last update: Jan 21 2020 at 08:30UTC