diff --git a/tokio-trace-log/src/lib.rs b/tokio-trace-log/src/lib.rs index 060e7434..465a21fb 100644 --- a/tokio-trace-log/src/lib.rs +++ b/tokio-trace-log/src/lib.rs @@ -23,7 +23,7 @@ extern crate tokio_trace; extern crate log; use std::{io, time::Instant}; -use tokio_trace::{Subscriber, Event, SpanData, Meta}; +use tokio_trace::{span, Subscriber, Event, SpanData, Meta}; /// Format a log record as a trace event in the current span. pub fn format_trace(record: &log::Record) -> io::Result<()> { @@ -155,6 +155,10 @@ impl Subscriber for LogSubscriber { log::logger().enabled(&metadata.as_log()) } + fn new_span_id(&self, metadata: &Meta) -> span::Id { + span::Id::from_u64(0) + } + fn observe_event<'event, 'meta: 'event>(&self, event: &'event Event<'event, 'meta>) { let fields = event.debug_fields(); let meta = event.meta.as_log(); diff --git a/tokio-trace/examples/sloggish/sloggish_subscriber.rs b/tokio-trace/examples/sloggish/sloggish_subscriber.rs index 3df6b594..8d02e044 100644 --- a/tokio-trace/examples/sloggish/sloggish_subscriber.rs +++ b/tokio-trace/examples/sloggish/sloggish_subscriber.rs @@ -21,7 +21,7 @@ use std::{ hash::{BuildHasher, Hash, Hasher}, fmt, io::{self, Write}, - sync::Mutex, + sync::{Mutex, atomic::{AtomicUsize, Ordering}}, time::{Instant, SystemTime}, }; @@ -32,6 +32,7 @@ pub struct SloggishSubscriber { t0_sys: SystemTime, hash_builder: RandomState, stack: Mutex>, + ids: AtomicUsize, } struct ColorLevel(Level); @@ -57,6 +58,7 @@ impl SloggishSubscriber { t0_sys: SystemTime::now(), hash_builder: RandomState::new(), stack: Mutex::new(vec![]), + ids: AtomicUsize::new(0), } } @@ -117,6 +119,11 @@ impl tokio_trace::Subscriber for SloggishSubscriber { true } + fn new_span_id(&self, _: &tokio_trace::Meta) -> tokio_trace::span::Id { + let next = self.ids.fetch_add(1, Ordering::SeqCst) as u64; + tokio_trace::span::Id::from_u64(next) + } + #[inline] fn observe_event<'event, 'meta: 'event>(&self, event: &'event tokio_trace::Event<'event, 'meta>) { let mut stderr = self.stderr.lock(); diff --git a/tokio-trace/src/dispatcher.rs b/tokio-trace/src/dispatcher.rs index a5e61241..f0997ae2 100644 --- a/tokio-trace/src/dispatcher.rs +++ b/tokio-trace/src/dispatcher.rs @@ -1,4 +1,4 @@ -use {subscriber::Subscriber, Event, SpanData, Meta}; +use {span, subscriber::Subscriber, Event, SpanData, Meta}; use std::{ sync::atomic::{AtomicUsize, Ordering, ATOMIC_USIZE_INIT}, @@ -64,6 +64,15 @@ impl Subscriber for Builder { } } + fn new_span_id(&self, metadata: &Meta) -> span::Id { + // TODO: this shouldn't let the first attached subscriber always be in + // control of the span ID, but the dispatcher type is going away soon + // anyway, so for now, it just needs to compile. + self.subscribers.get(0) + .map(|subscriber| subscriber.new_span_id(metadata)) + .unwrap_or_else(|| span::Id::from_u64(0)) + } + #[inline] fn enter(&self, span: &SpanData, at: Instant) { for subscriber in &self.subscribers { @@ -97,6 +106,11 @@ impl Subscriber for Dispatcher { self.0.enabled(metadata) } + #[inline] + fn new_span_id(&self, metadata: &Meta) -> span::Id { + self.0.new_span_id(metadata) + } + #[inline] fn observe_event<'event, 'meta: 'event>(&self, event: &'event Event<'event, 'meta>) { self.0.observe_event(event) @@ -123,6 +137,10 @@ impl Subscriber for NoDispatcher { false } + fn new_span_id(&self, _metadata: &Meta) -> span::Id { + span::Id::from_u64(0) + } + fn observe_event<'event, 'meta: 'event>(&self, _event: &'event Event<'event, 'meta>) { // Do nothing. } diff --git a/tokio-trace/src/lib.rs b/tokio-trace/src/lib.rs index bc385be1..e55df6f7 100644 --- a/tokio-trace/src/lib.rs +++ b/tokio-trace/src/lib.rs @@ -193,8 +193,10 @@ macro_rules! span { { use $crate::{span, Subscriber, Dispatcher, Meta}; static META: Meta<'static> = static_meta!($name, $($k),* ); - if Dispatcher::current().enabled(&META) { + let dispatcher = Dispatcher::current(); + if dispatcher.enabled(&META) { span::Span::new( + dispatcher.new_span_id(&META), ::std::time::Instant::now(), &META, vec![ $(Box::new($val)),* ], // todo: wish this wasn't double-boxed... diff --git a/tokio-trace/src/span.rs b/tokio-trace/src/span.rs index e459d75f..3bb4ad6f 100644 --- a/tokio-trace/src/span.rs +++ b/tokio-trace/src/span.rs @@ -101,6 +101,19 @@ pub struct Data { inner: Arc, } +/// Identifies a span within the context of a process. +/// +/// Span IDs are used primarily to determine of two handles refer to the same +/// span, without requiring the comparison of the span's fields. +/// +/// They are generated by `Subscriber`s for each span as it is created, through +/// the [`Subscriber::new_span_id`] trait method. See the documentation for that +/// method for more information on span ID generation. +/// +/// [`Subscriber::new_span_id`]: ../subscriber/trait.Subscriber.html#tymethod.new_span_id +#[derive(Clone, Debug, PartialEq, Hash)] +pub struct Id(u64); + /// Internal representation of the data associated with a span. /// /// This has the potential to outlive the span itself, if a `Data` reference to @@ -120,6 +133,8 @@ struct DataInner { pub field_values: Vec>, + pub id: Id, + state: AtomicUsize, } @@ -193,12 +208,14 @@ impl Span { /// directly. #[doc(hidden)] pub fn new( + id: Id, opened_at: Instant, static_meta: &'static StaticMeta, field_values: Vec>, ) -> Self { let parent = Active::current(); let data = Data::new( + id, opened_at, parent.as_ref().map(Active::data), static_meta, @@ -269,6 +286,7 @@ impl Into> for Span { impl Data { fn new( + id: Id, opened_at: Instant, parent: Option<&Data>, static_meta: &'static StaticMeta, @@ -280,6 +298,7 @@ impl Data { parent: parent.cloned(), static_meta, field_values, + id, state: AtomicUsize::new(0), }) } @@ -394,6 +413,11 @@ impl Data { } } + /// Returns the span's identifier. + pub fn id(&self) -> Id { + Id(self.inner.id.0) + } + fn set_state(&self, prev: State, next: State) { self.inner.state.compare_and_swap( prev as usize, @@ -423,6 +447,15 @@ impl fmt::Debug for Data { } } +// ===== impl Id ===== + +impl Id { + pub fn from_u64(u: u64) -> Self { + Id(u) + } +} + + // ===== impl Active ===== impl Active { @@ -530,15 +563,13 @@ impl Hash for ActiveInner { impl Hash for DataInner { fn hash(&self, state: &mut H) { - self.opened_at.hash(state); - self.static_meta.hash(state); + self.id.hash(state); } } impl cmp::PartialEq for DataInner { fn eq(&self, other: &DataInner) -> bool { - self.opened_at == other.opened_at && - self.static_meta == other.static_meta + self.id == other.id } } @@ -685,4 +716,51 @@ mod tests { }); } + #[test] + fn handles_to_the_same_span_are_equal() { + // Create a mock subscriber that will return `true` on calls to + // `Subscriber::enabled`, so that the spans will be constructed. We + // won't enter any spans in this test, so the subscriber won't actually + // expect to see any spans. + subscriber::mock().run(); + + let foo1 = span!("foo"); + let foo2 = foo1.clone(); + + // Two handles that point to the same span are equal. + assert_eq!(foo1, foo2); + + // The two span's data handles are also equal. + assert_eq!(foo1.data(), foo2.data()); + } + + #[test] + fn handles_to_different_spans_are_not_equal() { + subscriber::mock().run(); + + // Even though these spans have the same name and fields, they will have + // differing metadata, since they were created on different lines. + let foo1 = span!("foo", bar = 1, baz = false); + let foo2 = span!("foo", bar = 1, baz = false); + + assert_ne!(foo1, foo2); + assert_ne!(foo1.data(), foo2.data()); + } + + #[test] + fn handles_to_different_spans_with_the_same_metadata_are_not_equal() { + subscriber::mock().run(); + + // Every time time this function is called, it will return a _new + // instance_ of a span with the same metadata, name, and fields. + fn make_span() -> Span { + span!("foo", bar = 1, baz = false) + } + + let foo1 = make_span(); + let foo2 = make_span(); + + assert_ne!(foo1, foo2); + assert_ne!(foo1.data(), foo2.data()); + } } diff --git a/tokio-trace/src/subscriber.rs b/tokio-trace/src/subscriber.rs index 61d92f52..e3bd3641 100644 --- a/tokio-trace/src/subscriber.rs +++ b/tokio-trace/src/subscriber.rs @@ -1,4 +1,4 @@ -use super::{Event, SpanData, Meta}; +use super::{span, Event, SpanData, Meta}; use std::time::Instant; pub trait Subscriber { @@ -8,6 +8,23 @@ pub trait Subscriber { /// if the span would be discarded anyway. fn enabled(&self, metadata: &Meta) -> bool; + /// Returns a new [span ID] for a span with the specified metadata. + /// + /// Span IDs are used to uniquely identify spans, so span equality will be + /// based on the returned ID. Thus, if the subscriber wishes for all spans + /// with the same metadata to be considered equal, it should return the same + /// ID every time it is given a particular set of metadata. Similarly, if it + /// wishes for two separate instances of a span with the same metadata to *not* + /// be equal, it should return a distinct ID every time this function is called, + /// regardless of the metadata. + /// + /// Subscribers which do not rely on the implementations of `PartialEq`, + /// `Eq`, and `Hash` for `Span`s are free to return span IDs with value 0 + /// from all calls to this function, if they so choose. + /// + /// [span ID]: ../span/struct.Id.html + fn new_span_id(&self, metadata: &Meta) -> span::Id; + /// Note that this function is generic over a pair of lifetimes because the /// `Event` type is. See the documentation for [`Event`] for details. /// @@ -82,6 +99,10 @@ where (self.filter)(metadata) && self.inner.enabled(metadata) } + fn new_span_id(&self, metadata: &Meta) -> span::Id { + self.inner.new_span_id(metadata) + } + #[inline] fn observe_event<'event, 'meta: 'event>(&self, event: &'event Event<'event, 'meta>) { self.inner.observe_event(event) @@ -105,13 +126,14 @@ pub use self::test_support::*; mod test_support { use super::Subscriber; use ::{Event, SpanData, Meta}; - use ::span::MockSpan; + use ::span::{self, MockSpan}; use std::{ cell::RefCell, collections::VecDeque, time::Instant, thread, + sync::atomic::{AtomicUsize, Ordering}, }; struct ExpectEvent { @@ -126,6 +148,7 @@ mod test_support { struct Running { expected: RefCell>, + ids: AtomicUsize, } pub struct MockSubscriber { @@ -166,6 +189,7 @@ mod test_support { .try_init(); let subscriber = Running { expected: RefCell::new(self.expected), + ids: AtomicUsize::new(0), }; MOCK_SUBSCRIBER.with(move |mock| { *mock.borrow_mut() = Some(subscriber); @@ -179,6 +203,10 @@ mod test_support { true } + fn new_span_id(&self, _meta: &Meta) -> span::Id { + span::Id::from_u64(self.ids.fetch_add(1, Ordering::SeqCst) as u64) + } + fn observe_event<'event, 'meta: 'event>(&self, _event: &'event Event<'event, 'meta>) { match self.expected.borrow_mut().pop_front() { None => {} @@ -237,6 +265,15 @@ mod test_support { true } + fn new_span_id(&self, meta: &Meta) -> span::Id { + MOCK_SUBSCRIBER.with(|mock| { + mock.borrow() + .as_ref() + .map(|subscriber| subscriber.new_span_id(meta)) + .unwrap_or_else(|| span::Id::from_u64(0)) + }) + } + fn observe_event<'event, 'meta: 'event>(&self, event: &'event Event<'event, 'meta>) { MOCK_SUBSCRIBER.with(|mock| { if let Some(ref subscriber) = *mock.borrow() {