diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index f6e5fd79d3..da75ebcbfe 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -36,7 +36,7 @@ tracing-core = { path = "../tracing-core", version = "0.1.2" } # only required by the filter feature matchers = { optional = true, version = "0.0.1" } regex = { optional = true, version = "1" } -smallvec = { optional = true, version = "1"} +smallvec = { optional = true, version = "1", features = ["write"] } lazy_static = { optional = true, version = "1" } # fmt @@ -60,6 +60,7 @@ tracing = { path = "../tracing", version = "0.1"} log = "0.4" tracing-log = { path = "../tracing-log", version = "0.1" } criterion = { version = "0.3", default_features = false } +regex = "1" [badges] maintenance = { status = "experimental" } diff --git a/tracing-subscriber/src/fmt/fmt_layer.rs b/tracing-subscriber/src/fmt/fmt_layer.rs index 7209a241d2..e310d55977 100644 --- a/tracing-subscriber/src/fmt/fmt_layer.rs +++ b/tracing-subscriber/src/fmt/fmt_layer.rs @@ -4,13 +4,22 @@ use crate::{ layer::{self, Context}, registry::{LookupSpan, SpanRef}, }; -use std::{any::TypeId, cell::RefCell, fmt, io, marker::PhantomData, ops::Deref, time::Instant}; +use format::FmtSpan; +use std::{ + any::TypeId, cell::RefCell, fmt, io, marker::PhantomData, ops::Deref, str::from_utf8_unchecked, + time::Instant, +}; use tracing_core::{ field, span::{Attributes, Id, Record}, - Event, Kind, Metadata, Subscriber, + Event, Subscriber, }; +#[cfg(feature = "smallvec")] +type BufVec = smallvec::SmallVec<[T; 24]>; +#[cfg(not(feature = "smallvec"))] +type BufVec = Vec; + /// A [`Layer`] that logs formatted representations of `tracing` events. /// /// ## Examples @@ -66,6 +75,7 @@ pub struct Layer< make_writer: W, fmt_fields: N, fmt_event: E, + fmt_span: format::FmtSpanConfig, _inner: PhantomData, } @@ -139,6 +149,7 @@ where Layer { fmt_fields: self.fmt_fields, fmt_event: e, + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -173,6 +184,7 @@ impl Layer { Layer { fmt_fields: self.fmt_fields, fmt_event: self.fmt_event, + fmt_span: self.fmt_span, make_writer, _inner: self._inner, } @@ -198,6 +210,7 @@ where Layer { fmt_event: self.fmt_event.with_timer(timer), fmt_fields: self.fmt_fields, + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -208,6 +221,18 @@ where Layer { fmt_event: self.fmt_event.without_time(), fmt_fields: self.fmt_fields, + fmt_span: self.fmt_span.without_time(), + make_writer: self.make_writer, + _inner: self._inner, + } + } + + /// Select which span usage shall be logged as events + pub fn with_spans(self, kind: FmtSpan) -> Self { + Layer { + fmt_event: self.fmt_event, + fmt_fields: self.fmt_fields, + fmt_span: self.fmt_span.with_kind(kind), make_writer: self.make_writer, _inner: self._inner, } @@ -220,6 +245,7 @@ where Layer { fmt_event: self.fmt_event.with_ansi(ansi), fmt_fields: self.fmt_fields, + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -230,6 +256,7 @@ where Layer { fmt_event: self.fmt_event.with_target(display_target), fmt_fields: self.fmt_fields, + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -240,6 +267,7 @@ where Layer { fmt_event: self.fmt_event.with_level(display_level), fmt_fields: self.fmt_fields, + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -253,6 +281,7 @@ where Layer { fmt_event: self.fmt_event.compact(), fmt_fields: self.fmt_fields, + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -280,6 +309,7 @@ where Layer { fmt_event: self.fmt_event.json(), fmt_fields: format::JsonFields::new(), + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -299,6 +329,7 @@ impl Layer, W> { Layer { fmt_event: self.fmt_event.flatten_event(flatten_event), fmt_fields: format::JsonFields::new(), + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -315,6 +346,7 @@ impl Layer { Layer { fmt_event: self.fmt_event, fmt_fields, + fmt_span: self.fmt_span, make_writer: self.make_writer, _inner: self._inner, } @@ -346,6 +378,7 @@ impl Default for Layer { Layer { fmt_fields: format::DefaultFields::default(), fmt_event: format::Format::default(), + fmt_span: format::FmtSpanConfig::default(), make_writer: io::stdout, _inner: PhantomData, } @@ -417,6 +450,21 @@ impl Deref for FormattedFields { // === impl FmtLayer === +macro_rules! event_from_span { + ($event:ident = $id:ident, $span:ident, $($field:ident = $value:expr),*) => { + let meta = $span.metadata(); + let cs = meta.callsite(); + let fs = field::FieldSet::new(&[$(stringify!($field)),*], cs); + #[allow(unused)] + let mut iter = fs.iter(); + let v = [$( + (&iter.next().unwrap(), Some(&$value as &dyn field::Value)), + )*]; + let vs = fs.value_set(&v); + let $event = Event::new_child_of($id, meta, &vs); + }; +} + impl layer::Layer for Layer where S: Subscriber + for<'a> LookupSpan<'a>, @@ -438,6 +486,20 @@ where extensions.insert(fmt_fields); } } + + if self.fmt_span.fmt_timing + && self.fmt_span.trace_close() + && extensions.get_mut::().is_none() + { + extensions.insert(Timings::new()); + } + + if self.fmt_span.trace_new() { + event_from_span!(event = id, span, message = "new"); + drop(extensions); + drop(span); + self.on_event(&event, ctx); + } } fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) { @@ -463,9 +525,16 @@ where let span = ctx.span(id).expect("Span not found, this is a bug"); let mut extensions = span.extensions_mut(); if let Some(timings) = extensions.get_mut::() { - timings.entered = Some(Instant::now()); - } else { - extensions.insert(Timings::new()); + let now = Instant::now(); + timings.idle += (now - timings.last).as_nanos() as u64; + timings.last = now; + } + + if self.fmt_span.trace_enter() { + event_from_span!(event = id, span, message = "enter"); + drop(extensions); + drop(span); + self.on_event(&event, ctx); } } @@ -473,63 +542,58 @@ where let span = ctx.span(id).expect("Span not found, this is a bug"); let mut extensions = span.extensions_mut(); if let Some(timings) = extensions.get_mut::() { - if let Some(started) = timings.entered.take() { - timings.accumulated += started.elapsed().as_nanos() as u64; - } + let now = Instant::now(); + timings.busy += (now - timings.last).as_nanos() as u64; + timings.last = now; + } + + if self.fmt_span.trace_exit() { + event_from_span!(event = id, span, message = "exit"); + drop(extensions); + drop(span); + self.on_event(&event, ctx); } } fn on_close(&self, id: Id, ctx: Context<'_, S>) { let span = ctx.span(&id).expect("Span not found, this is a bug"); let extensions = span.extensions(); - if let Some(timing) = extensions.get::() { - let t = field::display(timing.get_accumulated()); - let meta = span.metadata(); - let name = field::display(meta.name()); - let cs = meta.callsite(); - let meta = Metadata::new( - meta.name(), - meta.target(), - meta.level().clone(), - meta.file(), - meta.line(), - meta.module_path(), - field::FieldSet::new(&[], cs.clone()), - Kind::EVENT, - ); - let fs = field::FieldSet::new(&["message", "timing"], cs); - let mut it = fs.iter(); - let v = [ - (&it.next().unwrap(), Some(&name as &dyn field::Value)), - (&it.next().unwrap(), Some(&t as &dyn field::Value)), - ]; - let vs = fs.value_set(&v); - let event = - Event::new_child_of(id, unsafe { &*(&meta as *const Metadata<'static>) }, &vs); - - let mut buf = String::new(); - let ctx = self.make_ctx(ctx.clone()); - if self.fmt_event.format_event(&ctx, &mut buf, &event).is_ok() { - let fields = extensions - .get::>() - .expect("Unable to find FormattedFields in extensions; this is a bug"); - if !fields.is_empty() { - use std::fmt::Write; - loop { - let last = buf.pop(); - match last { - Some(x) if x.is_whitespace() => {} - Some(x) => { - buf.push(x); - break; - } - None => break, - } - } - let _ = writeln!(&mut buf, " {}", fields); - } - let mut writer = self.make_writer.make_writer(); - let _ = io::Write::write_all(&mut writer, buf.as_bytes()); + if self.fmt_span.trace_close() { + if let Some(timing) = extensions.get::() { + let Timings { + busy, + mut idle, + last, + } = *timing; + idle += (Instant::now() - last).as_nanos() as u64; + + let mut s_idle = BufVec::new(); + self.fmt_span.fmt_timing(idle, &mut s_idle); + // safe because we control the writers and they write strings + let s_idle = unsafe { from_utf8_unchecked(s_idle.as_ref()) }; + let t_idle = field::display(s_idle); + + let mut s_busy = BufVec::new(); + self.fmt_span.fmt_timing(busy, &mut s_busy); + // safe because we control the writers and they write strings + let s_busy = unsafe { from_utf8_unchecked(s_busy.as_ref()) }; + let t_busy = field::display(s_busy); + + event_from_span!( + event = id, + span, + message = "close", + t_busy = t_busy, + t_idle = t_idle + ); + drop(extensions); + drop(span); + self.on_event(&event, ctx); + } else { + event_from_span!(event = id, span, message = "close"); + drop(extensions); + drop(span); + self.on_event(&event, ctx); } } } @@ -628,32 +692,17 @@ where } struct Timings { - accumulated: u64, - entered: Option, + idle: u64, + busy: u64, + last: Instant, } impl Timings { fn new() -> Self { Self { - accumulated: 0, - entered: Some(Instant::now()), - } - } - fn get_accumulated(&self) -> String { - if self.accumulated >= 10_000_000_000 { - format!("{}s", self.accumulated) - } else if self.accumulated >= 1_000_000_000 { - format!("{:.1}s", self.accumulated as f64 / 1_000_000_000.0) - } else if self.accumulated >= 10_000_000 { - format!("{}ms", self.accumulated / 1_000_000) - } else if self.accumulated >= 1_000_000 { - format!("{:.1}ms", self.accumulated as f64 / 1_000_000.0) - } else if self.accumulated >= 10_000 { - format!("{}µs", self.accumulated / 1000) - } else if self.accumulated >= 1000 { - format!("{:.1}µs", self.accumulated as f64 / 1000.0) - } else { - format!("{}ns", self.accumulated) + idle: 0, + busy: 0, + last: Instant::now(), } } } @@ -662,11 +711,17 @@ impl Timings { mod test { use crate::fmt::{ self, - format::{self, Format}, + format::{self, test::MockTime, Format}, layer::Layer as _, + test::MockWriter, time, }; use crate::Registry; + use format::FmtSpan; + use lazy_static::lazy_static; + use regex::Regex; + use std::sync::Mutex; + use tracing::subscriber::with_default; use tracing_core::dispatcher::Dispatch; #[test] @@ -714,4 +769,141 @@ mod test { let subscriber = fmt.with_subscriber(Registry::default()); assert_lookup_span(subscriber) } + + fn sanitize_timings(s: String) -> String { + let re = Regex::new("t_(idle|busy)=([0-9.]+)[mµn]s").unwrap(); + re.replace_all(s.as_str(), "timing").to_string() + } + + #[test] + fn synthesize_span_none() { + lazy_static! { + static ref BUF: Mutex> = Mutex::new(vec![]); + } + + let make_writer = || MockWriter::new(&BUF); + let subscriber = crate::fmt::Subscriber::builder() + .with_writer(make_writer) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime) + // check that FmtSpan::None is the default + .finish(); + + with_default(subscriber, || { + let span1 = tracing::info_span!("span1", x = 42); + let _e = span1.enter(); + }); + let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap()); + assert_eq!("", actual.as_str()); + } + + #[test] + fn synthesize_span_active() { + lazy_static! { + static ref BUF: Mutex> = Mutex::new(vec![]); + } + + let make_writer = || MockWriter::new(&BUF); + let subscriber = crate::fmt::Subscriber::builder() + .with_writer(make_writer) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime) + .with_spans(FmtSpan::Active) + .finish(); + + with_default(subscriber, || { + let span1 = tracing::info_span!("span1", x = 42); + let _e = span1.enter(); + }); + let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap()); + assert_eq!( + "fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: enter\n\ + fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: exit\n", + actual.as_str() + ); + } + + #[test] + fn synthesize_span_close() { + lazy_static! { + static ref BUF: Mutex> = Mutex::new(vec![]); + } + + let make_writer = || MockWriter::new(&BUF); + let subscriber = crate::fmt::Subscriber::builder() + .with_writer(make_writer) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime) + .with_spans(FmtSpan::Close) + .finish(); + + with_default(subscriber, || { + let span1 = tracing::info_span!("span1", x = 42); + let _e = span1.enter(); + }); + let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap()); + assert_eq!( + "fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: close timing timing\n", + actual.as_str() + ); + } + + #[test] + fn synthesize_span_close_no_timing() { + lazy_static! { + static ref BUF: Mutex> = Mutex::new(vec![]); + } + + let make_writer = || MockWriter::new(&BUF); + let subscriber = crate::fmt::Subscriber::builder() + .with_writer(make_writer) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime) + .without_time() + .with_spans(FmtSpan::Close) + .finish(); + + with_default(subscriber, || { + let span1 = tracing::info_span!("span1", x = 42); + let _e = span1.enter(); + }); + let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap()); + assert_eq!( + " span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: close\n", + actual.as_str() + ); + } + + #[test] + fn synthesize_span_full() { + lazy_static! { + static ref BUF: Mutex> = Mutex::new(vec![]); + } + + let make_writer = || MockWriter::new(&BUF); + let subscriber = crate::fmt::Subscriber::builder() + .with_writer(make_writer) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime) + .with_spans(FmtSpan::Full) + .finish(); + + with_default(subscriber, || { + let span1 = tracing::info_span!("span1", x = 42); + let _e = span1.enter(); + }); + let actual = sanitize_timings(String::from_utf8(BUF.try_lock().unwrap().to_vec()).unwrap()); + assert_eq!( + "fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: new\n\ + fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: enter\n\ + fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: exit\n\ + fake time span1{x=42}: tracing_subscriber::fmt::fmt_layer::test: close timing timing\n", + actual.as_str() + ); + } } diff --git a/tracing-subscriber/src/fmt/format/mod.rs b/tracing-subscriber/src/fmt/format/mod.rs index 2d428784b1..5b079d855c 100644 --- a/tracing-subscriber/src/fmt/format/mod.rs +++ b/tracing-subscriber/src/fmt/format/mod.rs @@ -9,7 +9,7 @@ use crate::{ use std::{ fmt::{self, Write}, - iter, + io, iter, }; use tracing_core::{ field::{self, Field, Visit}, @@ -25,6 +25,7 @@ use ansi_term::{Colour, Style}; #[cfg(feature = "json")] mod json; +use fmt::Debug; #[cfg(feature = "json")] #[cfg_attr(docsrs, doc(cfg(feature = "json")))] pub use json::*; @@ -854,8 +855,113 @@ impl<'a, F> fmt::Debug for FieldFnVisitor<'a, F> { } } +// === printing synthetic Span events === + +/// Select the degree to which tracing spans are logged as events +#[derive(Debug)] +pub enum FmtSpan { + /// spans are ignored (this is the default) + None, + /// one event per enter/exit of a span + Active, + /// one event when the span is dropped + Close, + /// events at all points (new, enter, exit, drop) + Full, +} + +pub(super) struct FmtSpanConfig { + pub(super) kind: FmtSpan, + pub(super) fmt_timing: bool, +} + +impl FmtSpanConfig { + pub(super) fn without_time(self) -> Self { + Self { + kind: self.kind, + fmt_timing: false, + } + } + pub(super) fn with_kind(self, kind: FmtSpan) -> Self { + Self { + kind, + fmt_timing: self.fmt_timing, + } + } + pub(super) fn fmt_timing(&self, t: u64, buf: &mut impl io::Write) { + if self.fmt_timing { + fmt_nanos(t, buf) + } + } + pub(super) fn trace_new(&self) -> bool { + match self.kind { + FmtSpan::None => false, + FmtSpan::Active => false, + FmtSpan::Close => false, + FmtSpan::Full => true, + } + } + pub(super) fn trace_enter(&self) -> bool { + match self.kind { + FmtSpan::None => false, + FmtSpan::Active => true, + FmtSpan::Close => false, + FmtSpan::Full => true, + } + } + pub(super) fn trace_exit(&self) -> bool { + match self.kind { + FmtSpan::None => false, + FmtSpan::Active => true, + FmtSpan::Close => false, + FmtSpan::Full => true, + } + } + pub(super) fn trace_close(&self) -> bool { + match self.kind { + FmtSpan::None => false, + FmtSpan::Active => false, + FmtSpan::Close => true, + FmtSpan::Full => true, + } + } +} + +impl Debug for FmtSpanConfig { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + self.kind.fmt(f) + } +} + +impl Default for FmtSpanConfig { + fn default() -> Self { + Self { + kind: FmtSpan::None, + fmt_timing: true, + } + } +} + +fn fmt_nanos(t: u64, buf: &mut impl io::Write) { + let mut t = t as f64; + for unit in ["ns", "µs", "ms", "s"].iter() { + if t < 10.0 { + let _ = write!(buf, "{:.2}{}", t, unit); + return; + } else if t < 100.0 { + let _ = write!(buf, "{:.1}{}", t, unit); + return; + } else if t < 1000.0 { + let _ = write!(buf, "{:.0}{}", t, unit); + return; + } + t /= 1000.0; + } + let _ = write!(buf, "{:.0}s", t * 1000.0); +} + #[cfg(test)] -mod test { +pub(super) mod test { use crate::fmt::{test::MockWriter, time::FormatTime}; use lazy_static::lazy_static; @@ -863,7 +969,7 @@ mod test { use std::{fmt, sync::Mutex}; - struct MockTime; + pub(crate) struct MockTime; impl FormatTime for MockTime { fn format_time(&self, w: &mut dyn fmt::Write) -> fmt::Result { write!(w, "fake time") @@ -1026,4 +1132,27 @@ mod test { ); }); } + + #[test] + fn format_nanos() { + fn fmt(t: u64) -> String { + let mut s = Vec::new(); + super::fmt_nanos(t, &mut s); + String::from_utf8(s).unwrap() + } + + assert_eq!(fmt(1), "1.00ns"); + assert_eq!(fmt(12), "12.0ns"); + assert_eq!(fmt(123), "123ns"); + assert_eq!(fmt(1234), "1.23µs"); + assert_eq!(fmt(12345), "12.3µs"); + assert_eq!(fmt(123456), "123µs"); + assert_eq!(fmt(1234567), "1.23ms"); + assert_eq!(fmt(12345678), "12.3ms"); + assert_eq!(fmt(123456789), "123ms"); + assert_eq!(fmt(1234567890), "1.23s"); + assert_eq!(fmt(12345678901), "12.3s"); + assert_eq!(fmt(123456789012), "123s"); + assert_eq!(fmt(1234567890123), "1235s"); + } } diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index f8be96c88a..8105ca1f73 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -477,6 +477,14 @@ where } } + /// Select which span usage shall be logged as events + pub fn with_spans(self, kind: format::FmtSpan) -> Self { + SubscriberBuilder { + filter: self.filter, + inner: self.inner.with_spans(kind), + } + } + /// Enable ANSI encoding for formatted events. #[cfg(feature = "ansi")] #[cfg_attr(docsrs, doc(cfg(feature = "ansi")))]