subscriber: move timing into separate subscriber layer #3063
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,22 @@ | ||
| #![deny(rust_2018_idioms)] | ||
|
|
||
| use tracing_subscriber::{fmt::format::FmtSpan, prelude::*, subscribe::CollectExt}; | ||
| #[path = "fmt/yak_shave.rs"] | ||
| mod yak_shave; | ||
|
|
||
| fn main() { | ||
| tracing_subscriber::registry() | ||
| .with(tracing_subscriber::fmt::timing::TimingSubscriber::default()) | ||
| .with(tracing_subscriber::FmtSubscriber::new().with_span_events(FmtSpan::FULL)) | ||
| .init(); | ||
|
|
||
| let number_of_yaks = 3; | ||
| // this creates a new event, outside of any spans. | ||
| tracing::info!(number_of_yaks, "preparing to shave yaks"); | ||
|
|
||
| let number_shaved = yak_shave::shave_all(number_of_yaks); | ||
| tracing::info!( | ||
| all_yaks_shaved = number_shaved == number_of_yaks, | ||
| "yak shaving completed." | ||
| ); | ||
| } | ||
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,155 @@ | ||
| //! A subscriber that tracks the time spent in each span. | ||
|
|
||
| use core::time::Duration; | ||
| use std::time::Instant; | ||
|
There was a problem hiding this comment. 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. |
||
|
|
||
| use tracing::Collect; | ||
| use tracing_core::span::{self, Attributes}; | ||
|
|
||
| use crate::{registry::LookupSpan, subscribe::Context, Subscribe}; | ||
|
|
||
| /// A subscriber that tracks the time spent in each span. | ||
| /// | ||
| /// This subscriber records the time spent in each span, storing the timing data in the span's | ||
| /// extensions. The subscriber records the time spent in each span as either "idle" time, when the | ||
| /// span is not executing, or "busy" time, when the span is executing. The subscriber records the | ||
| /// time spent in each span as a [`Timing`] resource, which can be accessed by other subscribers. | ||
| #[derive(Debug, Default)] | ||
| pub struct TimingSubscriber; | ||
|
|
||
| /// A resource tracking the idle and busy time spent in each span. | ||
| /// | ||
| /// This is used by the [`TimingSubscriber`] to track the time spent in each span. | ||
| #[derive(Debug, Clone, Copy, PartialEq, Eq)] | ||
| pub struct Timing { | ||
| state: State, | ||
| idle: Duration, | ||
| busy: Duration, | ||
| last: Instant, | ||
| } | ||
|
|
||
| impl Default for Timing { | ||
| fn default() -> Self { | ||
| Self::new() | ||
| } | ||
| } | ||
|
|
||
| #[derive(Debug, Default, Clone, Copy, PartialEq, Eq)] | ||
| enum State { | ||
| /// The span is closed. | ||
| /// | ||
| /// No further timing information will be recorded. | ||
| Closed, | ||
| #[default] | ||
| /// The span is currently idle. | ||
| /// | ||
| /// Timing information will be recorded when the span becomes busy or closed. | ||
| Idle, | ||
| /// The span is currently busy. | ||
| /// | ||
| /// Timing information will be recorded when the span becomes idle or closed. | ||
| Busy, | ||
| } | ||
|
|
||
| impl Timing { | ||
| /// Create a new `Timing` resource. | ||
| fn new() -> Self { | ||
| Self { | ||
| state: State::Idle, | ||
| idle: Duration::ZERO, | ||
| busy: Duration::ZERO, | ||
| last: Instant::now(), | ||
| } | ||
| } | ||
|
|
||
| /// Record that the span has become idle. | ||
| fn enter(&mut self) { | ||
| if self.state == State::Busy { | ||
| return; | ||
| } | ||
| let now = Instant::now(); | ||
| self.idle += now.duration_since(self.last); | ||
| self.last = now; | ||
| self.state = State::Busy; | ||
| } | ||
|
|
||
| /// Record that the span has become busy. | ||
| fn exit(&mut self) { | ||
| if self.state == State::Idle { | ||
| return; | ||
| } | ||
| let now = Instant::now(); | ||
| self.busy += now.duration_since(self.last); | ||
| self.last = now; | ||
| self.state = State::Idle; | ||
| } | ||
|
|
||
| /// Record that the span has been closed. | ||
| fn close(&mut self) { | ||
| match self.state { | ||
| State::Idle => self.idle += Instant::now().duration_since(self.last), | ||
| State::Busy => self.busy += Instant::now().duration_since(self.last), | ||
| State::Closed => {} | ||
| } | ||
| self.state = State::Closed; | ||
| } | ||
|
|
||
| /// Get the idle time spent in this span. | ||
| pub fn idle(&self) -> Duration { | ||
| self.idle | ||
| } | ||
|
|
||
| /// Get the busy time spent in this span. | ||
| pub fn busy(&self) -> Duration { | ||
| self.busy | ||
| } | ||
|
|
||
| /// Get the total time spent in this span. | ||
| pub fn total(&self) -> Duration { | ||
|
There was a problem hiding this comment. 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) |
||
| self.idle + self.busy | ||
| } | ||
| } | ||
|
|
||
| impl<C> Subscribe<C> for TimingSubscriber | ||
| where | ||
| C: Collect + for<'a> LookupSpan<'a>, | ||
| { | ||
| /// Records that a new span has been created. | ||
| fn on_new_span(&self, _attrs: &Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { | ||
| let span = ctx.span(id).expect("span not found"); | ||
| let mut extensions = span.extensions_mut(); | ||
| extensions.insert(Timing::new()); | ||
| } | ||
|
|
||
| /// Records that a span has been entered. | ||
| /// | ||
| /// The subscriber records the time spent in the span as "idle" time, as the span is not | ||
| /// executing. | ||
| fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { | ||
| let span = ctx.span(id).expect("span not found"); | ||
| let mut extensions = span.extensions_mut(); | ||
| let timings = extensions.get_mut::<Timing>().expect("timings not found"); | ||
| timings.enter(); | ||
| } | ||
|
|
||
| /// Records that a span has been exited. | ||
| /// | ||
| /// The subscriber records the time spent in the span as "busy" time, as the span is executing. | ||
| fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { | ||
| let span = ctx.span(id).expect("span not found"); | ||
| let mut extensions = span.extensions_mut(); | ||
| let timings = extensions.get_mut::<Timing>().expect("timings not found"); | ||
| timings.exit(); | ||
| } | ||
|
|
||
| /// Records that a span has been closed. | ||
| /// | ||
| /// The subscriber records the time spent in the span as either "idle" time or "busy" time, as | ||
| /// the span is not executing. | ||
| fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { | ||
| let span = ctx.span(&id).expect("span not found"); | ||
| let mut extensions = span.extensions_mut(); | ||
| let timings = extensions.get_mut::<Timing>().expect("timings not found"); | ||
| timings.close(); | ||
| } | ||
| } | ||
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
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?