print spans on close #761

rkuhn · 2020-06-21T21:11:30Z

EDIT: thanks to @hawkw’s help this now actually is a pull request :-)

This is not really a pull request, more a hack that demonstrates the question I’d like to ask. Currently there is no subscriber that comes out of the box that will print information about spans. I find the concept quite useful and instrumented some code that does database queries in order to print out how long things take as well as tracing the execution (i.e. each span is doubling as a log statement of the same level). Example output looks like the following:

There is an ugly hack in the code to get the fields of the recently closed span into the output, and the output is generated using an even uglier hack by faking an event, but I hope that this still makes it sufficiently clear what I am trying to do.

There has been some discussion about “printing spans” in the past, but they did not quite target the same thing. I am after the timings and I want one line per span, just like an event, so I think the argument that “spans are too noisy” does not apply (otherwise events were too noisy as well).

Do you think it might make sense to implement this in a better way and offer it under a feature flag? This would be particularly useful for enabling test logging with a crate like test-env-log, where manual layer configuration is not suitable. I can also see myself using this to get nice and useful log output from production applications as well in several cases.

hawkw

Thanks for the PR, this is really cool! I had been hoping someone would come up with a good solution for generating log lines from spans, and I think the idea of synthesizing an event is actually really elegant --- it allows us to reuse the existing user-provided formatter without having to add more callback methods for span lifecycle logging, and makes whether or not span closes are logged into something that a user can just switch on or off.

I had some thoughts on how we could make this a bit less hacky and maybe get it merged. Let me know what you think!

tracing-subscriber/src/fmt/fmt_layer.rs

hawkw · 2020-06-22T22:34:11Z

tracing-subscriber/src/fmt/fmt_layer.rs

+            if self.fmt_event.format_event(&ctx, &mut buf, &event).is_ok() {
+                let fields = extensions
+                    .get::<FormattedFields<N>>()
+                    .expect("Unable to find FormattedFields in extensions; this is a bug");
+                if !fields.is_empty() {
+                    use std::fmt::Write;
+                    loop {
+                        let last = buf.pop();
+                        match last {
+                            Some(x) if x.is_whitespace() => {}
+                            Some(x) => {
+                                buf.push(x);
+                                break;
+                            }
+                            None => break,
+                        }
+                    }
+                    let _ = writeln!(&mut buf, " {}", fields);
+                }
+                let mut writer = self.make_writer.make_writer();
+                let _ = io::Write::write_all(&mut writer, buf.as_bytes());
+            }


What do you think about just calling self.on_event with the synthesized event, and including the formatted fields of the span in the message field? That way we could benefit from the same thread-local buffer that on_event formats events into, and avoid having to allocate a string for every span close?

Is it somehow possible to transfer the fields from the (close) span into the (synthesised) event? Then that would be the cleanest solution.

Hmm, not the field values --- the field values themselves are only available when they are recorded, since they are borrowed from the scope they were recorded in. At this point, we only have their formatted representation.

That said: since we generate the synthesized event as a child of the span that closed, the output of self.on_event would already contain the span's fields in the context that's displayed before the event's data. I'm not sure if we really need to also duplicate the fields in the message as well?

No, I tried that for quite a while before I understood that that cannot work: the span is closed, so the .scope() will not include it when iterating, so the span’s fields are not printed by some existing magic :-(

No, I tried that for quite a while before I understood that that cannot work: the span is closed, so the .scope() will not include it when iterating, so the span’s fields are not printed by some existing magic :-(

Hmm, after taking a look at format_event, you're right, but that's actually due to a bug in the format_event implementation for the default formatters. It looks like they always print the current span's scope as the context, even if the event has an explicitly set parent. We should fix that, and print the event's explicit parent's scope if one is set. Then, using new_child_of to create the synthesized event would include that span in the scope (since its data is only removed from the registry after on_close completes).

Okay, I just merged PR #767, which fixes the issue where format_event did not honor the overridden parent set by Event::new_child_of. If we rebase this branch to pick that up, we shouldn't have to bother with the span`s fields at all, since the event will be properly formatted as its child.

tracing-subscriber/src/fmt/fmt_layer.rs

rkuhn · 2020-06-23T20:09:26Z

I’ll be somewhat busy for the next two days, but will work on this soon.

tracing-subscriber/src/fmt/format/mod.rs

tracing-subscriber/src/fmt/fmt_layer.rs

tracing-subscriber/src/fmt/format/mod.rs

hawkw

This looks great to me --- I have some ideas on how we can make the docs a bit more helpful that would be good to address before this is merged.

Beyond that, I mainly commented on minor style nits that are not blockers.

tracing-subscriber/src/fmt/fmt_layer.rs

hawkw · 2020-06-29T16:42:41Z

tracing-subscriber/src/fmt/fmt_layer.rs

+            drop(extensions);
+            drop(span);


The explicit drop is necessary here so that the lock on the extensions is released before the call to on_event, preventing a deadlock, right? It might be nice to note that in a comment so that nobody reading this code in the future is confused or thinks that this can be confused.

The compiler will scream at you if you remove it because span is borrowed while on_event takes ownership of it. So github readers would benefit from a comment while IDE-users should see it quickly. I tried returning event to a different context, but Rust cannot express that (hence the macro, a function wouldn’t work).

hawkw · 2020-06-29T16:45:33Z

tracing-subscriber/src/fmt/fmt_layer.rs

+            (&iter.next().unwrap(), Some(&$value as &dyn field::Value)),
+        )*];
+        let vs = fs.value_set(&v);
+        let $event = Event::new_child_of($id, meta, &vs);


