Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

subscriber: move timing into separate subscriber layer #3063

Draft
wants to merge 2 commits into
base: master
Choose a base branch
from

Conversation

joshka
Copy link
Contributor

@joshka joshka commented Aug 17, 2024

Moves the Timing logic out from fmt::Subcriber into its own layer.

Motivation

This allows for the timing subscriber logic to be composed and used by
any subscriber rather than just users of the fmt subscriber. I'd like this
info to be available as part of some ideas for a new Ratatui tracing layer
I'm thinking about.

Solution

A new subscriber (TimingSubscriber) that stores Timing in the span extensions
Updated the on_close logic in fmt::Subsciber to use this and removed all
the code that otherwise dealt with timing.

The expectation is that this subscriber would be composed when there's need to
record any timing data.

TODO: work out how to properly configure the fmt subscriber to use the
timing subscriber as a layer (or otherwise make it easy to compose this
layer)

Questions:

  • is this a good idea?
  • what should be the backwards compat story for this?
  • should this have a quanta implementation instead of Instant::now, and should that be feature flagged, or just defaulted (ping @tobz for some advice)

Fixes: #2946
Replaces: #3038

This allows for the timing subscriber logic to be composed and used by
any subscriber rather than just users of the fmt subscriber.

TODO: work out how to properly configure the fmt subscriber to use the
timing subscriber as a layer.

Fixes: tokio-rs#2946
Replaces: tokio-rs#3038
@joshka
Copy link
Contributor Author

joshka commented Aug 17, 2024

Added an example which uses this:

    tracing_subscriber::registry()
        .with(tracing_subscriber::fmt::timing::TimingSubscriber::default())
        .with(tracing_subscriber::FmtSubscriber::new().with_span_events(FmtSpan::FULL))
        .init();
image

Copy link
Contributor Author

@joshka joshka left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few extra comments to help review.


let t_idle = field::display(TimingDisplay(idle));
let t_busy = field::display(TimingDisplay(busy));
if let Some(timing) = extensions.get::<super::timing::Timing>() {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This likely should still check whether the fmt_timing field is set. That now should control whether to display the timing, not whether to capture it.

@@ -1630,24 +1630,6 @@ impl Default for FmtSpanConfig {
}
}

pub(super) struct TimingDisplay(pub(super) u64);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Storing a Duration instead of a u54 makes this unnecessary.

}

/// Get the total time spent in this span.
pub fn total(&self) -> Duration {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added total as an affordance to make viewing logs easier (and not require the viewer / software where the logs end up to do math to work out the total)

Comment on lines +9 to +10
.with(tracing_subscriber::fmt::timing::TimingSubscriber::default())
.with(tracing_subscriber::FmtSubscriber::new().with_span_events(FmtSpan::FULL))
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the main part I'd want to work better / get guidance on what's best for tracing. Perhaps this is the right thing to do. Maybe moving this into its own top level module, and providing something like the following would be useful?

tracing_subscriber::timing::subscriber()

//! A subscriber that tracks the time spent in each span.

use core::time::Duration;
use std::time::Instant;
Copy link
Contributor Author

@joshka joshka Aug 21, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder whether it's worth considering using quanta here instead of std::time::Instant? That would make this inherently testable without too much complication.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Separate out Timings extension from FmtSubscriber
1 participant