appender: add initial set of benches (#2128)

* appender: add initial set of benches

This patch adds blocking and nonblocking benchmarks. This code is from
an old PR (#703) that was never merged, and now ported to TOT so that it
compiles.

Co-authored-by: Zeki Sherif <[email protected]>

* switch to no-op writers in benchmarks

* fix macro resolution issue

Co-authored-by: Zeki Sherif <[email protected]>
Co-authored-by: David Barsky <[email protected]>

Author: 3 people

tracing-appender/Cargo.toml

@@ -32,6 +32,11 @@ default-features = false
 features = ["fmt", "std"]
 
 [dev-dependencies]
+criterion = { version = "0.3", default_features = false }
 tracing = { path = "../tracing", version = "0.2" }
 time = { version = "0.3", default-features = false, features = ["formatting", "parsing"] }
 tempfile = "3"
+
+[[bench]]
+name = "bench"
+harness = false

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<usize> {
+        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::collect::with_default(subscriber.finish(), || {
+            b.iter(|| event!(Level::INFO, "event"))
+        });
+    });
+
+    group.bench_function("multiple_writers", |b| {
+        b.iter_custom(|iters| {
+            let mut handles: Vec<JoinHandle<()>> = 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::collect::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::collect::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::collect::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<JoinHandle<()>> = 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::collect::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::collect::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);

tracing/src/macros.rs

@@ -826,6 +826,8 @@ macro_rules! event {
 /// }
 /// ```
 ///
+/// [`enabled!`]: crate::enabled
+/// [`span_enabled!`]: crate::span_enabled
 #[macro_export]
 macro_rules! event_enabled {
     ($($rest:tt)*)=> (
@@ -858,6 +860,8 @@ macro_rules! event_enabled {
 /// }
 /// ```
 ///
+/// [`enabled!`]: crate::enabled
+/// [`span_enabled!`]: crate::span_enabled
 #[macro_export]
 macro_rules! span_enabled {
     ($($rest:tt)*)=> (
@@ -953,7 +957,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)* } )=> ({