It seems a bit weird to me that this macro expands to a let binding that we assign to an identifier that's passed into the macro from the parent scope...but I guess that's so that the borrows on the metadata etc are still live?

Yes, and the identifier needs to be passed in because otherwise the following code wouldn’t be able to access it.

Yup, that makes sense --- it was a little surprising at first glance, so it might be worth adding a comment explaining why this works the way it does? But, not a blocker.

Edit: I see that you've changed the macro to take a sort of fake closure, instead. I think that communicates this more clearly --- LGTM!

tracing-subscriber/src/fmt/fmt_layer.rs

hawkw · 2020-06-29T16:47:19Z

tracing-subscriber/src/fmt/fmt_layer.rs

+            event_from_span!(event = id, span, message = "enter");
+            drop(extensions);
+            drop(span);
+            self.on_event(&event, ctx);


as above: where does the event variable come from? it looks like the generated event is being assigned to id...

Hmm, perhaps this could be solved by a with_event approach … I’ll experiment with that.

yes, that works better, thanks for pushing!

tracing-subscriber/src/fmt/format/mod.rs

tracing-subscriber/src/fmt/fmt_layer.rs

tracing-subscriber/src/fmt/mod.rs

tracing-subscriber/src/fmt/format/mod.rs

hawkw · 2020-06-29T18:43:08Z

tracing-subscriber/src/fmt/fmt_layer.rs

+    /// Select which span usage shall be logged as events
+    pub fn with_spans(self, kind: FmtSpan) -> Self {


Let's also apply my docs suggestions from #761 (comment) here as well.

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

hawkw · 2020-06-29T19:37:42Z

Looks like rustfmt needs to be run because it doesn't like the whitespace in the docs change I suggested (sorry). Mind fixing that?

rkuhn · 2020-06-30T06:18:24Z

One more thought based on the remark you added to the docs: would it make sense to split this out into a separate layer so that people could use it with their own event sinks?

davidbarsky · 2020-06-30T14:08:25Z

One more thought based on the remark you added to the docs: would it make sense to split this out into a separate layer so that people could use it with their own event sinks?

I'm (weakly) of the opinion that we can do this in followup PRs. This PR solves an immediate user need and splitting this into a separate layer might be better done as part of a larger tracing-subscriber modularization. I've proposed such a modularization in the past before, but I didn't think through the details and implications then; I think a have a better grasp on the problem space now.

hawkw · 2020-06-30T16:26:39Z

One more thought based on the remark you added to the docs: would it make sense to split this out into a separate layer so that people could use it with their own event sinks?

I'm (weakly) of the opinion that we can do this in followup PRs. This PR solves an immediate user need and splitting this into a separate layer might be better done as part of a larger tracing-subscriber modularization. I've proposed such a modularization in the past before, but I didn't think through the details and implications then; I think a have a better grasp on the problem space now.

Let's save that for later — I think this code is tightly coupled with the formatting stuff and would be hard to factor out witout other changes.

FWIW, I think it's a feature, not a bug, that these events are only visible by the fmt layer that produced them --- other layers may have their own ways of handling the span lifecycle that don't require a synthesized event, and this would just introduce noise (since the synthesized events can't be filtered out). If we did want to expose them to other layers, we could use the Context::event method, but I'd err on the side of not doing that unless there's a specific reason to.

hawkw

This looks great, and I'm really excited to merge it!

I commented on a few last style nits which you might want to address, but aren't blockers for merging this.

Thanks @rkuhn for all the work you've put into this PR!

hawkw · 2020-06-30T16:27:41Z

tracing-subscriber/src/fmt/fmt_layer.rs

+            (&iter.next().unwrap(), Some(&$value as &dyn field::Value)),
+        )*];
+        let vs = fs.value_set(&v);
+        let $event = Event::new_child_of($id, meta, &vs);


Yup, that makes sense --- it was a little surprising at first glance, so it might be worth adding a comment explaining why this works the way it does? But, not a blocker.

Edit: I see that you've changed the macro to take a sort of fake closure, instead. I think that communicates this more clearly --- LGTM!

tracing-subscriber/src/fmt/fmt_layer.rs

tracing-subscriber/src/fmt/format/mod.rs

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

rkuhn · 2020-06-30T17:26:02Z

Cool, thanks for your thorough reviews! I think it is good to go.

@rkuhn

