From 2405e5279754e8f3161d623a8a0e3d40aa8e616e Mon Sep 17 00:00:00 2001 From: Bryan Garza <1396101+bryangarza@users.noreply.github.com> Date: Mon, 16 May 2022 15:38:34 -0700 Subject: [PATCH 1/3] 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 <9832640+zekisherif@users.noreply.github.com> --- tracing-appender/Cargo.toml | 5 + tracing-appender/benches/bench.rs | 181 ++++++++++++++++++++++++++++++ 2 files changed, 186 insertions(+) create mode 100644 tracing-appender/benches/bench.rs diff --git a/tracing-appender/Cargo.toml b/tracing-appender/Cargo.toml index 1e51039a99..920629f475 100644 --- a/tracing-appender/Cargo.toml +++ b/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 \ 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..82c1ce3ed5 --- /dev/null +++ b/tracing-appender/benches/bench.rs @@ -0,0 +1,181 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use crossbeam_channel::{unbounded, Receiver, Sender}; +use std::sync::{Arc, Mutex}; +use std::thread; +use std::thread::JoinHandle; +use std::time::Instant; +use tracing::{event, Level}; +use tracing_appender::non_blocking; +use tracing_subscriber::fmt::MakeWriter; + +#[derive(Clone)] +struct SynchronousWriter { + writer: Arc>>, +} + +impl SynchronousWriter { + fn new() -> SynchronousWriter { + SynchronousWriter { + writer: Arc::new(Mutex::new(Vec::new())), + } + } +} + +impl<'a> MakeWriter<'a> for SynchronousWriter { + type Writer = SynchronousWriter; + + fn make_writer(&self) -> Self::Writer { + self.clone() + } +} + +impl std::io::Write for SynchronousWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let buf_len = buf.len(); + match self.writer.lock() { + Ok(mut guard) => { + guard.extend_from_slice(buf); + } + Err(e) => { + eprintln!("Failed to acquire lock: {:?}", e); + } + } + Ok(buf_len) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +/// A cheap writer so that we don't spam console if we had used stdout +#[derive(Clone)] +struct SilentWriter { + tx: Sender, +} + +impl SilentWriter { + fn new() -> (Self, Receiver) { + let (tx, rx) = unbounded(); + (Self { tx }, rx) + } +} + +impl std::io::Write for SilentWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let buf_len = buf.len(); + let _ = self.tx.send(String::from_utf8_lossy(buf).to_string()); + Ok(buf_len) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +impl<'a> MakeWriter<'a> for SilentWriter { + type Writer = SilentWriter; + + fn make_writer(&self) -> Self::Writer { + self.clone() + } +} + +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(SynchronousWriter::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> = Vec::new(); + + let start = Instant::now(); + + let make_writer = SynchronousWriter::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 (silent_writer, _rx) = SilentWriter::new(); + let (non_blocking, _guard) = non_blocking(silent_writer); + 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 (silent_writer, _rx) = SilentWriter::new(); + let (non_blocking, _guard) = non_blocking(silent_writer); + + 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::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); From 82c5672f879de8d04f51fdbd2788cf0dff9b46f9 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Tue, 17 May 2022 15:57:04 -0400 Subject: [PATCH 2/3] switch to no-op writers in benchmarks --- tracing-appender/benches/bench.rs | 83 +++++++------------------------ 1 file changed, 18 insertions(+), 65 deletions(-) diff --git a/tracing-appender/benches/bench.rs b/tracing-appender/benches/bench.rs index 82c1ce3ed5..163351978f 100644 --- a/tracing-appender/benches/bench.rs +++ b/tracing-appender/benches/bench.rs @@ -1,46 +1,34 @@ use criterion::{criterion_group, criterion_main, Criterion}; -use crossbeam_channel::{unbounded, Receiver, Sender}; -use std::sync::{Arc, Mutex}; -use std::thread; -use std::thread::JoinHandle; -use std::time::Instant; +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 SynchronousWriter { - writer: Arc>>, -} +struct NoOpWriter; -impl SynchronousWriter { - fn new() -> SynchronousWriter { - SynchronousWriter { - writer: Arc::new(Mutex::new(Vec::new())), - } +impl NoOpWriter { + fn new() -> NoOpWriter { + NoOpWriter } } -impl<'a> MakeWriter<'a> for SynchronousWriter { - type Writer = SynchronousWriter; +impl<'a> MakeWriter<'a> for NoOpWriter { + type Writer = NoOpWriter; fn make_writer(&self) -> Self::Writer { self.clone() } } -impl std::io::Write for SynchronousWriter { +impl std::io::Write for NoOpWriter { fn write(&mut self, buf: &[u8]) -> std::io::Result { - let buf_len = buf.len(); - match self.writer.lock() { - Ok(mut guard) => { - guard.extend_from_slice(buf); - } - Err(e) => { - eprintln!("Failed to acquire lock: {:?}", e); - } - } - Ok(buf_len) + Ok(buf.len()) } fn flush(&mut self) -> std::io::Result<()> { @@ -48,43 +36,10 @@ impl std::io::Write for SynchronousWriter { } } -/// A cheap writer so that we don't spam console if we had used stdout -#[derive(Clone)] -struct SilentWriter { - tx: Sender, -} - -impl SilentWriter { - fn new() -> (Self, Receiver) { - let (tx, rx) = unbounded(); - (Self { tx }, rx) - } -} - -impl std::io::Write for SilentWriter { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - let buf_len = buf.len(); - let _ = self.tx.send(String::from_utf8_lossy(buf).to_string()); - Ok(buf_len) - } - - fn flush(&mut self) -> std::io::Result<()> { - Ok(()) - } -} - -impl<'a> MakeWriter<'a> for SilentWriter { - type Writer = SilentWriter; - - fn make_writer(&self) -> Self::Writer { - self.clone() - } -} - 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(SynchronousWriter::new()); + let subscriber = tracing_subscriber::fmt().with_writer(NoOpWriter::new()); tracing::collect::with_default(subscriber.finish(), || { b.iter(|| event!(Level::INFO, "event")) }); @@ -96,7 +51,7 @@ fn synchronous_benchmark(c: &mut Criterion) { let start = Instant::now(); - let make_writer = SynchronousWriter::new(); + let make_writer = NoOpWriter::new(); let cloned_make_writer = make_writer.clone(); handles.push(thread::spawn(move || { @@ -130,8 +85,7 @@ fn non_blocking_benchmark(c: &mut Criterion) { let mut group = c.benchmark_group("non_blocking"); group.bench_function("single_thread", |b| { - let (silent_writer, _rx) = SilentWriter::new(); - let (non_blocking, _guard) = non_blocking(silent_writer); + let (non_blocking, _guard) = non_blocking(NoOpWriter::new()); let subscriber = tracing_subscriber::fmt().with_writer(non_blocking); tracing::collect::with_default(subscriber.finish(), || { @@ -141,8 +95,7 @@ fn non_blocking_benchmark(c: &mut Criterion) { group.bench_function("multiple_writers", |b| { b.iter_custom(|iters| { - let (silent_writer, _rx) = SilentWriter::new(); - let (non_blocking, _guard) = non_blocking(silent_writer); + let (non_blocking, _guard) = non_blocking(NoOpWriter::new()); let mut handles: Vec> = Vec::new(); From b22c9a778acace4fa42204d5e1f0c90f27ae0156 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Fri, 20 May 2022 11:30:04 -0400 Subject: [PATCH 3/3] fix macro resolution issue --- tracing/src/macros.rs | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 28c59319f8..20cc3b04d8 100644 --- a/tracing/src/macros.rs +++ b/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)* } )=> ({