From 9dc0129fe2c108bf1d0d52fd38e60455213bace7 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 6 Feb 2019 13:00:48 -0800 Subject: [PATCH] trace: Improve support for batching field values (#880) This branch reworks `tokio-trace`'s field recording APIs to improve performance in cases where field values are provided in batches. `tokio-trace` supports recording values for span fields either when the span is constructed, or at any point during its lifetime. In order to support this, the current implementation represents each field value recorded with a separate call to a `Subscriber::record_$TYPE` function. This can incur significant overhead --- for example, if the span data is stored behind a mutex, every call to `record` must reacquire the lock. Providing most or all of the fields on a span up-front as it is constructed is likely to be the common case, but in the current design, this use-case has to pay performance costs in order to support the less common case of adding values post-initialization. Even in situations where some field values are unknown, if a majority are recorded at construction-time, each individual value takes a separate trip through the `record` pipeline. This branch rewrites this API so that all field recording is done by a `ValueSet` type, which groups together multiple values. A subscriber may pass an implementation of `Record` to the `ValueSet`'s `record` function, which will record all the provided values with that recorder. When a span is constructed, the `Subscriber::new_span` method is called with a `ValueSet` containing all the fields provided to the `span!` macro, and additional fields may be recorded either individually or in batches. In addition, the previous implementation of `Event`s on top of `Span`s has been removed and replaced with a new `Event` type which goes through a separate `Subscriber::event` function. Events are always known to have all their values at construction time, since the event cannot live long enough to have more values added. Thus, an `Event` also contains a `ValueSet`. I've added new test-support code for expecting certain fields to be recorded by spans and events, and written new tests to cover this behaviour. I've also updated the example code, and my experience doing so suggests that the new API is also somewhat more ergonomic to use. These changes result in significant improvement on the benchmark that simulates recording multiple fields on a span (`bench_span_with_fields_record`). Before: ``` Running target/release/deps/no_subscriber-a6af9f5aa4934184 running 5 tests test bench_1_atomic_load ... bench: 0 ns/iter (+/- 0) test bench_costly_field_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_log_no_logger ... bench: 0 ns/iter (+/- 0) test bench_no_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test result: ok. 0 passed; 0 failed; 0 ignored; 5 measured; 0 filtered out Running target/release/deps/subscriber-ba753dc1d87e480d running 4 tests test span_no_fields ... bench: 41 ns/iter (+/- 5) test span_repeatedly ... bench: 5,418 ns/iter (+/- 658) test span_with_fields ... bench: 110 ns/iter (+/- 42) test span_with_fields_record ... bench: 1,047 ns/iter (+/- 240) test result: ok. 0 passed; 0 failed; 0 ignored; 4 measured; 0 filtered out ``` After: ``` Running target/release/deps/no_subscriber-611d60b262fbbcfb running 5 tests test bench_1_atomic_load ... bench: 0 ns/iter (+/- 0) test bench_costly_field_no_subscriber ... bench: 1 ns/iter (+/- 0) test bench_log_no_logger ... bench: 0 ns/iter (+/- 0) test bench_no_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test result: ok. 0 passed; 0 failed; 0 ignored; 5 measured; 0 filtered out Running target/release/deps/subscriber-7a1279c84c0d50ff running 4 tests test span_no_fields ... bench: 37 ns/iter (+/- 9) test span_repeatedly ... bench: 4,502 ns/iter (+/- 712) test span_with_fields ... bench: 54 ns/iter (+/- 17) test span_with_fields_record ... bench: 364 ns/iter (+/- 38) test result: ok. 0 passed; 0 failed; 0 ignored; 4 measured; 0 filtered out ``` Signed-off-by: Eliza Weisman --- tokio-trace/benches/subscriber.rs | 54 +- tokio-trace/examples/counters.rs | 69 ++- .../examples/sloggish/sloggish_subscriber.rs | 175 ++++--- tokio-trace/src/field.rs | 178 ------- tokio-trace/src/lib.rs | 306 +++++------ tokio-trace/src/span.rs | 280 ++-------- tokio-trace/tests/event.rs | 169 ++++++ tokio-trace/tests/span.rs | 161 +++++- tokio-trace/tests/support/event.rs | 92 ++++ tokio-trace/tests/support/field.rs | 224 ++++++++ tokio-trace/tests/support/metadata.rs | 64 +++ tokio-trace/tests/support/mod.rs | 3 + tokio-trace/tests/support/span.rs | 91 +++- tokio-trace/tests/support/subscriber.rs | 164 +++--- tokio-trace/tokio-trace-core/src/callsite.rs | 2 +- .../tokio-trace-core/src/dispatcher.rs | 75 +-- tokio-trace/tokio-trace-core/src/event.rs | 58 +++ tokio-trace/tokio-trace-core/src/field.rs | 492 +++++++++++++++++- tokio-trace/tokio-trace-core/src/lib.rs | 6 + .../tokio-trace-core/src/subscriber.rs | 109 ++-- 20 files changed, 1843 insertions(+), 929 deletions(-) create mode 100644 tokio-trace/tests/event.rs create mode 100644 tokio-trace/tests/support/event.rs create mode 100644 tokio-trace/tests/support/field.rs create mode 100644 tokio-trace/tests/support/metadata.rs create mode 100644 tokio-trace/tokio-trace-core/src/event.rs diff --git a/tokio-trace/benches/subscriber.rs b/tokio-trace/benches/subscriber.rs index 5e2c22d0141..fd60979b1b1 100644 --- a/tokio-trace/benches/subscriber.rs +++ b/tokio-trace/benches/subscriber.rs @@ -5,23 +5,30 @@ extern crate tokio_trace; extern crate test; use test::Bencher; -use std::sync::Mutex; -use tokio_trace::{field, span, Id, Metadata}; +use std::{ + fmt, + sync::{Mutex, MutexGuard}, +}; +use tokio_trace::{field, span, Event, Id, Metadata}; /// A subscriber that is enabled but otherwise does nothing. struct EnabledSubscriber; impl tokio_trace::Subscriber for EnabledSubscriber { - fn new_span(&self, span: &Metadata) -> Id { - let _ = span; + fn new_span(&self, span: &Metadata, values: &field::ValueSet) -> Id { + let _ = (span, values); Id::from_u64(0) } - fn record_debug(&self, span: &Id, field: &field::Field, value: &::std::fmt::Debug) { - let _ = (span, field, value); + fn event(&self, event: &Event) { + let _ = event; + } + + fn record(&self, span: &Id, values: &field::ValueSet) { + let _ = (span, values); } - fn add_follows_from(&self, span: &Id, follows: Id) { + fn record_follows_from(&self, span: &Id, follows: &Id) { let _ = (span, follows); } @@ -40,19 +47,35 @@ impl tokio_trace::Subscriber for EnabledSubscriber { } /// Simulates a subscriber that records span data. -struct Record(Mutex>); +struct RecordingSubscriber(Mutex); -impl tokio_trace::Subscriber for Record { - fn new_span(&self, span: &Metadata) -> Id { - *self.0.lock().unwrap() = Some(span.name().to_string()); +struct Recorder<'a>(MutexGuard<'a, String>); + +impl<'a> field::Record for Recorder<'a> { + fn record_debug(&mut self, _field: &field::Field, value: &fmt::Debug) { + use std::fmt::Write; + let _ = write!(&mut *self.0, "{:?}", value); + } +} + +impl tokio_trace::Subscriber for RecordingSubscriber { + fn new_span(&self, _span: &Metadata, values: &field::ValueSet) -> Id { + let mut recorder = Recorder(self.0.lock().unwrap()); + values.record(&mut recorder); Id::from_u64(0) } - fn record_debug(&self, _span: &Id, _field: &field::Field, value: &::std::fmt::Debug) { - *self.0.lock().unwrap() = Some(format!("{:?}", value)); + fn record(&self, _span: &Id, values: &field::ValueSet) { + let mut recorder = Recorder(self.0.lock().unwrap()); + values.record(&mut recorder); + } + + fn event(&self, event: &Event) { + let mut recorder = Recorder(self.0.lock().unwrap()); + event.record(&mut recorder); } - fn add_follows_from(&self, span: &Id, follows: Id) { + fn record_follows_from(&self, span: &Id, follows: &Id) { let _ = (span, follows); } @@ -107,7 +130,8 @@ fn span_with_fields(b: &mut Bencher) { #[bench] fn span_with_fields_record(b: &mut Bencher) { - tokio_trace::subscriber::with_default(Record(Mutex::new(None)), || { + let subscriber = RecordingSubscriber(Mutex::new(String::from(""))); + tokio_trace::subscriber::with_default(subscriber, || { b.iter(|| { span!( "span", diff --git a/tokio-trace/examples/counters.rs b/tokio-trace/examples/counters.rs index 7304cd857b3..9c617c4c6dc 100644 --- a/tokio-trace/examples/counters.rs +++ b/tokio-trace/examples/counters.rs @@ -2,16 +2,18 @@ extern crate tokio_trace; use tokio_trace::{ - field, span, + field::{self, Field, Record}, + span, subscriber::{self, Subscriber}, - Id, Metadata, + Event, Id, Metadata, }; use std::{ collections::HashMap, + fmt, sync::{ atomic::{AtomicUsize, Ordering}, - Arc, RwLock, + Arc, RwLock, RwLockReadGuard, }, }; @@ -23,8 +25,42 @@ struct CounterSubscriber { counters: Counters, } +struct Count<'a> { + counters: RwLockReadGuard<'a, HashMap>, +} + +impl<'a> Record for Count<'a> { + fn record_i64(&mut self, field: &Field, value: i64) { + if let Some(counter) = self.counters.get(field.name()) { + if value > 0 { + counter.fetch_add(value as usize, Ordering::Release); + } else { + counter.fetch_sub((value * -1) as usize, Ordering::Release); + } + }; + } + + fn record_u64(&mut self, field: &Field, value: u64) { + if let Some(counter) = self.counters.get(field.name()) { + counter.fetch_add(value as usize, Ordering::Release); + }; + } + + fn record_bool(&mut self, _: &Field, _: bool) {} + fn record_str(&mut self, _: &Field, _: &str) {} + fn record_debug(&mut self, _: &Field, _: &fmt::Debug) {} +} + +impl CounterSubscriber { + fn recorder(&self) -> Count { + Count { + counters: self.counters.0.read().unwrap(), + } + } +} + impl Subscriber for CounterSubscriber { - fn register_callsite(&self, meta: &tokio_trace::Metadata) -> subscriber::Interest { + fn register_callsite(&self, meta: &Metadata) -> subscriber::Interest { let mut interest = subscriber::Interest::never(); for key in meta.fields() { let name = key.name(); @@ -41,35 +77,24 @@ impl Subscriber for CounterSubscriber { interest } - fn new_span(&self, _new_span: &Metadata) -> Id { + fn new_span(&self, _new_span: &Metadata, values: &field::ValueSet) -> Id { + values.record(&mut self.recorder()); let id = self.ids.fetch_add(1, Ordering::SeqCst); Id::from_u64(id as u64) } - fn add_follows_from(&self, _span: &Id, _follows: Id) { + fn record_follows_from(&self, _span: &Id, _follows: &Id) { // unimplemented } - fn record_i64(&self, _id: &Id, field: &field::Field, value: i64) { - let registry = self.counters.0.read().unwrap(); - if let Some(counter) = registry.get(field.name()) { - if value > 0 { - counter.fetch_add(value as usize, Ordering::Release); - } else { - counter.fetch_sub(value as usize, Ordering::Release); - } - }; + fn record(&self, _: &Id, values: &field::ValueSet) { + values.record(&mut self.recorder()) } - fn record_u64(&self, _id: &Id, field: &field::Field, value: u64) { - let registry = self.counters.0.read().unwrap(); - if let Some(counter) = registry.get(field.name()) { - counter.fetch_add(value as usize, Ordering::Release); - }; + fn event(&self, event: &Event) { + event.record(&mut self.recorder()) } - fn record_debug(&self, _id: &Id, _field: &field::Field, _value: &::std::fmt::Debug) {} - fn enabled(&self, metadata: &Metadata) -> bool { metadata.fields().iter().any(|f| f.name().contains("count")) } diff --git a/tokio-trace/examples/sloggish/sloggish_subscriber.rs b/tokio-trace/examples/sloggish/sloggish_subscriber.rs index 720f92a5fb8..4a93f93533a 100644 --- a/tokio-trace/examples/sloggish/sloggish_subscriber.rs +++ b/tokio-trace/examples/sloggish/sloggish_subscriber.rs @@ -13,7 +13,11 @@ extern crate ansi_term; extern crate humantime; use self::ansi_term::{Color, Style}; -use super::tokio_trace::{self, Id, Level, Subscriber}; +use super::tokio_trace::{ + self, + field::{Field, Record}, + Id, Level, Subscriber, +}; use std::{ cell::RefCell, @@ -70,73 +74,83 @@ pub struct SloggishSubscriber { stderr: io::Stderr, stack: Mutex>, spans: Mutex>, - events: Mutex>, ids: AtomicUsize, } struct Span { parent: Option, - kvs: Vec<(String, String)>, + kvs: Vec<(&'static str, String)>, } -struct Event { - level: tokio_trace::Level, - target: String, - message: String, - kvs: Vec<(String, String)>, +struct Event<'a> { + stderr: io::StderrLock<'a>, + comma: bool, } -struct ColorLevel(Level); +struct ColorLevel<'a>(&'a Level); -impl fmt::Display for ColorLevel { +impl<'a> fmt::Display for ColorLevel<'a> { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { match self.0 { - Level::TRACE => Color::Purple.paint("TRACE"), - Level::DEBUG => Color::Blue.paint("DEBUG"), - Level::INFO => Color::Green.paint("INFO"), - Level::WARN => Color::Yellow.paint("WARN "), - Level::ERROR => Color::Red.paint("ERROR"), + &Level::TRACE => Color::Purple.paint("TRACE"), + &Level::DEBUG => Color::Blue.paint("DEBUG"), + &Level::INFO => Color::Green.paint("INFO "), + &Level::WARN => Color::Yellow.paint("WARN "), + &Level::ERROR => Color::Red.paint("ERROR"), } .fmt(f) } } impl Span { - fn new(parent: Option, _meta: &tokio_trace::Metadata) -> Self { - Self { + fn new( + parent: Option, + _meta: &tokio_trace::Metadata, + values: &tokio_trace::field::ValueSet, + ) -> Self { + let mut span = Self { parent, kvs: Vec::new(), - } - } - - fn record(&mut self, key: &tokio_trace::field::Field, value: fmt::Arguments) { - // TODO: shouldn't have to alloc the key... - let k = key.name().to_owned(); - let v = fmt::format(value); - self.kvs.push((k, v)); + }; + values.record(&mut span); + span } } -impl Event { - fn new(meta: &tokio_trace::Metadata) -> Self { - Self { - target: meta.target.to_owned(), - level: meta.level.clone(), - message: String::new(), - kvs: Vec::new(), - } +impl Record for Span { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.kvs.push((field.name(), format!("{:?}", value))) } +} - fn record(&mut self, key: &tokio_trace::field::Field, value: fmt::Arguments) { - if key.name() == "message" { - self.message = fmt::format(value); - return; +impl<'a> Record for Event<'a> { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + write!( + &mut self.stderr, + "{comma} ", + comma = if self.comma { "," } else { "" }, + ) + .unwrap(); + let name = field.name(); + if name == "message" { + write!( + &mut self.stderr, + "{}", + // Have to alloc here due to `ansi_term`'s API... + Style::new().bold().paint(format!("{:?}", value)) + ) + .unwrap(); + self.comma = true; + } else { + write!( + &mut self.stderr, + "{}: {:?}", + Style::new().bold().paint(name), + value + ) + .unwrap(); + self.comma = true; } - - // TODO: shouldn't have to alloc the key... - let k = key.name().to_owned(); - let v = fmt::format(value); - self.kvs.push((k, v)); } } @@ -148,7 +162,6 @@ impl SloggishSubscriber { stderr: io::stderr(), stack: Mutex::new(vec![]), spans: Mutex::new(HashMap::new()), - events: Mutex::new(HashMap::new()), ids: AtomicUsize::new(0), } } @@ -193,39 +206,26 @@ impl Subscriber for SloggishSubscriber { true } - fn new_span(&self, span: &tokio_trace::Metadata) -> tokio_trace::Id { + fn new_span( + &self, + span: &tokio_trace::Metadata, + values: &tokio_trace::field::ValueSet, + ) -> tokio_trace::Id { let next = self.ids.fetch_add(1, Ordering::SeqCst) as u64; let id = tokio_trace::Id::from_u64(next); - if span.name.contains("event") { - self.events - .lock() - .unwrap() - .insert(id.clone(), Event::new(span)); - } else { - self.spans - .lock() - .unwrap() - .insert(id.clone(), Span::new(self.current.id(), span)); - } + let span = Span::new(self.current.id(), span, values); + self.spans.lock().unwrap().insert(id.clone(), span); id } - fn record_debug( - &self, - span: &tokio_trace::Id, - name: &tokio_trace::field::Field, - value: &fmt::Debug, - ) { - if let Some(event) = self.events.lock().expect("mutex poisoned!").get_mut(span) { - return event.record(name, format_args!("{:?}", value)); - }; + fn record(&self, span: &tokio_trace::Id, values: &tokio_trace::field::ValueSet) { let mut spans = self.spans.lock().expect("mutex poisoned!"); if let Some(span) = spans.get_mut(span) { - span.record(name, format_args!("{:?}", value)) + values.record(span); } } - fn add_follows_from(&self, _span: &tokio_trace::Id, _follows: tokio_trace::Id) { + fn record_follows_from(&self, _span: &tokio_trace::Id, _follows: &tokio_trace::Id) { // unimplemented } @@ -261,34 +261,33 @@ impl Subscriber for SloggishSubscriber { } } + fn event(&self, event: &tokio_trace::Event) { + let mut stderr = self.stderr.lock(); + let indent = self.stack.lock().unwrap().len(); + self.print_indent(&mut stderr, indent).unwrap(); + write!( + &mut stderr, + "{timestamp} {level} {target}", + timestamp = humantime::format_rfc3339_seconds(SystemTime::now()), + level = ColorLevel(event.metadata().level()), + target = &event.metadata().target(), + ) + .unwrap(); + let mut recorder = Event { + stderr, + comma: false, + }; + event.record(&mut recorder); + write!(&mut recorder.stderr, "\n").unwrap(); + } + #[inline] fn exit(&self, _span: &tokio_trace::Id) { // TODO: unify stack with current span self.current.exit(); } - fn drop_span(&self, id: tokio_trace::Id) { - if let Some(event) = self.events.lock().expect("mutex poisoned").remove(&id) { - let mut stderr = self.stderr.lock(); - let indent = self.stack.lock().unwrap().len(); - self.print_indent(&mut stderr, indent).unwrap(); - write!( - &mut stderr, - "{timestamp} {level} {target} {message}", - timestamp = humantime::format_rfc3339_seconds(SystemTime::now()), - level = ColorLevel(event.level), - target = &event.target, - message = Style::new().bold().paint(event.message), - ) - .unwrap(); - self.print_kvs( - &mut stderr, - event.kvs.iter().map(|&(ref k, ref v)| (k, v)), - ", ", - ) - .unwrap(); - write!(&mut stderr, "\n").unwrap(); - } + fn drop_span(&self, _id: tokio_trace::Id) { // TODO: GC unneeded spans. } } diff --git a/tokio-trace/src/field.rs b/tokio-trace/src/field.rs index 2c3b3e6b113..9f8fdad9788 100644 --- a/tokio-trace/src/field.rs +++ b/tokio-trace/src/field.rs @@ -1,7 +1,6 @@ //! Structured data associated with `Span`s and `Event`s. pub use tokio_trace_core::field::*; -use std::fmt; use Metadata; /// Trait implemented to allow a type to be used as a field key. @@ -19,120 +18,6 @@ pub trait AsField: ::sealed::Sealed { fn as_field(&self, metadata: &Metadata) -> Option; } -// If, in the future, there's a valid use-case for user-defined `Record` -// implementations, consider unsealing this trait. -pub trait Record: ::sealed::Sealed { - /// Record a signed 64-bit integer value. - fn record_i64(&mut self, field: &Q, value: i64) - where - Q: AsField; - - /// Record an umsigned 64-bit integer value. - fn record_u64(&mut self, field: &Q, value: u64) - where - Q: AsField; - - /// Record a boolean value. - fn record_bool(&mut self, field: &Q, value: bool) - where - Q: AsField; - - /// Record a string value. - fn record_str(&mut self, field: &Q, value: &str) - where - Q: AsField; - - /// Record a value implementing `fmt::Debug`. - fn record_debug(&mut self, field: &Q, value: &fmt::Debug) - where - Q: AsField; -} - -/// A field value of an erased type. -/// -/// Implementors of `Value` may call the appropriate typed recording methods on -/// the `Subscriber` passed to `record` in order to indicate how their data -/// should be recorded. -pub trait Value { - /// Records this value with the given `Subscriber`. - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record; -} - -/// A `Value` which serializes as a string using `fmt::Display`. -#[derive(Clone)] -pub struct DisplayValue(T); - -/// A `Value` which serializes as a string using `fmt::Debug`. -#[derive(Clone)] -pub struct DebugValue(T); - -/// Wraps a type implementing `fmt::Display` as a `Value` that can be -/// recorded using its `Display` implementation. -pub fn display(t: T) -> DisplayValue -where - T: fmt::Display, -{ - DisplayValue(t) -} - -// ===== impl Value ===== - -/// Wraps a type implementing `fmt::Debug` as a `Value` that can be -/// recorded using its `Debug` implementation. -pub fn debug(t: T) -> DebugValue -where - T: fmt::Debug, -{ - DebugValue(t) -} - -macro_rules! impl_values { - ( $( $record:ident( $( $whatever:tt)+ ) ),+ ) => { - $( - impl_value!{ $record( $( $whatever )+ ) } - )+ - } -} -macro_rules! impl_value { - ( $record:ident( $( $value_ty:ty ),+ ) ) => { - $( - impl $crate::field::Value for $value_ty { - fn record( - &self, - key: &Q, - recorder: &mut R, - ) - where - Q: $crate::field::AsField, - R: $crate::field::Record, - { - recorder.$record(key, *self) - } - } - )+ - }; - ( $record:ident( $( $value_ty:ty ),+ as $as_ty:ty) ) => { - $( - impl Value for $value_ty { - fn record( - &self, - key: &Q, - recorder: &mut R, - ) - where - Q: $crate::field::AsField, - R: $crate::field::Record, - { - recorder.$record(key, *self as $as_ty) - } - } - )+ - }; -} - // ===== impl AsField ===== impl AsField for Field { @@ -167,66 +52,3 @@ impl AsField for str { impl ::sealed::Sealed for Field {} impl<'a> ::sealed::Sealed for &'a Field {} impl ::sealed::Sealed for str {} - -// ===== impl Value ===== - -impl_values! { - record_u64(u64), - record_u64(usize, u32, u16 as u64), - record_i64(i64), - record_i64(isize, i32, i16, i8 as i64), - record_bool(bool) -} - -impl Value for str { - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record, - { - recorder.record_str(key, &self) - } -} - -impl<'a, T: ?Sized> Value for &'a T -where - T: Value + 'a, -{ - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record, - { - (*self).record(key, recorder) - } -} - -// ===== impl DisplayValue ===== - -impl Value for DisplayValue -where - T: fmt::Display, -{ - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record, - { - recorder.record_debug(key, &format_args!("{}", self.0)) - } -} - -// ===== impl DebugValue ===== - -impl Value for DebugValue -where - T: fmt::Debug, -{ - fn record(&self, key: &Q, recorder: &mut R) - where - Q: AsField, - R: Record, - { - recorder.record_debug(key, &self.0) - } -} diff --git a/tokio-trace/src/lib.rs b/tokio-trace/src/lib.rs index 8bd3025cee9..e6a3d27d982 100644 --- a/tokio-trace/src/lib.rs +++ b/tokio-trace/src/lib.rs @@ -247,11 +247,12 @@ //! #[macro_use] //! extern crate tokio_trace; //! # pub struct FooSubscriber; -//! # use tokio_trace::{span::Id, field::Field, Metadata}; +//! # use tokio_trace::{span::Id, Metadata, field::ValueSet}; //! # impl tokio_trace::Subscriber for FooSubscriber { -//! # fn new_span(&self, _: &Metadata) -> Id { Id::from_u64(0) } -//! # fn record_debug(&self, _: &Id, _: &Field, _: &::std::fmt::Debug) {} -//! # fn add_follows_from(&self, _: &Id, _: Id) {} +//! # fn new_span(&self, _: &Metadata, _: &ValueSet) -> Id { Id::from_u64(0) } +//! # fn record(&self, _: &Id, _: &ValueSet) {} +//! # fn event(&self, _: &tokio_trace::Event) {} +//! # fn record_follows_from(&self, _: &Id, _: &Id) {} //! # fn enabled(&self, _: &Metadata) -> bool { false } //! # fn enter(&self, _: &Id) {} //! # fn exit(&self, _: &Id) {} @@ -302,10 +303,11 @@ use tokio_trace_core::*; pub use self::{ dispatcher::Dispatch, + event::Event, field::Value, - span::{Event, Span}, + span::Span, subscriber::Subscriber, - tokio_trace_core::{dispatcher, Level, Metadata}, + tokio_trace_core::{dispatcher, event, Level, Metadata}, }; #[doc(hidden)] @@ -321,31 +323,30 @@ pub use self::{ #[doc(hidden)] #[macro_export] macro_rules! callsite { - (span: $name:expr, $( $field_name:ident ),*) => ({ - callsite!(@ + (name: $name:expr, fields: $( $field_name:ident ),* $(,)*) => ({ + callsite! { name: $name, target: module_path!(), level: $crate::Level::TRACE, - fields: &[ $(stringify!($field_name)),* ] - ) + fields: $( $field_name ),* + } }); - (event: $lvl:expr, $( $field_name:ident ),*) => - (callsite!(event: $lvl, target: module_path!(), $( $field_name ),* )); - (event: $lvl:expr, target: $target:expr, $( $field_name:ident ),*) => ({ - callsite!(@ - name: concat!("event at ", file!(), ":", line!()), - target: $target, + (name: $name:expr, level: $lvl:expr, fields: $( $field_name:ident ),* $(,)*) => ({ + callsite! { + name: $name, + target: module_path!(), level: $lvl, - fields: &[ "message", $(stringify!($field_name)),* ] - ) + fields: $( $field_name ),* + } }); - (@ + ( name: $name:expr, target: $target:expr, level: $lvl:expr, - fields: $field_names:expr + fields: $( $field_name:ident ),* + $(,)* ) => ({ - use std::sync::{Once, atomic::{ATOMIC_USIZE_INIT, AtomicUsize, Ordering}}; + use std::sync::{Once, atomic::{self, AtomicUsize, Ordering}}; use $crate::{callsite, Metadata, subscriber::Interest}; struct MyCallsite; static META: Metadata<'static> = { @@ -353,11 +354,14 @@ macro_rules! callsite { name: $name, target: $target, level: $lvl, - fields: $field_names, + fields: &[ $( stringify!($field_name) ),* ], callsite: &MyCallsite, } }; - static INTEREST: AtomicUsize = ATOMIC_USIZE_INIT; + // FIXME: Rust 1.34 deprecated ATOMIC_USIZE_INIT. When Tokio's minimum + // supported version is 1.34, replace this with the const fn `::new`. + #[allow(deprecated)] + static INTEREST: AtomicUsize = atomic::ATOMIC_USIZE_INIT; static REGISTRATION: Once = Once::new(); impl MyCallsite { #[inline] @@ -444,37 +448,17 @@ macro_rules! span { ($name:expr) => { span!($name,) }; ($name:expr, $($k:ident $( = $val:expr )* ) ,*) => { { - #[allow(unused_imports)] - use $crate::{callsite, field::{Value, AsField}, Span}; + use $crate::{callsite, field::{Value, ValueSet, AsField}, Span}; use $crate::callsite::Callsite; - let callsite = callsite! { span: $name, $( $k ),* }; - let interest = callsite.interest(); - if interest.is_never() { - Span::new_disabled() + let callsite = callsite! { name: $name, fields: $( $k ),* }; + if is_enabled!(callsite) { + let meta = callsite.metadata(); + Span::new(meta, &valueset!(meta.fields(), $($k $( = $val)*),*)) } else { - let mut span = Span::new(interest, callsite.metadata()); - // Depending on how many fields are generated, this may or may - // not actually be used, but it doesn't make sense to repeat it. - #[allow(unused_variables, unused_mut)] { - if !span.is_disabled() { - let mut keys = callsite.metadata().fields().into_iter(); - $( - let key = keys.next() - .expect(concat!("metadata should define a key for '", stringify!($k), "'")); - span!(@ record: span, $k, &key, $($val)*); - )* - }; - } - span + Span::new_disabled() } } }; - (@ record: $span:expr, $k:expr, $i:expr, $val:expr) => ( - $span.record($i, &$val) - ); - (@ record: $span:expr, $k:expr, $i:expr,) => ( - // skip - ); } /// Constructs a new `Event`. @@ -501,96 +485,58 @@ macro_rules! span { /// event!(Level::INFO, the_answer = data.0); /// # } /// ``` +/// +/// Note that *unlike `span!`*, `event!` requires a value for all fields. As +/// events are recorded immediately when the macro is invoked, there is no +/// opportunity for fields to be recorded later. +/// +/// For example, the following does not compile: +/// ```rust,compile_fail +/// # #[macro_use] +/// # extern crate tokio_trace; +/// use tokio_trace::{Level, field}; +/// +/// # fn main() { +/// event!(Level::Info, foo = 5, bad_field, bar = field::display("hello")) +/// #} +/// ``` #[macro_export] macro_rules! event { - (target: $target:expr, $lvl:expr, $( $k:ident $( = $val:expr )* ),+ ) => ( - event!(target: $target, $lvl, { $( $k $( = $val)* ),+ }) - ); - (target: $target:expr, $lvl:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ({ + (target: $target:expr, $lvl:expr, { $( $k:ident = $val:expr ),* $(,)*} )=> ({ { #[allow(unused_imports)] - use $crate::{callsite, Id, Subscriber, Event, field::{Value, AsField}}; + use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}}; use $crate::callsite::Callsite; - let callsite = callsite! { event: - $lvl, - target: - $target, $( $k ),* + let callsite = callsite! { + name: concat!("event ", file!(), ":", line!()), + target: $target, + level: $lvl, + fields: $( $k ),* }; - let interest = callsite.interest(); - if interest.is_never() { - Event::new_disabled() - } else { - let mut event = Event::new(callsite.interest(), callsite.metadata()); - // Depending on how many fields are generated, this may or may - // not actually be used, but it doesn't make sense to repeat it. - #[allow(unused_variables, unused_mut)] { - if !event.is_disabled() { - let mut keys = callsite.metadata().fields().into_iter(); - let msg_key = keys.next() - .expect("event metadata should define a key for the message"); - event.message(&msg_key, format_args!( $($arg)+ )); - $( - let key = keys.next() - .expect(concat!("metadata should define a key for '", stringify!($k), "'")); - event!(@ record: event, $k, &key, $($val)*); - )* - } - } - event + if is_enabled!(callsite) { + let meta = callsite.metadata(); + Event::observe(meta, &valueset!(meta.fields(), $( $k = $val),* )); } } }); - (target: $target:expr, $lvl:expr, { $( $k:ident $( = $val:expr )* ),* } ) => ({ - { - #[allow(unused_imports)] - use $crate::{callsite, Id, Subscriber, Event, field::{Value, AsField}}; - use $crate::callsite::Callsite; - let callsite = callsite! { event: - $lvl, - target: - $target, $( $k ),* - }; - let interest = callsite.interest(); - if interest.is_never() { - Event::new_disabled() - } else { - let mut event = Event::new(callsite.interest(), callsite.metadata()); - // Depending on how many fields are generated, this may or may - // not actually be used, but it doesn't make sense to repeat it. - #[allow(unused_variables, unused_mut)] { - if !event.is_disabled() { - let mut keys = callsite.metadata().fields().into_iter(); - let msg_key = keys.next() - .expect("event metadata should define a key for the message"); - $( - let key = keys.next() - .expect(concat!("metadata should define a key for '", stringify!($k), "'")); - event!(@ record: event, $k, &key, $($val)*); - )* - } - } - event - } - } + (target: $target:expr, $lvl:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ({ + event!(target: $target, $lvl, { message = format_args!($($arg)+), $( $k = $val ),* }) }); + (target: $target:expr, $lvl:expr, $( $k:ident = $val:expr ),+ ) => ( + event!(target: $target, $lvl, { $($k = $val),+ }) + ); (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ( event!(target: $target, $lvl, { }, $($arg)+) ); - ( $lvl:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: module_path!(), $lvl, { $($k $( = $val)* ),* }, $($arg)+) + ( $lvl:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $lvl, { message = format_args!($($arg)+), $($k = $val),* }) ); - ( $lvl:expr, $( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: module_path!(), $lvl, { $($k $( = $val)* ),* }) + ( $lvl:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $lvl, { $($k = $val),* }) ); ( $lvl:expr, $($arg:tt)+ ) => ( event!(target: module_path!(), $lvl, { }, $($arg)+) ); - (@ record: $ev:expr, $k:expr, $i:expr, $val:expr) => ( - $ev.record($i, &$val); - ); - (@ record: $ev:expr, $k:expr, $i:expr,) => ( - // skip - ); } /// Constructs an event at the trace level. @@ -620,7 +566,7 @@ macro_rules! event { /// /// trace!(position = field::debug(pos), origin_dist = field::debug(origin_dist)); /// trace!(target: "app_events", -/// { pos = field::debug(pos) }, +/// { position = field::debug(pos) }, /// "x is {} and y is {}", /// if pos.x >= 0.0 { "positive" } else { "negative" }, /// if pos.y >= 0.0 { "positive" } else { "negative" }); @@ -628,11 +574,11 @@ macro_rules! event { /// ``` #[macro_export] macro_rules! trace { - (target: $target:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: $target, $crate::Level::TRACE, { $($k $( = $val)* ),* }, $($arg)+) + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::TRACE, { $($k = $val),* }, $($arg)+) ); - (target: $target:expr, $( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: $target, $crate::Level::TRACE, { $($k $( = $val)* ),* }) + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::TRACE, { $($k = $val),* }) ); (target: $target:expr, $($arg:tt)+ ) => ( // When invoking this macro with `log`-style syntax (no fields), we @@ -642,11 +588,11 @@ macro_rules! trace { // the handle won't be used later to add values to them. drop(event!(target: $target, $crate::Level::TRACE, {}, $($arg)+)); ); - ({ $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: module_path!(), $crate::Level::TRACE, { $($k $( = $val)* ),* }, $($arg)+) + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::TRACE, { $($k = $val),* }, $($arg)+) ); - ($( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: module_path!(), $crate::Level::TRACE, { $($k $( = $val)* ),* }) + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::TRACE, { $($k = $val),* }) ); ($($arg:tt)+ ) => ( drop(event!(target: module_path!(), $crate::Level::TRACE, {}, $($arg)+)); @@ -675,20 +621,20 @@ macro_rules! trace { /// ``` #[macro_export] macro_rules! debug { - (target: $target:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: $target, $crate::Level::DEBUG, { $($k $( = $val)* ),* }, $($arg)+) + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::DEBUG, { $($k = $val),* }, $($arg)+) ); - (target: $target:expr, $( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: $target, $crate::Level::DEBUG, { $($k $( = $val)* ),* }) + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::DEBUG, { $($k = $val),* }) ); (target: $target:expr, $($arg:tt)+ ) => ( drop(event!(target: $target, $crate::Level::DEBUG, {}, $($arg)+)); ); - ({ $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: module_path!(), $crate::Level::DEBUG, { $($k $( = $val)* ),* }, $($arg)+) + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::DEBUG, { $($k = $val),* }, $($arg)+) ); - ($( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: module_path!(), $crate::Level::DEBUG, { $($k $( = $val)* ),* }) + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::DEBUG, { $($k = $val),* }) ); ($($arg:tt)+ ) => ( drop(event!(target: module_path!(), $crate::Level::DEBUG, {}, $($arg)+)); @@ -724,20 +670,20 @@ macro_rules! debug { /// ``` #[macro_export] macro_rules! info { - (target: $target:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: $target, $crate::Level::INFO, { $($k $( = $val)* ),* }, $($arg)+) + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::INFO, { $($k = $val),* }, $($arg)+) ); - (target: $target:expr, $( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: $target, $crate::Level::INFO, { $($k $( = $val)* ),* }) + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::INFO, { $($k = $val),* }) ); (target: $target:expr, $($arg:tt)+ ) => ( drop(event!(target: $target, $crate::Level::INFO, {}, $($arg)+)); ); - ({ $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: module_path!(), $crate::Level::INFO, { $($k $( = $val)* ),* }, $($arg)+) + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::INFO, { $($k = $val),* }, $($arg)+) ); - ($( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: module_path!(), $crate::Level::INFO, { $($k $( = $val)* ),* }) + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::INFO, { $($k = $val),* }) ); ($($arg:tt)+ ) => ( drop(event!(target: module_path!(), $crate::Level::INFO, {}, $($arg)+)); @@ -770,20 +716,20 @@ macro_rules! info { /// ``` #[macro_export] macro_rules! warn { - (target: $target:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: $target, $crate::Level::WARN, { $($k $( = $val)* ),* }, $($arg)+) + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::WARN, { $($k = $val),* }, $($arg)+) ); - (target: $target:expr, $( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: $target, $crate::Level::WARN, { $($k $( = $val)* ),* }) + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::WARN, { $($k = $val),* }) ); (target: $target:expr, $($arg:tt)+ ) => ( drop(event!(target: $target, $crate::Level::WARN, {}, $($arg)+)); ); - ({ $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: module_path!(), $crate::Level::WARN, { $($k $( = $val)* ),* }, $($arg)+) + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::WARN, { $($k = $val),* }, $($arg)+) ); - ($( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: module_path!(), $crate::Level::WARN,{ $($k $( = $val)* ),* }) + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::WARN,{ $($k = $val),* }) ); ($($arg:tt)+ ) => ( drop(event!(target: module_path!(), $crate::Level::WARN, {}, $($arg)+)); @@ -811,26 +757,62 @@ macro_rules! warn { /// ``` #[macro_export] macro_rules! error { - (target: $target:expr, { $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: $target, $crate::Level::ERROR, { $($k $( = $val)* ),* }, $($arg)+) + (target: $target:expr, { $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: $target, $crate::Level::ERROR, { $($k = $val),* }, $($arg)+) ); - (target: $target:expr, $( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: $target, $crate::Level::ERROR, { $($k $( = $val)* ),* }) + (target: $target:expr, $( $k:ident = $val:expr ),* ) => ( + event!(target: $target, $crate::Level::ERROR, { $($k = $val),* }) ); (target: $target:expr, $($arg:tt)+ ) => ( drop(event!(target: $target, $crate::Level::ERROR, {}, $($arg)+)); ); - ({ $( $k:ident $( = $val:expr )* ),* }, $($arg:tt)+ ) => ( - event!(target: module_path!(), $crate::Level::ERROR, { $($k $( = $val)* ),* }, $($arg)+) + ({ $( $k:ident = $val:expr ),* }, $($arg:tt)+ ) => ( + event!(target: module_path!(), $crate::Level::ERROR, { $($k = $val),* }, $($arg)+) ); - ($( $k:ident $( = $val:expr )* ),* ) => ( - event!(target: module_path!(), $crate::Level::ERROR, { $($k $( = $val)* ),* }) + ($( $k:ident = $val:expr ),* ) => ( + event!(target: module_path!(), $crate::Level::ERROR, { $($k = $val),* }) ); ($($arg:tt)+ ) => ( drop(event!(target: module_path!(), $crate::Level::ERROR, {}, $($arg)+)); ); } +#[macro_export] +// TODO: determine if this ought to be public API? +#[doc(hidden)] +macro_rules! is_enabled { + ($callsite:expr) => {{ + let interest = $callsite.interest(); + if interest.is_never() { + false + } else if interest.is_always() { + true + } else { + let meta = $callsite.metadata(); + $crate::dispatcher::with(|current| current.enabled(meta)) + } + }}; +} + +#[doc(hidden)] +#[macro_export] +macro_rules! valueset { + ($fields:expr, $($k:ident $( = $val:expr )* ) ,*) => { + { + let mut iter = $fields.iter(); + $fields.value_set(&[ + $(( + &iter.next().expect("FieldSet corrupted (this is a bug)"), + valueset!(@val $k $(= $val)*) + )),* + ]) + } + }; + (@val $k:ident = $val:expr) => { + Some(&$val as &$crate::field::Value) + }; + (@val $k:ident) => { None }; +} pub mod field; pub mod span; pub mod subscriber; diff --git a/tokio-trace/src/span.rs b/tokio-trace/src/span.rs index 02f38bbe111..ceae403770e 100644 --- a/tokio-trace/src/span.rs +++ b/tokio-trace/src/span.rs @@ -145,9 +145,7 @@ use std::{ }; use { dispatcher::{self, Dispatch}, - field, - subscriber::Interest, - Metadata, + field, Metadata, }; /// A handle representing a span, with the capability to enter the span if it @@ -171,28 +169,6 @@ pub struct Span<'a> { is_closed: bool, } -/// `Event`s represent single points in time where something occurred during the -/// execution of a program. -/// -/// An event can be compared to a log record in unstructured logging, but with -/// two key differences: -/// - Events exist _within the context of a [`Span`]_. Unlike log lines, they may -/// be located within the trace tree, allowing visibility into the context in -/// which the event occurred. -/// - Events have structured key-value data known as _fields_, as well as a -/// textual message. In general, a majority of the data associated with an -/// event should be in the event's fields rather than in the textual message, -/// as the fields are more structed. -/// -/// [`Span`]: ::span::Span -#[derive(PartialEq, Hash)] -pub struct Event<'a> { - /// A handle used to enter the span when it is not executing. - /// - /// If this is `None`, then the span has either closed or was never enabled. - inner: Option>, -} - /// A handle representing the capacity to enter a span which is known to exist. /// /// Unlike `Span`, this type is only constructed for spans which _have_ been @@ -233,39 +209,32 @@ struct Entered<'a> { // ===== impl Span ===== impl<'a> Span<'a> { - /// Constructs a new `Span` originating from the given [`Callsite`]. + /// Constructs a new `Span` with the given [metadata] and set of [field values]. /// /// The new span will be constructed by the currently-active [`Subscriber`], - /// with the [current span] as its parent (if one exists). + /// with the current span as its parent (if one exists). /// /// After the span is constructed, [field values] and/or [`follows_from`] /// annotations may be added to it. /// - /// [`Callsite`]: ::callsite::Callsite + /// [metadata]: ::metadata::Metadata /// [`Subscriber`]: ::subscriber::Subscriber - /// [current span]: ::span::Span::current - /// [field values]: ::span::Span::record + /// [field values]: ::field::ValueSet /// [`follows_from`]: ::span::Span::follows_from #[inline] - pub fn new(interest: Interest, meta: &'a Metadata<'a>) -> Span<'a> { - if interest.is_never() { - return Self::new_disabled(); + pub fn new(meta: &'a Metadata<'a>, values: &field::ValueSet) -> Span<'a> { + let inner = dispatcher::with(move |dispatch| { + let id = dispatch.new_span(meta, values); + Some(Enter::new(id, dispatch, meta)) + }); + Self { + inner, + is_closed: false, } - dispatcher::with(|dispatch| { - if interest.is_sometimes() && !dispatch.enabled(meta) { - return Span::new_disabled(); - } - let id = dispatch.new_span(meta); - let inner = Some(Enter::new(id, dispatch, meta)); - Self { - inner, - is_closed: false, - } - }) } /// Constructs a new disabled span. - #[inline] + #[inline(always)] pub fn new_disabled() -> Span<'a> { Span { inner: None, @@ -316,13 +285,24 @@ impl<'a> Span<'a> { } /// Records that the field described by `field` has the value `value`. - pub fn record(&mut self, field: &Q, value: &V) -> &mut Self + pub fn record(&mut self, field: &Q, value: &V) -> &mut Self where Q: field::AsField, V: field::Value, { if let Some(ref mut inner) = self.inner { - value.record(field, inner); + let meta = inner.metadata(); + if let Some(field) = field.as_field(meta) { + inner.record(&meta.fields().value_set(&[(&field, Some(value))])) + } + } + self + } + + /// Record all the fields in the span + pub fn record_all(&mut self, values: &field::ValueSet) -> &mut Self { + if let Some(ref mut inner) = self.inner { + inner.record(&values); } self } @@ -366,7 +346,7 @@ impl<'a> Span<'a> { /// /// If this span is disabled, or the resulting follows-from relationship /// would be invalid, this function will do nothing. - pub fn follows_from(&self, from: Id) -> &Self { + pub fn follows_from(&self, from: &Id) -> &Self { if let Some(ref inner) = self.inner { inner.follows_from(from); } @@ -396,125 +376,6 @@ impl<'a> fmt::Debug for Span<'a> { } } -// ===== impl Event ===== - -impl<'a> Event<'a> { - /// Constructs a new `Event` originating from the given [`Callsite`]. - /// - /// The new span will be constructed by the currently-active [`Subscriber`], - /// with the [current span] as its parent (if one exists). - /// - /// After the event is constructed, [field values] and/or [`follows_from`] - /// annotations may be added to it. - /// - /// [`Callsite`]: ::callsite::Callsite - /// [`Subscriber`]: ::subscriber::Subscriber - /// [current span]: ::span::Span::current - /// [field values]: ::span::Evemt::record - /// [`follows_from`]: ::span::Event::follows_from - #[inline] - pub fn new(interest: Interest, meta: &'a Metadata<'a>) -> Self { - if interest.is_never() { - return Self::new_disabled(); - } - dispatcher::with(|dispatch| { - if interest.is_sometimes() && !dispatch.enabled(meta) { - return Self::new_disabled(); - } - let id = dispatch.new_span(meta); - let inner = Enter::new(id, dispatch, meta); - Self { inner: Some(inner) } - }) - } - - /// Returns a new disabled `Event`. - #[inline] - pub fn new_disabled() -> Self { - Self { - inner: None, - } - } - - /// Adds a formattable message describing the event that occurred. - pub fn message(&mut self, key: &field::Field, message: fmt::Arguments) -> &mut Self { - if let Some(ref mut inner) = self.inner { - inner.subscriber.record_debug(&inner.id, key, &message); - } - self - } - - /// Returns a [`Field`](::field::Field) for the field with the given `name`, if - /// one exists, - pub fn field(&self, name: &Q) -> Option - where - Q: Borrow, - { - self.inner - .as_ref() - .and_then(|inner| inner.meta.fields().field(name)) - } - - /// Returns true if this `Event` has a field for the given - /// [`Field`](::field::Field) or field name. - pub fn has_field(&self, field: &Q) -> bool - where - Q: field::AsField, - { - self.metadata() - .and_then(|meta| field.as_field(meta)) - .is_some() - } - - /// Records that the field described by `field` has the value `value`. - pub fn record(&mut self, field: &Q, value: &V) -> &mut Self - where - Q: field::AsField, - V: field::Value, - { - if let Some(ref mut inner) = self.inner { - value.record(field, inner); - } - self - } - - /// Returns `true` if this span was disabled by the subscriber and does not - /// exist. - pub fn is_disabled(&self) -> bool { - self.inner.is_none() - } - - /// Indicates that the span with the given ID has an indirect causal - /// relationship with this event. - /// - /// This relationship differs somewhat from the parent-child relationship: a - /// span may have any number of prior spans, rather than a single one; and - /// spans are not considered to be executing _inside_ of the spans they - /// follow from. This means that a span may close even if subsequent spans - /// that follow from it are still open, and time spent inside of a - /// subsequent span should not be included in the time its precedents were - /// executing. This is used to model causal relationships such as when a - /// single future spawns several related background tasks, et cetera. - /// - /// If this event is disabled, or the resulting follows-from relationship - /// would be invalid, this function will do nothing. - pub fn follows_from(&self, from: Id) -> &Self { - if let Some(ref inner) = self.inner { - inner.follows_from(from); - } - self - } - - /// Returns this span's `Id`, if it is enabled. - pub fn id(&self) -> Option { - self.inner.as_ref().map(Enter::id) - } - - /// Returns this span's `Metadata`, if it is enabled. - pub fn metadata(&self) -> Option<&'a Metadata<'a>> { - self.inner.as_ref().map(|inner| inner.metadata()) - } -} - // ===== impl Enter ===== impl<'a> Enter<'a> { @@ -552,8 +413,8 @@ impl<'a> Enter<'a> { /// If this span is disabled, this function will do nothing. Otherwise, it /// returns `Ok(())` if the other span was added as a precedent of this /// span, or an error if this was not possible. - fn follows_from(&self, from: Id) { - self.subscriber.add_follows_from(&self.id, from) + fn follows_from(&self, from: &Id) { + self.subscriber.record_follows_from(&self.id, &from) } /// Returns the span's ID. @@ -566,29 +427,10 @@ impl<'a> Enter<'a> { self.meta } - /// Record a signed 64-bit integer value. - fn record_value_i64(&self, field: &field::Field, value: i64) { - self.subscriber.record_i64(&self.id, field, value) - } - - /// Record an unsigned 64-bit integer value. - fn record_value_u64(&self, field: &field::Field, value: u64) { - self.subscriber.record_u64(&self.id, field, value) - } - - /// Record a boolean value. - fn record_value_bool(&self, field: &field::Field, value: bool) { - self.subscriber.record_bool(&self.id, field, value) - } - - /// Record a string value. - fn record_value_str(&self, field: &field::Field, value: &str) { - self.subscriber.record_str(&self.id, field, value) - } - - /// Record a value implementing `fmt::Debug`. - fn record_value_debug(&self, field: &field::Field, value: &fmt::Debug) { - self.subscriber.record_debug(&self.id, field, value) + fn record(&mut self, values: &field::ValueSet) { + if values.callsite() == self.meta.callsite() { + self.subscriber.record(&self.id, &values) + } } fn new(id: Id, subscriber: &Dispatch, meta: &'a Metadata<'a>) -> Self { @@ -630,60 +472,6 @@ impl<'a> Clone for Enter<'a> { } } -impl<'a> ::sealed::Sealed for Enter<'a> {} - -impl<'a> field::Record for Enter<'a> { - #[inline] - fn record_i64(&mut self, field: &Q, value: i64) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_i64(&key, value); - } - } - - #[inline] - fn record_u64(&mut self, field: &Q, value: u64) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_u64(&key, value); - } - } - - #[inline] - fn record_bool(&mut self, field: &Q, value: bool) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_bool(&key, value); - } - } - - #[inline] - fn record_str(&mut self, field: &Q, value: &str) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_str(&key, value); - } - } - - #[inline] - fn record_debug(&mut self, field: &Q, value: &fmt::Debug) - where - Q: field::AsField, - { - if let Some(key) = field.as_field(self.metadata()) { - self.record_value_debug(&key, value); - } - } -} - // ===== impl Entered ===== impl<'a> Entered<'a> { diff --git a/tokio-trace/tests/event.rs b/tokio-trace/tests/event.rs new file mode 100644 index 00000000000..e5fcd81812f --- /dev/null +++ b/tokio-trace/tests/event.rs @@ -0,0 +1,169 @@ +#[macro_use] +extern crate tokio_trace; +mod support; + +use self::support::*; + +use tokio_trace::{ + field::{debug, display}, + subscriber::with_default, + Level, +}; + +#[test] +fn event_without_message() { + let (subscriber, handle) = subscriber::mock() + .event( + event::mock().with_fields( + field::mock("answer") + .with_value(&42) + .and( + field::mock("to_question") + .with_value(&"life, the universe, and everything"), + ) + .only(), + ), + ) + .done() + .run_with_handle(); + + with_default(subscriber, || { + info!( + answer = 42, + to_question = "life, the universe, and everything" + ); + }); + + handle.assert_finished(); +} + +#[test] +fn event_with_message() { + let (subscriber, handle) = subscriber::mock() + .event(event::mock().with_fields(field::mock("message").with_value( + &tokio_trace::field::debug(format_args!( + "hello from my event! yak shaved = {:?}", + true + )), + ))) + .done() + .run_with_handle(); + + with_default(subscriber, || { + debug!("hello from my event! yak shaved = {:?}", true); + }); + + handle.assert_finished(); +} + +#[test] +fn one_with_everything() { + let (subscriber, handle) = subscriber::mock() + .event( + event::mock() + .with_fields( + field::mock("message") + .with_value(&tokio_trace::field::debug(format_args!( + "{:#x} make me one with{what:.>20}", + 4277009102u64, + what = "everything" + ))) + .and(field::mock("foo").with_value(&666)) + .and(field::mock("bar").with_value(&false)) + .only(), + ) + .at_level(tokio_trace::Level::ERROR) + .with_target("whatever"), + ) + .done() + .run_with_handle(); + + with_default(subscriber, || { + event!( + target: "whatever", + tokio_trace::Level::ERROR, + { foo = 666, bar = false }, + "{:#x} make me one with{what:.>20}", 4277009102u64, what = "everything" + ); + }); + + handle.assert_finished(); +} + +#[test] +fn moved_field() { + let (subscriber, handle) = subscriber::mock() + .event( + event::mock().with_fields( + field::mock("foo") + .with_value(&display("hello from my event")) + .only(), + ), + ) + .done() + .run_with_handle(); + with_default(subscriber, || { + let from = "my event"; + event!(Level::INFO, foo = display(format!("hello from {}", from))) + }); + + handle.assert_finished(); +} + +#[test] +fn borrowed_field() { + let (subscriber, handle) = subscriber::mock() + .event( + event::mock().with_fields( + field::mock("foo") + .with_value(&display("hello from my event")) + .only(), + ), + ) + .done() + .run_with_handle(); + with_default(subscriber, || { + let from = "my event"; + let mut message = format!("hello from {}", from); + event!(Level::INFO, foo = display(&message)); + message.push_str(", which happened!"); + }); + + handle.assert_finished(); +} + +#[test] +fn move_field_out_of_struct() { + #[derive(Debug)] + struct Position { + x: f32, + y: f32, + } + + let pos = Position { + x: 3.234, + y: -1.223, + }; + let (subscriber, handle) = subscriber::mock() + .event( + event::mock().with_fields( + field::mock("x") + .with_value(&debug(3.234)) + .and(field::mock("y").with_value(&debug(-1.223))) + .only(), + ), + ) + .event(event::mock().with_fields(field::mock("position").with_value(&debug(&pos)))) + .done() + .run_with_handle(); + + with_default(subscriber, || { + let pos = Position { + x: 3.234, + y: -1.223, + }; + debug!(x = debug(pos.x), y = debug(pos.y)); + debug!(target: "app_events", { position = debug(pos) }, "New position"); + }); + handle.assert_finished(); +} diff --git a/tokio-trace/tests/span.rs b/tokio-trace/tests/span.rs index 4460790ec96..f7764cf9f2d 100644 --- a/tokio-trace/tests/span.rs +++ b/tokio-trace/tests/span.rs @@ -4,7 +4,11 @@ mod support; use self::support::*; use std::thread; -use tokio_trace::{dispatcher, Dispatch, Level, Span}; +use tokio_trace::{ + dispatcher, + field::{debug, display}, + Dispatch, Level, Span, +}; #[test] fn closed_handle_cannot_be_entered() { @@ -146,7 +150,7 @@ fn dropping_a_span_calls_drop_span() { fn span_closes_after_event() { let (subscriber, handle) = subscriber::mock() .enter(span::mock().named("foo")) - .event() + .event(event::mock()) .exit(span::mock().named("foo")) .drop_span(span::mock().named("foo")) .done() @@ -164,7 +168,7 @@ fn span_closes_after_event() { fn new_span_after_event() { let (subscriber, handle) = subscriber::mock() .enter(span::mock().named("foo")) - .event() + .event(event::mock()) .exit(span::mock().named("foo")) .drop_span(span::mock().named("foo")) .enter(span::mock().named("bar")) @@ -185,7 +189,7 @@ fn new_span_after_event() { #[test] fn event_outside_of_span() { let (subscriber, handle) = subscriber::mock() - .event() + .event(event::mock()) .enter(span::mock().named("foo")) .exit(span::mock().named("foo")) .drop_span(span::mock().named("foo")) @@ -303,3 +307,152 @@ fn entering_a_closed_span_again_is_a_no_op() { handle.assert_finished(); } + +#[test] +fn moved_field() { + let (subscriber, handle) = subscriber::mock() + .new_span( + span::mock().named("foo").with_field( + field::mock("bar") + .with_value(&display("hello from my span")) + .only(), + ), + ) + .enter(span::mock().named("foo")) + .exit(span::mock().named("foo")) + .drop_span(span::mock().named("foo")) + .done() + .run_with_handle(); + dispatcher::with_default(Dispatch::new(subscriber), || { + let from = "my span"; + let mut span = span!("foo", bar = display(format!("hello from {}", from))); + span.enter(|| {}); + }); + + handle.assert_finished(); +} + +#[test] +fn borrowed_field() { + let (subscriber, handle) = subscriber::mock() + .new_span( + span::mock().named("foo").with_field( + field::mock("bar") + .with_value(&display("hello from my span")) + .only(), + ), + ) + .enter(span::mock().named("foo")) + .exit(span::mock().named("foo")) + .drop_span(span::mock().named("foo")) + .done() + .run_with_handle(); + + dispatcher::with_default(Dispatch::new(subscriber), || { + let from = "my span"; + let mut message = format!("hello from {}", from); + let mut span = span!("foo", bar = display(&message)); + span.enter(|| { + message.insert_str(10, " inside"); + }); + }); + + handle.assert_finished(); +} + +#[test] +fn move_field_out_of_struct() { + #[derive(Debug)] + struct Position { + x: f32, + y: f32, + } + + let pos = Position { + x: 3.234, + y: -1.223, + }; + let (subscriber, handle) = subscriber::mock() + .new_span( + span::mock().named("foo").with_field( + field::mock("x") + .with_value(&debug(3.234)) + .and(field::mock("y").with_value(&debug(-1.223))) + .only(), + ), + ) + .new_span( + span::mock() + .named("bar") + .with_field(field::mock("position").with_value(&debug(&pos)).only()), + ) + .run_with_handle(); + + dispatcher::with_default(Dispatch::new(subscriber), || { + let pos = Position { + x: 3.234, + y: -1.223, + }; + let mut foo = span!("foo", x = debug(pos.x), y = debug(pos.y)); + let mut bar = span!("bar", position = debug(pos)); + foo.enter(|| {}); + bar.enter(|| {}); + }); + + handle.assert_finished(); +} + +#[test] +fn add_field_after_new_span() { + let (subscriber, handle) = subscriber::mock() + .new_span( + span::mock() + .named("foo") + .with_field(field::mock("bar").with_value(&5).only()), + ) + .record( + span::mock().named("foo"), + field::mock("baz").with_value(&true).only(), + ) + .enter(span::mock().named("foo")) + .exit(span::mock().named("foo")) + .drop_span(span::mock().named("foo")) + .done() + .run_with_handle(); + + dispatcher::with_default(Dispatch::new(subscriber), || { + let mut span = span!("foo", bar = 5, baz); + span.record("baz", &true); + span.enter(|| {}) + }); + + handle.assert_finished(); +} + +#[test] +fn add_fields_only_after_new_span() { + let (subscriber, handle) = subscriber::mock() + .new_span(span::mock().named("foo")) + .record( + span::mock().named("foo"), + field::mock("bar").with_value(&5).only(), + ) + .record( + span::mock().named("foo"), + field::mock("baz").with_value(&true).only(), + ) + .enter(span::mock().named("foo")) + .exit(span::mock().named("foo")) + .drop_span(span::mock().named("foo")) + .done() + .run_with_handle(); + + dispatcher::with_default(Dispatch::new(subscriber), || { + let mut span = span!("foo", bar, baz); + span.record("bar", &5); + span.record("baz", &true); + span.enter(|| {}) + }); + + handle.assert_finished(); +} diff --git a/tokio-trace/tests/support/event.rs b/tokio-trace/tests/support/event.rs new file mode 100644 index 00000000000..5dbe2b235f3 --- /dev/null +++ b/tokio-trace/tests/support/event.rs @@ -0,0 +1,92 @@ +#![allow(missing_docs)] +use super::{field, metadata}; + +use std::fmt; + +/// A mock event. +/// +/// This is intended for use with the mock subscriber API in the +/// `subscriber` module. +#[derive(Debug, Default, Eq, PartialEq)] +pub struct MockEvent { + pub fields: Option, + metadata: metadata::Expect, +} + +pub fn mock() -> MockEvent { + MockEvent { + ..Default::default() + } +} + +impl MockEvent { + pub fn named(self, name: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + name: Some(name.into()), + ..self.metadata + }, + ..self + } + } + + pub fn with_fields(self, fields: I) -> Self + where + I: Into, + { + Self { + fields: Some(fields.into()), + ..self + } + } + + pub fn at_level(self, level: tokio_trace::Level) -> Self { + Self { + metadata: metadata::Expect { + level: Some(level), + ..self.metadata + }, + ..self + } + } + + pub fn with_target(self, target: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + target: Some(target.into()), + ..self.metadata + }, + ..self + } + } + + pub(in support) fn check(self, event: &tokio_trace::Event) { + let meta = event.metadata(); + let name = meta.name(); + self.metadata.check(meta, format_args!("event {}", name)); + if let Some(mut expected_fields) = self.fields { + let mut checker = expected_fields.checker(format!("{}", name)); + event.record(&mut checker); + checker.finish(); + } + } +} + +impl fmt::Display for MockEvent { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "an event")?; + if let Some(ref name) = self.metadata.name { + write!(f, " named {:?}", name)?; + } + if let Some(ref fields) = self.fields { + write!(f, " with {}", fields)? + } + Ok(()) + } +} diff --git a/tokio-trace/tests/support/field.rs b/tokio-trace/tests/support/field.rs new file mode 100644 index 00000000000..578452b0b96 --- /dev/null +++ b/tokio-trace/tests/support/field.rs @@ -0,0 +1,224 @@ +use tokio_trace::{ + callsite::Callsite, + field::{self, Field, Record, Value}, +}; + +use std::{collections::HashMap, fmt}; + +#[derive(Default, Debug, Eq, PartialEq)] +pub struct Expect { + fields: HashMap, + only: bool, +} + +#[derive(Debug)] +pub struct MockField { + name: String, + value: MockValue, +} + +#[derive(Debug, Eq, PartialEq)] +pub enum MockValue { + I64(i64), + U64(u64), + Bool(bool), + Str(String), + Debug(String), + Any, +} + +pub fn mock(name: K) -> MockField +where + String: From, +{ + MockField { + name: name.into(), + value: MockValue::Any, + } +} + +impl MockField { + /// Expect a field with the given name and value. + pub fn with_value(self, value: &Value) -> Self { + Self { + value: MockValue::from(value), + ..self + } + } + + pub fn and(self, other: MockField) -> Expect { + Expect { + fields: HashMap::new(), + only: false, + } + .and(self) + .and(other) + } + + pub fn only(self) -> Expect { + Expect { + fields: HashMap::new(), + only: true, + } + .and(self) + } +} + +impl Into for MockField { + fn into(self) -> Expect { + Expect { + fields: HashMap::new(), + only: false, + } + .and(self) + } +} + +impl Expect { + pub fn and(mut self, field: MockField) -> Self { + self.fields.insert(field.name, field.value); + self + } + + /// Indicates that no fields other than those specified should be expected. + pub fn only(self) -> Self { + Self { only: true, ..self } + } + + fn compare_or_panic(&mut self, name: &str, value: &Value, ctx: &str) { + let value = value.into(); + match self.fields.remove(name) { + Some(MockValue::Any) => {} + Some(expected) => assert!( + expected == value, + "\nexpected `{}` to contain:\n\t`{}{}`\nbut got:\n\t`{}{}`", + ctx, + name, + expected, + name, + value + ), + None if self.only => panic!( + "\nexpected `{}` to contain only:\n\t`{}`\nbut got:\n\t`{}{}`", + ctx, self, name, value + ), + _ => {} + } + } + + pub fn checker<'a>(&'a mut self, ctx: String) -> CheckRecorder<'a> { + CheckRecorder { expect: self, ctx } + } + + pub fn is_empty(&self) -> bool { + self.fields.is_empty() + } +} + +impl fmt::Display for MockValue { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + match self { + MockValue::I64(v) => write!(f, ": i64 = {:?}", v), + MockValue::U64(v) => write!(f, ": u64 = {:?}", v), + MockValue::Bool(v) => write!(f, ": bool = {:?}", v), + MockValue::Str(v) => write!(f, ": &str = {:?}", v), + MockValue::Debug(v) => write!(f, ": &fmt::Debug = {:?}", v), + MockValue::Any => write!(f, ": _ = _"), + } + } +} + +pub struct CheckRecorder<'a> { + expect: &'a mut Expect, + ctx: String, +} + +impl<'a> Record for CheckRecorder<'a> { + fn record_i64(&mut self, field: &Field, value: i64) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_u64(&mut self, field: &Field, value: u64) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_bool(&mut self, field: &Field, value: bool) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.expect + .compare_or_panic(field.name(), &field::debug(value), &self.ctx) + } +} + +impl<'a> CheckRecorder<'a> { + pub fn finish(self) { + assert!( + self.expect.fields.is_empty(), + "{}missing {}", + self.expect, + self.ctx + ); + } +} + +impl<'a> From<&'a Value> for MockValue { + fn from(value: &'a Value) -> Self { + struct MockValueBuilder { + value: Option, + } + + impl Record for MockValueBuilder { + fn record_i64(&mut self, _: &Field, value: i64) { + self.value = Some(MockValue::I64(value)); + } + + fn record_u64(&mut self, _: &Field, value: u64) { + self.value = Some(MockValue::U64(value)); + } + + fn record_bool(&mut self, _: &Field, value: bool) { + self.value = Some(MockValue::Bool(value)); + } + + fn record_str(&mut self, _: &Field, value: &str) { + self.value = Some(MockValue::Str(value.to_owned())); + } + + fn record_debug(&mut self, _: &Field, value: &fmt::Debug) { + self.value = Some(MockValue::Debug(format!("{:?}", value))); + } + } + + let fake_field = callsite!(name: "fake", fields: fake_field) + .metadata() + .fields() + .field("fake_field") + .unwrap(); + let mut builder = MockValueBuilder { value: None }; + value.record(&fake_field, &mut builder); + builder + .value + .expect("finish called before a value was recorded") + } +} + +impl fmt::Display for Expect { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "fields ")?; + let entries = self + .fields + .iter() + .map(|(k, v)| (field::display(k), field::display(v))); + f.debug_map().entries(entries).finish() + } +} diff --git a/tokio-trace/tests/support/metadata.rs b/tokio-trace/tests/support/metadata.rs new file mode 100644 index 00000000000..502c04e44e8 --- /dev/null +++ b/tokio-trace/tests/support/metadata.rs @@ -0,0 +1,64 @@ +use std::fmt; +use tokio_trace::Metadata; + +#[derive(Debug, Eq, PartialEq, Default)] +pub struct Expect { + pub name: Option, + pub level: Option, + pub target: Option, +} + +impl Expect { + pub(in support) fn check(&self, actual: &Metadata, ctx: fmt::Arguments) { + if let Some(ref expected_name) = self.name { + let name = actual.name(); + assert!( + expected_name == name, + "expected {} to be named `{}`, but got one named `{}`", + ctx, + expected_name, + name + ) + } + + if let Some(ref expected_level) = self.level { + let level = actual.level(); + assert!( + expected_level == level, + "expected {} to be at level `{:?}`, but it was at level `{:?}` instead", + ctx, + expected_level, + level, + ) + } + + if let Some(ref expected_target) = self.target { + let target = actual.target(); + assert!( + expected_target == &target, + "expected {} to have target `{}`, but it had target `{}` instead", + ctx, + expected_target, + target, + ) + } + } +} + +impl fmt::Display for Expect { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + if let Some(ref name) = self.name { + write!(f, "named `{}`", name)?; + } + + if let Some(ref level) = self.level { + write!(f, " at the `{:?}` level", level)?; + } + + if let Some(ref target) = self.target { + write!(f, " with target `{}`", target)?; + } + + Ok(()) + } +} diff --git a/tokio-trace/tests/support/mod.rs b/tokio-trace/tests/support/mod.rs index 919f6af49aa..b8f78cc7a29 100644 --- a/tokio-trace/tests/support/mod.rs +++ b/tokio-trace/tests/support/mod.rs @@ -1,3 +1,6 @@ #![allow(dead_code)] +pub mod event; +pub mod field; +mod metadata; pub mod span; pub mod subscriber; diff --git a/tokio-trace/tests/support/span.rs b/tokio-trace/tests/support/span.rs index f72e59f12df..e1e738780c3 100644 --- a/tokio-trace/tests/support/span.rs +++ b/tokio-trace/tests/support/span.rs @@ -1,4 +1,5 @@ #![allow(missing_docs)] +use super::{field, metadata}; use std::fmt; /// A mock span. @@ -7,8 +8,13 @@ use std::fmt; /// `subscriber` module. #[derive(Debug, Default, Eq, PartialEq)] pub struct MockSpan { - pub name: Option<&'static str>, - // TODO: more + pub(in support) metadata: metadata::Expect, +} + +#[derive(Debug, Default, Eq, PartialEq)] +pub struct NewSpan { + pub(in support) span: MockSpan, + pub(in support) fields: field::Expect, } pub fn mock() -> MockSpan { @@ -18,19 +24,86 @@ pub fn mock() -> MockSpan { } impl MockSpan { - pub fn named(mut self, name: &'static str) -> Self { - self.name = Some(name); - self + pub fn named(self, name: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + name: Some(name.into()), + ..self.metadata + }, + ..self + } + } + + pub fn at_level(self, level: tokio_trace::Level) -> Self { + Self { + metadata: metadata::Expect { + level: Some(level), + ..self.metadata + }, + ..self + } } - // TODO: fields, etc + pub fn with_target(self, target: I) -> Self + where + I: Into, + { + Self { + metadata: metadata::Expect { + target: Some(target.into()), + ..self.metadata + }, + ..self + } + } + + pub fn name(&self) -> Option<&str> { + self.metadata.name.as_ref().map(String::as_ref) + } + + pub fn with_field(self, fields: I) -> NewSpan + where + I: Into, + { + NewSpan { + span: self, + fields: fields.into(), + } + } + + pub(in support) fn check_metadata(&self, actual: &tokio_trace::Metadata) { + self.metadata.check(actual, format_args!("span {}", self)) + } } impl fmt::Display for MockSpan { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - match self.name { - Some(name) => write!(f, "a span named {:?}", name), - None => write!(f, "any span"), + if self.metadata.name.is_some() { + write!(f, "a span{}", self.metadata) + } else { + write!(f, "any span{}", self.metadata) + } + } +} + +impl Into for MockSpan { + fn into(self) -> NewSpan { + NewSpan { + span: self, + ..Default::default() + } + } +} + +impl fmt::Display for NewSpan { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + write!(f, "a new span{}", self.span.metadata)?; + if !self.fields.is_empty() { + write!(f, " with {}", self.fields)?; } + Ok(()) } } diff --git a/tokio-trace/tests/support/subscriber.rs b/tokio-trace/tests/support/subscriber.rs index 3b4c10b69a0..662e0cc3979 100644 --- a/tokio-trace/tests/support/subscriber.rs +++ b/tokio-trace/tests/support/subscriber.rs @@ -1,5 +1,9 @@ #![allow(missing_docs)] -use super::span::MockSpan; +use super::{ + event::MockEvent, + field as mock_field, + span::{MockSpan, NewSpan}, +}; use std::{ collections::{HashMap, VecDeque}, fmt, @@ -8,21 +12,17 @@ use std::{ Arc, Mutex, }, }; -use tokio_trace::{field, Id, Metadata, Subscriber}; - -#[derive(Debug, Eq, PartialEq)] -struct ExpectEvent { - // TODO: implement -} +use tokio_trace::{field, Event, Id, Metadata, Subscriber}; #[derive(Debug, Eq, PartialEq)] enum Expect { - #[allow(dead_code)] // TODO: implement! - Event(ExpectEvent), + Event(MockEvent), Enter(MockSpan), Exit(MockSpan), CloneSpan(MockSpan), DropSpan(MockSpan), + Record(MockSpan, mock_field::Expect), + NewSpan(NewSpan), Nothing, } @@ -58,9 +58,8 @@ impl bool> MockSubscriber { self } - pub fn event(mut self) -> Self { - // TODO: expect message/fields! - self.expected.push_back(Expect::Event(ExpectEvent {})); + pub fn event(mut self, event: MockEvent) -> Self { + self.expected.push_back(Expect::Event(event)); self } @@ -84,6 +83,22 @@ impl bool> MockSubscriber { self } + pub fn record(mut self, span: MockSpan, fields: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::Record(span, fields.into())); + self + } + + pub fn new_span(mut self, new_span: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::NewSpan(new_span.into())); + self + } + pub fn with_filter(self, filter: G) -> MockSubscriber where G: Fn(&Metadata) -> bool, @@ -117,15 +132,47 @@ impl bool> Subscriber for Running { (self.filter)(meta) } - fn record_debug(&self, _span: &Id, _field: &field::Field, _value: &fmt::Debug) { - // TODO: it would be nice to be able to expect field values... + fn record(&self, id: &Id, values: &field::ValueSet) { + let spans = self.spans.lock().unwrap(); + let mut expected = self.expected.lock().unwrap(); + let span = spans + .get(id) + .unwrap_or_else(|| panic!("no span for ID {:?}", id)); + println!("record: {}; id={:?}; values={:?};", span.name, id, values); + let was_expected = if let Some(Expect::Record(_, _)) = expected.front() { + true + } else { + false + }; + if was_expected { + if let Expect::Record(expected_span, mut expected_values) = + expected.pop_front().unwrap() + { + if let Some(name) = expected_span.name() { + assert_eq!(name, span.name); + } + let mut checker = expected_values.checker(format!("span {}: ", span.name)); + values.record(&mut checker); + checker.finish(); + } + } } - fn add_follows_from(&self, _span: &Id, _follows: Id) { + fn event(&self, event: &Event) { + let name = event.metadata().name(); + println!("event: {};", name); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Event(expected)) => expected.check(event), + Some(ex) => ex.bad(format_args!("observed event {:?}", event)), + } + } + + fn record_follows_from(&self, _span: &Id, _follows: &Id) { // TODO: it should be possible to expect spans to follow from other spans } - fn new_span(&self, meta: &Metadata) -> Id { + fn new_span(&self, meta: &Metadata, values: &field::ValueSet) -> Id { let id = self.ids.fetch_add(1, Ordering::SeqCst); let id = Id::from_u64(id as u64); println!( @@ -134,6 +181,23 @@ impl bool> Subscriber for Running { meta.target(), id ); + let mut expected = self.expected.lock().unwrap(); + let was_expected = match expected.front() { + Some(Expect::NewSpan(_)) => true, + _ => false, + }; + if was_expected { + if let Expect::NewSpan(mut expected) = expected.pop_front().unwrap() { + let name = meta.name(); + expected + .span + .metadata + .check(meta, format_args!("span `{}`", name)); + let mut checker = expected.fields.checker(format!("{}", name)); + values.record(&mut checker); + checker.finish(); + } + } self.spans.lock().unwrap().insert( id.clone(), SpanState { @@ -150,32 +214,12 @@ impl bool> Subscriber for Running { println!("enter: {}; id={:?};", span.name, id); match self.expected.lock().unwrap().pop_front() { None => {} - Some(Expect::Event(_)) => panic!( - "expected an event, but entered span {:?} instead", - span.name - ), Some(Expect::Enter(ref expected_span)) => { - if let Some(name) = expected_span.name { + if let Some(name) = expected_span.name() { assert_eq!(name, span.name); } - // TODO: expect fields } - Some(Expect::Exit(ref expected_span)) => panic!( - "expected to exit {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::CloneSpan(ref expected_span)) => panic!( - "expected to clone {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::DropSpan(ref expected_span)) => panic!( - "expected to drop {}, but entered span {:?} instead", - expected_span, span.name - ), - Some(Expect::Nothing) => panic!( - "expected nothing else to happen, but entered span {:?}", - span.name, - ), + Some(ex) => ex.bad(format_args!("entered span {:?}", span.name)), } }; } @@ -188,31 +232,12 @@ impl bool> Subscriber for Running { println!("exit: {}; id={:?};", span.name, id); match self.expected.lock().unwrap().pop_front() { None => {} - Some(Expect::Event(_)) => { - panic!("expected an event, but exited span {:?} instead", span.name) - } - Some(Expect::Enter(ref expected_span)) => panic!( - "expected to enter {}, but exited span {:?} instead", - expected_span, span.name - ), Some(Expect::Exit(ref expected_span)) => { - if let Some(name) = expected_span.name { + if let Some(name) = expected_span.name() { assert_eq!(name, span.name); } - // TODO: expect fields } - Some(Expect::CloneSpan(ref expected_span)) => panic!( - "expected to clone {}, but exited span {:?} instead", - expected_span, span.name - ), - Some(Expect::DropSpan(ref expected_span)) => panic!( - "expected to drop {}, but exited span {:?} instead", - expected_span, span.name - ), - Some(Expect::Nothing) => panic!( - "expected nothing else to happen, but exited span {:?}", - span.name, - ), + Some(ex) => ex.bad(format_args!("exited span {:?}", span.name)), }; } @@ -228,7 +253,7 @@ impl bool> Subscriber for Running { } let mut expected = self.expected.lock().unwrap(); let was_expected = if let Some(Expect::CloneSpan(ref span)) = expected.front() { - assert_eq!(name, span.name); + assert_eq!(name, span.name()); true } else { false @@ -263,7 +288,7 @@ impl bool> Subscriber for Running { // Don't assert if this function was called while panicking, // as failing the assertion can cause a double panic. if !::std::thread::panicking() { - assert_eq!(name, span.name); + assert_eq!(name, span.name()); } true } @@ -293,3 +318,20 @@ impl MockHandle { } } } + +impl Expect { + fn bad<'a>(&self, what: fmt::Arguments<'a>) { + match self { + Expect::Event(e) => panic!("expected event {}, but {} instead", e, what,), + Expect::Enter(e) => panic!("expected to enter {} but {} instead", e, what,), + Expect::Exit(e) => panic!("expected to exit {} but {} instead", e, what,), + Expect::CloneSpan(e) => panic!("expected to clone {} but {} instead", e, what,), + Expect::DropSpan(e) => panic!("expected to drop {} but {} instead", e, what,), + Expect::Record(e, fields) => { + panic!("expected {} to record {} but {} instead", e, fields, what,) + } + Expect::NewSpan(e) => panic!("expected {} but {} instead", e, what), + Expect::Nothing => panic!("expected nothing else to happen, but {} instead", what,), + } + } +} diff --git a/tokio-trace/tokio-trace-core/src/callsite.rs b/tokio-trace/tokio-trace-core/src/callsite.rs index 1401e84089d..4b45aa0e43c 100644 --- a/tokio-trace/tokio-trace-core/src/callsite.rs +++ b/tokio-trace/tokio-trace-core/src/callsite.rs @@ -107,7 +107,7 @@ impl Eq for Identifier {} impl fmt::Debug for Identifier { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - f.pad("Identifier(...)") + write!(f, "Identifier({:p})", self.0) } } diff --git a/tokio-trace/tokio-trace-core/src/dispatcher.rs b/tokio-trace/tokio-trace-core/src/dispatcher.rs index 798d4375947..14ac3478079 100644 --- a/tokio-trace/tokio-trace-core/src/dispatcher.rs +++ b/tokio-trace/tokio-trace-core/src/dispatcher.rs @@ -2,7 +2,7 @@ use { callsite, field, subscriber::{self, Subscriber}, - Metadata, Span, + Event, Metadata, Span, }; use std::{ @@ -106,63 +106,27 @@ impl Dispatch { /// /// [`Span`]: ::span::Span #[inline] - pub fn new_span(&self, metadata: &Metadata) -> Span { - self.subscriber.new_span(metadata) + pub fn new_span(&self, metadata: &Metadata, values: &field::ValueSet) -> Span { + self.subscriber.new_span(metadata, values) } - /// Record a signed 64-bit integer value. + /// Record a set of values on a span. /// - /// This calls the [`record_i64`](::Subscriber::record_i64) + /// This calls the [`record`](::Subscriber::record) /// function on the `Subscriber` that this `Dispatch` forwards to. #[inline] - pub fn record_i64(&self, span: &Span, field: &field::Field, value: i64) { - self.subscriber.record_i64(span, field, value) - } - - /// Record an unsigned 64-bit integer value. - /// - /// This calls the [`record_u64`](::Subscriber::record_u64) - /// function on the `Subscriber` that this `Dispatch` forwards to. - #[inline] - pub fn record_u64(&self, span: &Span, field: &field::Field, value: u64) { - self.subscriber.record_u64(span, field, value) - } - - /// Record a boolean value. - /// - /// This calls the [`record_bool`](::Subscriber::record_bool) - /// function on the `Subscriber` that this `Dispatch` forwards to. - #[inline] - pub fn record_bool(&self, span: &Span, field: &field::Field, value: bool) { - self.subscriber.record_bool(span, field, value) - } - - /// Record a string value. - /// - /// This calls the [`record_str`](::Subscriber::record_str) - /// function on the `Subscriber` that this `Dispatch` forwards to. - #[inline] - pub fn record_str(&self, span: &Span, field: &field::Field, value: &str) { - self.subscriber.record_str(span, field, value) - } - - /// Record a value implementing `fmt::Debug`. - /// - /// This calls the [`record_debug`](::Subscriber::record_debug) - /// function on the `Subscriber` that this `Dispatch` forwards to. - #[inline] - pub fn record_debug(&self, span: &Span, field: &field::Field, value: &fmt::Debug) { - self.subscriber.record_debug(span, field, value) + pub fn record(&self, span: &Span, values: &field::ValueSet) { + self.subscriber.record(span, &values) } /// Adds an indication that `span` follows from the span with the id /// `follows`. /// - /// This calls the [`add_follows_from`](::Subscriber::add_follows_from) + /// This calls the [`record_follows_from`](::Subscriber::record_follows_from) /// function on the `Subscriber` that this `Dispatch` forwards to. #[inline] - pub fn add_follows_from(&self, span: &Span, follows: Span) { - self.subscriber.add_follows_from(span, follows) + pub fn record_follows_from(&self, span: &Span, follows: &Span) { + self.subscriber.record_follows_from(span, follows) } /// Returns true if a span with the specified [metadata] would be @@ -177,6 +141,17 @@ impl Dispatch { self.subscriber.enabled(metadata) } + /// Records that an [`Event`] has occurred. + /// + /// This calls the [`event`](::Subscriber::event) function on + /// the `Subscriber` that this `Dispatch` forwards to. + /// + /// [`Event`]: ::event::Event + #[inline] + pub fn event(&self, event: &Event) { + self.subscriber.event(event) + } + /// Records that a [`Span`] has been entered. /// /// This calls the [`enter`](::Subscriber::enter) function on the @@ -242,13 +217,15 @@ impl Subscriber for NoSubscriber { subscriber::Interest::never() } - fn new_span(&self, _meta: &Metadata) -> Span { + fn new_span(&self, _meta: &Metadata, _vals: &field::ValueSet) -> Span { Span::from_u64(0) } - fn record_debug(&self, _span: &Span, _field: &field::Field, _value: &fmt::Debug) {} + fn event(&self, _event: &Event) {} + + fn record(&self, _span: &Span, _values: &field::ValueSet) {} - fn add_follows_from(&self, _span: &Span, _follows: Span) {} + fn record_follows_from(&self, _span: &Span, _follows: &Span) {} #[inline] fn enabled(&self, _metadata: &Metadata) -> bool { diff --git a/tokio-trace/tokio-trace-core/src/event.rs b/tokio-trace/tokio-trace-core/src/event.rs new file mode 100644 index 00000000000..370260b5458 --- /dev/null +++ b/tokio-trace/tokio-trace-core/src/event.rs @@ -0,0 +1,58 @@ +//! Events represent single points in time during the execution of a program. +use {field, Metadata}; + +/// `Event`s represent single points in time where something occurred during the +/// execution of a program. +/// +/// An `Event` can be compared to a log record in unstructured logging, but with +/// two key differences: +/// - `Event`s exist _within the context of a [`Span`]_. Unlike log lines, they +/// may be located within the trace tree, allowing visibility into the +/// _temporal_ context in which the event occurred, as well as the source +/// code location. +/// - Like spans, `Event`s have structured key-value data known as _fields_, +/// which may include textual message. In general, a majority of the data +/// associated with an event should be in the event's fields rather than in +/// the textual message, as the fields are more structed. +/// +/// [`Span`]: ::span::Span +#[derive(Debug)] +pub struct Event<'a> { + fields: &'a field::ValueSet<'a>, + metadata: &'a Metadata<'a>, +} + +impl<'a> Event<'a> { + /// Constructs a new `Event` with the specified metadata and set of values, + /// and observes it with the current subscriber. + #[inline] + pub fn observe(metadata: &'a Metadata<'a>, fields: &'a field::ValueSet) { + let event = Event { + metadata, + fields, + }; + ::dispatcher::with(|current| { + current.event(&event); + }); + } + + /// Records all the fields on this `Event` with the specified [recorder]. + /// + /// [recorder]: ::field::Record + #[inline] + pub fn record(&self, recorder: &mut field::Record) { + self.fields.record(recorder); + } + + /// Returns a reference to the set of values on this `Event`. + pub fn fields(&self) -> field::Iter { + self.fields.field_set().iter() + } + + /// Returns [metadata] describing this `Event`. + /// + /// [metadata]: ::metadata::Metadata + pub fn metadata(&self) -> &Metadata { + self.metadata + } +} diff --git a/tokio-trace/tokio-trace-core/src/field.rs b/tokio-trace/tokio-trace-core/src/field.rs index a267b1a7a30..45ee028eabd 100644 --- a/tokio-trace/tokio-trace-core/src/field.rs +++ b/tokio-trace/tokio-trace-core/src/field.rs @@ -1,16 +1,19 @@ -//! `Span` key-value data. +//! `Span` and `Event` key-value data. //! -//! Spans may be annotated with key-value data, referred to as known as -//! _fields_. These fields consist of a mapping from a key (corresponding to a -//! `&str` but represented internally as an array index) to a `Value`. +//! Spans and events may be annotated with key-value data, referred to as known +//! as _fields_. These fields consist of a mapping from a key (corresponding to +//! a `&str` but represented internally as an array index) to a `Value`. //! //! # `Value`s and `Subscriber`s //! -//! `Subscriber`s consume `Value`s as fields attached to `Span`s. The set of -//! field keys on a given `Span` or is defined on its `Metadata`. Once the span -//! has been created (i.e., the `new_id` or `new_span` methods on the -//! `Subscriber` have been called), field values may be added by calls to the -//! subscriber's `record_` methods. +//! `Subscriber`s consume `Value`s as fields attached to `Span`s or `Event`s. +//! The set of field keys on a given `Span` or is defined on its `Metadata`. +//! When a `Span` is created, it provides a `ValueSet` to the `Subscriber`'s +//! [`new_span`] method, containing any fields whose values were provided when +//! the span was created; and may call the `Subscriber`'s [`record`] method +//! with additional `ValueSet`s if values are added for more of its fields. +//! Similarly, the [`Event`] type passed to the subscriber's [`event`] method +//! will contain any fields attached to each event. //! //! `tokio_trace` represents values as either one of a set of Rust primitives //! (`i64`, `u64`, `bool`, and `&str`) or using a `fmt::Display` or `fmt::Debug` @@ -18,14 +21,16 @@ //! allow `Subscriber` implementations to provide type-specific behaviour for //! consuming values of each type. //! -//! The `Subscriber` trait provides default implementations of `record_u64`, -//! `record_i64`, `record_bool`, and `record_str` which call the `record_fmt` -//! function, so that only the `record_fmt` function must be implemented. -//! However, implementors of `Subscriber` that wish to consume these primitives -//! as their types may override the `record` methods for any types they care -//! about. For example, we might record integers by incrementing counters for -//! their field names, rather than printing them. +//! Instances of the `Record` trait are provided by `Subscriber`s to record the +//! values attached to `Span`s and `Event`. This trait represents the behavior +//! used to record values of various types. For example, we might record +//! integers by incrementing counters for their field names, rather than printing +//! them. //! +//! [`new_span`]: ::subscriber::Subscriber::new_span +//! [`record`]: ::subscriber::Subscriber::record +//! [`Event`]: ::event::Event +//! [`event`]: ::subscriber::Subscriber::event use callsite; use std::{ borrow::Borrow, @@ -71,6 +76,12 @@ pub struct FieldSet { pub callsite: callsite::Identifier, } +/// A set of fields and values for a span. +pub struct ValueSet<'a> { + values: &'a [(&'a Field, Option<&'a (Value + 'a)>)], + fields: &'a FieldSet, +} + /// An iterator over a set of fields. #[derive(Debug)] pub struct Iter { @@ -78,6 +89,259 @@ pub struct Iter { fields: FieldSet, } +/// Records typed values. +/// +/// An instance of `Record` ("a recorder") represents the logic necessary to +/// record field values of various types. When an implementor of [`Value`] is +/// [recorded], it calls the appropriate method on the provided recorder to +/// indicate the type that value should be recorded as. +/// +/// When a [`Subscriber`] implementation [records an `Event`] or a +/// [set of `Value`s added to a `Span`], it can pass an `&mut Record` to the +/// `record` method on the provided [`ValueSet`] or [`Event`]. This recorder +/// will then be used to record all the field-value pairs present on that +/// `Event` or `ValueSet`. +/// +/// # Examples +/// +/// A simple recorder that writes to a string might be implemented like so: +/// ``` +/// # extern crate tokio_trace_core as tokio_trace; +/// use std::fmt::{self, Write}; +/// use tokio_trace::field::{Value, Record, Field}; +/// # fn main() { +/// pub struct StringRecorder<'a> { +/// string: &'a mut String, +/// } +/// +/// impl<'a> Record for StringRecorder<'a> { +/// fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { +/// write!(self.string, "{} = {:?}; ", field.name(), value).unwrap(); +/// } +/// } +/// # } +/// ``` +/// This recorder will format each recorded value using `fmt::Debug`, and +/// append the field name and formatted value to the provided string, +/// regardless of the type of the recorded value. When all the values have +/// been recorded, the `StringRecorder` may be dropped, allowing the string +/// to be printed or stored in some other data structure. +/// +/// The `Record` trait provides default implementations for `record_i64`, +/// `record_u64`, `record_bool`, and `record_str` which simply forward the +/// recorded value to `record_debug`. Thus, `record_debug` is the only method +/// which a `Record` implementation *must* implement. However, recorders may +/// override the default implementations of these functions in order to +/// implement type-specific behavior. +/// +/// Additionally, when a recorder recieves a value of a type it does not care +/// about, it is free to ignore those values completely. For example, a +/// recorder which only records numeric data might look like this: +/// +/// ``` +/// # extern crate tokio_trace_core as tokio_trace; +/// # use std::fmt::{self, Write}; +/// # use tokio_trace::field::{Value, Record, Field}; +/// # fn main() { +/// pub struct SumRecorder { +/// sum: i64, +/// } +/// +/// impl Record for SumRecorder { +/// fn record_i64(&mut self, _field: &Field, value: i64) { +/// self.sum += value; +/// } +/// +/// fn record_u64(&mut self, _field: &Field, value: u64) { +/// self.sum += value as i64; +/// } +/// +/// fn record_debug(&mut self, _field: &Field, _value: &fmt::Debug) { +/// // Do nothing +/// } +/// } +/// # } +/// ``` +/// +/// This recorder (which is probably not particularly useful) keeps a running +/// sum of all the numeric values it records, and ignores all other values. A +/// more practical example of recording typed values is presented in +/// `examples/counters.rs`, which demonstrates a very simple metrics system +/// implemented using `tokio-trace`. +/// +/// [`Value`]: ::field::Value +/// [recorded]: ::field::Value::record +/// [`Subscriber`]: ::subscriber::Subscriber +/// [records an `Event`]: ::subscriber::Subscriber::event +/// [set of `Value`s added to a `Span`]: ::subscriber::Subscriber::record +/// [`Event`]: ::event::Event +/// [`ValueSet`]: ::field::ValueSet +pub trait Record { + /// Record a signed 64-bit integer value. + fn record_i64(&mut self, field: &Field, value: i64) { + self.record_debug(field, &value) + } + + /// Record an umsigned 64-bit integer value. + fn record_u64(&mut self, field: &Field, value: u64) { + self.record_debug(field, &value) + } + + /// Record a boolean value. + fn record_bool(&mut self, field: &Field, value: bool) { + self.record_debug(field, &value) + } + + /// Record a string value. + fn record_str(&mut self, field: &Field, value: &str) { + self.record_debug(field, &value) + } + + /// Record a value implementing `fmt::Debug`. + fn record_debug(&mut self, field: &Field, value: &fmt::Debug); +} + +/// A field value of an erased type. +/// +/// Implementors of `Value` may call the appropriate typed recording methods on +/// the [recorder] passed to their `record` method in order to indicate how +/// their data should be recorded. +/// +/// [recorder]: ::field::Record +pub trait Value: ::sealed::Sealed { + /// Records this value with the given `Recorder`. + fn record(&self, key: &Field, recorder: &mut Record); +} + +/// A `Value` which serializes as a string using `fmt::Display`. +#[derive(Debug, Clone)] +pub struct DisplayValue(T); + +/// A `Value` which serializes as a string using `fmt::Debug`. +#[derive(Debug, Clone)] +pub struct DebugValue(T); + +/// Wraps a type implementing `fmt::Display` as a `Value` that can be +/// recorded using its `Display` implementation. +pub fn display(t: T) -> DisplayValue +where + T: fmt::Display, +{ + DisplayValue(t) +} + +// ===== impl Value ===== + +/// Wraps a type implementing `fmt::Debug` as a `Value` that can be +/// recorded using its `Debug` implementation. +pub fn debug(t: T) -> DebugValue +where + T: fmt::Debug, +{ + DebugValue(t) +} + +macro_rules! impl_values { + ( $( $record:ident( $( $whatever:tt)+ ) ),+ ) => { + $( + impl_value!{ $record( $( $whatever )+ ) } + )+ + } +} +macro_rules! impl_value { + ( $record:ident( $( $value_ty:ty ),+ ) ) => { + $( + impl $crate::sealed::Sealed for $value_ty {} + impl $crate::field::Value for $value_ty { + fn record( + &self, + key: &$crate::field::Field, + recorder: &mut $crate::field::Record, + ) { + recorder.$record(key, *self) + } + } + )+ + }; + ( $record:ident( $( $value_ty:ty ),+ as $as_ty:ty) ) => { + $( + impl $crate::sealed::Sealed for $value_ty {} + impl Value for $value_ty { + fn record( + &self, + key: &$crate::field::Field, + recorder: &mut $crate::field::Record, + ) { + recorder.$record(key, *self as $as_ty) + } + } + )+ + }; +} + +// ===== impl Value ===== + +impl_values! { + record_u64(u64), + record_u64(usize, u32, u16 as u64), + record_i64(i64), + record_i64(isize, i32, i16, i8 as i64), + record_bool(bool) +} + +impl ::sealed::Sealed for str {} + +impl Value for str { + fn record(&self, key: &Field, recorder: &mut Record) { + recorder.record_str(key, &self) + } +} + +impl<'a, T: ?Sized> ::sealed::Sealed for &'a T where T: Value + ::sealed::Sealed + 'a {} + +impl<'a, T: ?Sized> Value for &'a T +where + T: Value + 'a, +{ + fn record(&self, key: &Field, recorder: &mut Record) { + (*self).record(key, recorder) + } +} + +impl<'a> ::sealed::Sealed for fmt::Arguments<'a> {} + +impl<'a> Value for fmt::Arguments<'a> { + fn record(&self, key: &Field, recorder: &mut Record) { + recorder.record_debug(key, self) + } +} + +// ===== impl DisplayValue ===== + +impl ::sealed::Sealed for DisplayValue {} + +impl Value for DisplayValue +where + T: fmt::Display, +{ + fn record(&self, key: &Field, recorder: &mut Record) { + recorder.record_debug(key, &format_args!("{}", self.0)) + } +} + +// ===== impl DebugValue ===== + +impl ::sealed::Sealed for DebugValue {} + +impl Value for DebugValue +where + T: fmt::Debug, +{ + fn record(&self, key: &Field, recorder: &mut Record) { + recorder.record_debug(key, &self.0) + } +} + // ===== impl Field ===== impl Field { @@ -145,7 +409,7 @@ impl FieldSet { /// Returns the [`Field`](::field::Field) named `name`, or `None` if no such /// field exists. - pub fn field(&self, name: &Q) -> Option + pub fn field(&self, name: &Q) -> Option where Q: Borrow, { @@ -167,12 +431,12 @@ impl FieldSet { /// define a field named "foo", the `Field` corresponding to "foo" for each /// of those callsites are not equivalent. pub fn contains(&self, field: &Field) -> bool { - field.callsite() == self.callsite() && field.i <= self.names.len() + field.callsite() == self.callsite() && field.i <= self.len() } /// Returns an iterator over the `Field`s in this `FieldSet`. pub fn iter(&self) -> Iter { - let idxs = 0..self.names.len(); + let idxs = 0..self.len(); Iter { idxs, fields: FieldSet { @@ -181,6 +445,24 @@ impl FieldSet { }, } } + + /// Returns a new `ValueSet` with entries for this `FieldSet`'s values. + #[doc(hidden)] + pub fn value_set<'v>( + &'v self, + values: &'v [(&'v Field, Option<&'v (Value + 'v)>)], + ) -> ValueSet<'v> { + ValueSet { + fields: self, + values, + } + } + + /// Returns the number of fields in this `FieldSet`. + #[inline] + pub fn len(&self) -> usize { + self.names.len() + } } impl<'a> IntoIterator for &'a FieldSet { @@ -216,3 +498,175 @@ impl Iterator for Iter { }) } } + +// ===== impl ValueSet ===== + +impl<'a> ValueSet<'a> { + /// Returns an [`Identifier`](::metadata::Identifier) that uniquely + /// identifies the callsite that defines the fields this `ValueSet` refers to. + #[inline] + pub fn callsite(&self) -> callsite::Identifier { + self.fields.callsite() + } + + /// Records all the fields in this `ValueSet` with the provided [recorder]. + /// + /// [recorder]: ::field::Record + pub fn record(&self, recorder: &mut Record) { + let my_callsite = self.callsite(); + for (field, value) in self.values { + if field.callsite() != my_callsite { + continue; + } + if let Some(value) = value { + value.record(field, recorder); + } + } + } + + /// Returns `true` if this `ValueSet` contains a value for the given `Field`. + pub fn contains(&self, field: &Field) -> bool { + field.callsite() == self.callsite() && self.values + .iter() + .any(|(key, val)| *key == field && val.is_some()) + } + + /// Returns true if this `ValueSet` contains _no_ values. + pub fn is_empty(&self) -> bool { + let my_callsite = self.callsite(); + self + .values + .iter() + .all(|(key, val)| val.is_none() || key.callsite() != my_callsite) + } + + pub(crate) fn field_set(&self) -> &FieldSet { + self.fields + } +} + +impl<'a> fmt::Debug for ValueSet<'a> { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + // TODO: this might be handy as a public impl? + impl<'a, 'b> Record for fmt::DebugStruct<'a, 'b> { + fn record_debug(&mut self, field: &Field, value: &fmt::Debug) { + self.field(field.name(), value); + } + } + self.values + .iter() + .fold(&mut f.debug_struct("ValueSet"), |dbg, (key, v)| { + if let Some(val) = v { + val.record(key, dbg); + } + dbg + }) + .finish() + } +} + +#[cfg(test)] +mod test { + use super::*; + use ::{Metadata, Level}; + + struct TestCallsite1; + static TEST_CALLSITE_1: TestCallsite1 = TestCallsite1; + static TEST_META_1: Metadata<'static> = metadata! { + name: "field_test1", + target: module_path!(), + level: Level::INFO, + fields: &["foo", "bar", "baz"], + callsite: &TEST_CALLSITE_1, + }; + + impl ::callsite::Callsite for TestCallsite1 { + fn add_interest(&self, _: ::subscriber::Interest) {} + fn clear_interest(&self) {} + + fn metadata(&self) -> &Metadata { + &TEST_META_1 + } + } + + struct TestCallsite2; + static TEST_CALLSITE_2: TestCallsite2 = TestCallsite2; + static TEST_META_2: Metadata<'static> = metadata! { + name: "field_test2", + target: module_path!(), + level: Level::INFO, + fields: &["foo", "bar", "baz"], + callsite: &TEST_CALLSITE_2, + }; + + impl ::callsite::Callsite for TestCallsite2 { + fn add_interest(&self, _: ::subscriber::Interest) {} + fn clear_interest(&self) {} + + fn metadata(&self) -> &Metadata { + &TEST_META_2 + } + } + + #[test] + fn value_set_with_no_values_is_empty() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), None), + (&fields.field("bar").unwrap(), None), + (&fields.field("baz").unwrap(), None), + ]; + let valueset = fields.value_set(&values[..]); + assert!(valueset.is_empty()); + } + + #[test] + fn empty_value_set_is_empty() { + let fields = TEST_META_1.fields(); + let valueset = fields.value_set(&[]); + assert!(valueset.is_empty()); + } + + #[test] + fn value_sets_with_fields_from_other_callsites_are_empty() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), Some(&1 as &Value)), + (&fields.field("bar").unwrap(), Some(&2 as &Value)), + (&fields.field("baz").unwrap(), Some(&3 as &Value)), + ]; + let valueset = TEST_META_2.fields().value_set(&values[..]); + assert!(valueset.is_empty()) + } + + #[test] + fn sparse_value_sets_are_not_empty() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), None), + (&fields.field("bar").unwrap(), Some(&57 as &Value)), + (&fields.field("baz").unwrap(), None), + ]; + let valueset = fields.value_set(&values[..]); + assert!(!valueset.is_empty()); + } + + #[test] + fn fields_from_other_callsets_are_skipped() { + let fields = TEST_META_1.fields(); + let values = &[ + (&fields.field("foo").unwrap(), None), + (&TEST_META_2.fields().field("bar").unwrap(), Some(&57 as &Value)), + (&fields.field("baz").unwrap(), None), + ]; + + struct MyRecorder; + impl Record for MyRecorder { + fn record_debug(&mut self, field: &Field, _: &::std::fmt::Debug) { + assert_eq!(field.callsite(), TEST_META_1.callsite()) + } + } + let valueset = fields.value_set(&values[..]); + valueset.record(&mut MyRecorder); + } +} diff --git a/tokio-trace/tokio-trace-core/src/lib.rs b/tokio-trace/tokio-trace-core/src/lib.rs index 21637b29b31..965aaea2381 100644 --- a/tokio-trace/tokio-trace-core/src/lib.rs +++ b/tokio-trace/tokio-trace-core/src/lib.rs @@ -156,6 +156,7 @@ macro_rules! metadata { pub mod callsite; pub mod dispatcher; +pub mod event; pub mod field; pub mod metadata; pub mod span; @@ -164,8 +165,13 @@ pub mod subscriber; pub use self::{ callsite::Callsite, dispatcher::Dispatch, + event::Event, field::Field, metadata::{Level, Metadata}, span::Span, subscriber::{Interest, Subscriber}, }; + +mod sealed { + pub trait Sealed {} +} diff --git a/tokio-trace/tokio-trace-core/src/subscriber.rs b/tokio-trace/tokio-trace-core/src/subscriber.rs index 412054608d8..8d381e6fa0b 100644 --- a/tokio-trace/tokio-trace-core/src/subscriber.rs +++ b/tokio-trace/tokio-trace-core/src/subscriber.rs @@ -1,7 +1,5 @@ //! Subscribers collect and record trace data. -use {field, Metadata, Span}; - -use std::fmt; +use {field, Event, Metadata, Span}; /// Trait representing the functions required to collect trace data. /// @@ -25,7 +23,7 @@ use std::fmt; /// /// When a span is entered or exited, the subscriber is provided only with the /// [ID] with which it tagged that span when it was created. This means -/// that it is up to the subscriber to determine whether or not span _data_ — +/// that it is up to the subscriber to determine whether and how span _data_ — /// the fields and metadata describing the span — should be stored. The /// [`new_span`] function is called when a new span is created, and at that /// point, the subscriber _may_ choose to store the associated data if it will @@ -99,9 +97,22 @@ pub trait Subscriber { } } + /// Returns true if a span with the specified [metadata] would be + /// recorded. + /// + /// This is used by the dispatcher to avoid allocating for span construction + /// if the span would be discarded anyway. + /// + /// [metadata]: ::Metadata + fn enabled(&self, metadata: &Metadata) -> bool; + /// Record the construction of a new [`Span`], returning a new ID for the /// span being constructed. /// + /// The provided `ValueSet` contains any field values that were provided + /// when the span was created. The subscriber may pass a [recorder] to the + /// `ValueSet`'s [`record` method] to record these values. + /// /// IDs are used to uniquely identify spans and events within the context of a /// subscriber, so span equality will be based on the returned ID. Thus, if /// the subscriber wishes for all spans with the same metadata to be @@ -111,71 +122,21 @@ pub trait Subscriber { /// 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`]: ::span::Span - fn new_span(&self, metadata: &Metadata) -> Span; - - /// Record a signed 64-bit integer value. - /// - /// This defaults to calling `self.record_debug()`; implementations wishing to - /// provide behaviour specific to signed integers may override the default - /// implementation. - /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_i64(&self, span: &Span, field: &field::Field, value: i64) { - self.record_debug(span, field, &value) - } - - /// Record an unsigned 64-bit integer value. - /// - /// This defaults to calling `self.record_debug()`; implementations wishing to - /// provide behaviour specific to unsigned integers may override the default - /// implementation. - /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_u64(&self, span: &Span, field: &field::Field, value: u64) { - self.record_debug(span, field, &value) - } + /// [recorder]: ::field::Record + /// [`record` method]: ::field::ValueSet::record + fn new_span(&self, metadata: &Metadata, values: &field::ValueSet) -> Span; - /// Record a boolean value. - /// - /// This defaults to calling `self.record_debug()`; implementations wishing to - /// provide behaviour specific to booleans may override the default - /// implementation. - /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_bool(&self, span: &Span, field: &field::Field, value: bool) { - self.record_debug(span, field, &value) - } + // === Notification methods =============================================== - /// Record a string value. - /// - /// This defaults to calling `self.record_debug()`; implementations wishing to - /// provide behaviour specific to strings may override the default - /// implementation. + /// Record a set of values on a span. /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_str(&self, span: &Span, field: &field::Field, value: &str) { - self.record_debug(span, field, &value) - } - - /// Record a value implementing `fmt::Debug`. + /// The subscriber is expected to provide a [recorder] to the `ValueSet`'s + /// [`record` method] in order to record the added values. /// - /// If recording the field is invalid (i.e. the span ID doesn't exist, the - /// field has already been recorded, and so on), the subscriber may silently - /// do nothing. - fn record_debug(&self, span: &Span, field: &field::Field, value: &fmt::Debug); + /// [recorder]: ::field::Record + /// [`record` method]: ::field::ValueSet::record + fn record(&self, span: &Span, values: &field::ValueSet); /// Adds an indication that `span` follows from the span with the id /// `follows`. @@ -195,20 +156,18 @@ pub trait Subscriber { /// subscriber knows about, or if a cyclical relationship would be created /// (i.e., some span _a_ which proceeds some other span _b_ may not also /// follow from _b_), it may silently do nothing. - fn add_follows_from(&self, span: &Span, follows: Span); + fn record_follows_from(&self, span: &Span, follows: &Span); - // === Filtering methods ================================================== - - /// Returns true if a span with the specified [metadata] would be - /// recorded. + /// Records that an [`Event`] has occurred. /// - /// This is used by the dispatcher to avoid allocating for span construction - /// if the span would be discarded anyway. + /// The provided `Event` struct contains any field values attached to the + /// event. The subscriber may pass a [recorder] to the `Event`'s + /// [`record` method] to record these values. /// - /// [metadata]: ::Metadata - fn enabled(&self, metadata: &Metadata) -> bool; - - // === Notification methods =============================================== + /// [`Event`]: ::event::Event + /// [recorder]: ::field::Record + /// [`record` method]: ::event::Event::record + fn event(&self, event: &Event); /// Records that a [`Span`] has been entered. ///