diff --git a/tracing-appender/Cargo.toml b/tracing-appender/Cargo.toml index c57932b503..2d02b38e95 100644 --- a/tracing-appender/Cargo.toml +++ b/tracing-appender/Cargo.toml @@ -32,6 +32,12 @@ default-features = false features = ["fmt", "std"] [dev-dependencies] + +criterion = { version = "0.3", default_features = false } tracing = { path = "../tracing", version = "0.1" } time = { version = "0.3", default-features = false, features = ["formatting", "parsing"] } tempfile = "3" + +[[bench]] +name = "bench" +harness = false \ No newline at end of file diff --git a/tracing-appender/benches/bench.rs b/tracing-appender/benches/bench.rs new file mode 100644 index 0000000000..e8ea4d75a6 --- /dev/null +++ b/tracing-appender/benches/bench.rs @@ -0,0 +1,134 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use std::{ + thread::{self, JoinHandle}, + time::Instant, +}; +use tracing::{event, Level}; +use tracing_appender::non_blocking; +use tracing_subscriber::fmt::MakeWriter; + +// a no-op writer is used in order to measure the overhead incurred by +// tracing-subscriber. +#[derive(Clone)] +struct NoOpWriter; + +impl NoOpWriter { + fn new() -> NoOpWriter { + NoOpWriter + } +} + +impl<'a> MakeWriter<'a> for NoOpWriter { + type Writer = NoOpWriter; + + fn make_writer(&self) -> Self::Writer { + self.clone() + } +} + +impl std::io::Write for NoOpWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +fn synchronous_benchmark(c: &mut Criterion) { + let mut group = c.benchmark_group("synchronous"); + group.bench_function("single_thread", |b| { + let subscriber = tracing_subscriber::fmt().with_writer(NoOpWriter::new()); + tracing::subscriber::with_default(subscriber.finish(), || { + b.iter(|| event!(Level::INFO, "event")) + }); + }); + + group.bench_function("multiple_writers", |b| { + b.iter_custom(|iters| { + let mut handles: Vec> = Vec::new(); + + let start = Instant::now(); + + let make_writer = NoOpWriter::new(); + let cloned_make_writer = make_writer.clone(); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(make_writer); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + for handle in handles { + let _ = handle.join(); + } + + start.elapsed() + }); + }); +} + +fn non_blocking_benchmark(c: &mut Criterion) { + let mut group = c.benchmark_group("non_blocking"); + + group.bench_function("single_thread", |b| { + let (non_blocking, _guard) = non_blocking(NoOpWriter::new()); + let subscriber = tracing_subscriber::fmt().with_writer(non_blocking); + + tracing::subscriber::with_default(subscriber.finish(), || { + b.iter(|| event!(Level::INFO, "event")) + }); + }); + + group.bench_function("multiple_writers", |b| { + b.iter_custom(|iters| { + let (non_blocking, _guard) = non_blocking(NoOpWriter::new()); + + let mut handles: Vec> = Vec::new(); + + let start = Instant::now(); + + let cloned_make_writer = non_blocking.clone(); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(non_blocking); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + for handle in handles { + let _ = handle.join(); + } + + start.elapsed() + }); + }); +} + +criterion_group!(benches, synchronous_benchmark, non_blocking_benchmark); +criterion_main!(benches); diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index bca42933b3..b134af6e81 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -832,6 +832,8 @@ macro_rules! event { /// } /// ``` /// +/// [`enabled!`]: crate::enabled +/// [`span_enabled!`]: crate::span_enabled #[macro_export] macro_rules! event_enabled { ($($rest:tt)*)=> ( @@ -864,6 +866,8 @@ macro_rules! event_enabled { /// } /// ``` /// +/// [`enabled!`]: crate::enabled +/// [`span_enabled!`]: crate::span_enabled #[macro_export] macro_rules! span_enabled { ($($rest:tt)*)=> ( @@ -959,7 +963,8 @@ macro_rules! span_enabled { /// [`Metadata`]: crate::Metadata /// [`is_event`]: crate::Metadata::is_event /// [`is_span`]: crate::Metadata::is_span -/// +/// [`enabled!`]: crate::enabled +/// [`span_enabled!`]: crate::span_enabled #[macro_export] macro_rules! enabled { (kind: $kind:expr, target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({