Changed: - **parking_lot**: Updated the optional `parking_lot` dependency to accept the latest `parking_lot` version (#774) Fixed - **fmt**: Fixed events with explicitly overridden parent spans being formatted as though they were children of the current span (#767) Added - **fmt**: Added the option to print synthesized events when spans are created, entered, exited, and closed, including span durations (#761) - Documentation clarification and improvement (#762, #769) Thanks to @rkuhn, @greenwoodcm, and @Ralith for contributing to this release! Signed-off-by: Eliza Weisman <eliza@buoyant.io>

@rkuhn

Changed: - **parking_lot**: Updated the optional `parking_lot` dependency to accept the latest `parking_lot` version (#774) Fixed - **fmt**: Fixed events with explicitly overridden parent spans being formatted as though they were children of the current span (#767) Added - **fmt**: Added the option to print synthesized events when spans are created, entered, exited, and closed, including span durations (#761) - Documentation clarification and improvement (#762, #769) Thanks to @rkuhn, @greenwoodcm, and @Ralith for contributing to this release! Signed-off-by: Eliza Weisman <eliza@buoyant.io>

@rkuhn

### Changed - **parking_lot**: Updated the optional `parking_lot` dependency to accept the latest `parking_lot` version (#774) ### Fixed - **fmt**: Fixed events with explicitly overridden parent spans being formatted as though they were children of the current span (#767) ### Added - **fmt**: Added the option to print synthesized events when spans are created, entered, exited, and closed, including span durations (#761) - Documentation clarification and improvement (#762, #769) Thanks to @rkuhn, @greenwoodcm, and @Ralith for contributing to this release! Signed-off-by: Eliza Weisman <eliza@buoyant.io>

rkuhn requested review from hawkw and a team as code owners June 21, 2020 21:11

hawkw reviewed Jun 22, 2020

View reviewed changes

tracing-subscriber/src/fmt/fmt_layer.rs Outdated Show resolved Hide resolved

hawkw mentioned this pull request Jun 24, 2020

subscriber: default event formatters don't honor explicit parents #766

Closed

rkuhn added 2 commits June 27, 2020 13:59

print spans on close

68365eb

make it nicer according to PR review

6fb9ee3

rkuhn force-pushed the print-spans-on-close branch from e1b53bd to 6fb9ee3 Compare June 27, 2020 16:52

rkuhn commented Jun 27, 2020

View reviewed changes

tracing-subscriber/src/fmt/format/mod.rs Show resolved Hide resolved

tracing-subscriber/src/fmt/fmt_layer.rs Outdated Show resolved Hide resolved

rkuhn added 2 commits June 27, 2020 20:45

use field::display properly

d927511

flatten one unnecessary function call

592950f

rkuhn commented Jun 27, 2020

View reviewed changes

tracing-subscriber/src/fmt/format/mod.rs Show resolved Hide resolved

switch FmtSpan to struct for non-exhaustive matching

70887c9

hawkw reviewed Jun 29, 2020

View reviewed changes

hawkw requested review from davidbarsky and yaahc June 29, 2020 18:43

hawkw added crate/subscriber Related to the `tracing-subscriber` crate kind/feature New feature or request labels Jun 29, 2020

better docs for span emission config

83af6ce

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

more polish after review

c7e8b61

hawkw approved these changes Jun 30, 2020

View reviewed changes

rkuhn and others added 2 commits June 30, 2020 19:22

make macro match more specific

d7856e9

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

doc fix

b2157f6

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

hawkw merged commit 50e8574 into tokio-rs:master Jun 30, 2020

hawkw mentioned this pull request Jul 1, 2020

subscriber: prepare to release 0.2.7 (July 1, 2020) #775

Merged

hawkw mentioned this pull request Jul 21, 2020

Inconsistent Structure of Log Messages #829

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

print spans on close #761

print spans on close #761

rkuhn commented Jun 21, 2020 •

edited

hawkw left a comment

hawkw Jun 22, 2020

rkuhn Jun 23, 2020

hawkw Jun 23, 2020

rkuhn Jun 23, 2020

hawkw Jun 23, 2020

hawkw Jun 24, 2020

rkuhn commented Jun 23, 2020

hawkw left a comment

hawkw Jun 29, 2020

rkuhn Jun 29, 2020

hawkw Jun 29, 2020

rkuhn Jun 29, 2020

hawkw Jun 30, 2020

hawkw Jun 29, 2020

rkuhn Jun 29, 2020

rkuhn Jun 30, 2020

hawkw Jun 29, 2020

hawkw commented Jun 29, 2020

rkuhn commented Jun 30, 2020

davidbarsky commented Jun 30, 2020 •

edited

hawkw commented Jun 30, 2020

hawkw left a comment

hawkw Jun 30, 2020

rkuhn commented Jun 30, 2020

		/// Select which span usage shall be logged as events
		pub fn with_spans(self, kind: FmtSpan) -> Self {

print spans on close #761

print spans on close #761

Conversation

rkuhn commented Jun 21, 2020 • edited

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rkuhn commented Jun 23, 2020

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hawkw commented Jun 29, 2020

rkuhn commented Jun 30, 2020

davidbarsky commented Jun 30, 2020 • edited

hawkw commented Jun 30, 2020

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rkuhn commented Jun 30, 2020

rkuhn commented Jun 21, 2020 •

edited

davidbarsky commented Jun 30, 2020 •

edited