From 55411a43aef16bf45f6849943266fe9330c17bb2 Mon Sep 17 00:00:00 2001 From: Zeki Sherif Date: Fri, 1 May 2020 13:05:02 -0700 Subject: [PATCH 1/5] Appender: Add benchmarks --- tracing-appender/Cargo.toml | 8 +- tracing-appender/benches/bench.rs | 134 ++++++++++++++++++++++++++++++ 2 files changed, 141 insertions(+), 1 deletion(-) create mode 100644 tracing-appender/benches/bench.rs diff --git a/tracing-appender/Cargo.toml b/tracing-appender/Cargo.toml index 66d802ce9b..f4fbce22a4 100644 --- a/tracing-appender/Cargo.toml +++ b/tracing-appender/Cargo.toml @@ -15,4 +15,10 @@ crossbeam-channel = "0.4.2" chrono = "0.4.11" [dev-dependencies] -tracing = { path = "../tracing", version = "0.1" } \ No newline at end of file +criterion = { version = "0.3", default_features = false } +tracing = { path = "../tracing", version = "0.1" } +tempdir = "0.3" + +[[bench]] +name = "bench" +harness = false diff --git a/tracing-appender/benches/bench.rs b/tracing-appender/benches/bench.rs new file mode 100644 index 0000000000..1311548fff --- /dev/null +++ b/tracing-appender/benches/bench.rs @@ -0,0 +1,134 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use crossbeam_channel::{unbounded, Receiver, Sender}; +use std::thread; +use std::thread::JoinHandle; +use std::time::{Duration, Instant}; +use tempdir::TempDir; +use tracing::{event, Level}; +use tracing_appender::non_blocking::NonBlocking; +use tracing_appender::{non_blocking, rolling}; +use tracing_subscriber::fmt::MakeWriter; + +/// 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 MakeWriter for SilentWriter { + type Writer = SilentWriter; + + fn make_writer(&self) -> Self::Writer { + self.clone() + } +} + +fn multi_threaded_bench(non_blocking: NonBlocking, iters: u64) -> Duration { + 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(cloned_make_writer); + tracing::subscriber::with_default(subscriber.finish(), || { + for _ in 0..iters { + event!(Level::INFO, "event"); + } + }); + })); + + let cloned_make_writer_2 = non_blocking.clone(); + + handles.push(thread::spawn(move || { + let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer_2); + 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 (silent_writer, _rx) = SilentWriter::new(); + let (non_blocking, _guard) = non_blocking(silent_writer); + 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 (silent_writer, _rx) = SilentWriter::new(); + let (non_blocking, _guard) = non_blocking(silent_writer); + + multi_threaded_bench(non_blocking, iters) + }); + }); +} + +fn non_blocking_rolling_appender_benchmark(c: &mut Criterion) { + let mut group = c.benchmark_group("non_blocking_rolling_file_appender"); + + group.bench_function("non_blocking", |b| { + let temp_dir = TempDir::new("rolling_file_appender").expect("Failed to create temp dir"); + let file_appender = rolling::hourly(temp_dir.path(), "log"); + let (non_blocking, _guard) = non_blocking(file_appender); + + let subscriber = tracing_subscriber::fmt().with_writer(non_blocking); + tracing::subscriber::with_default(subscriber.finish(), || { + b.iter(|| event!(Level::INFO, "non_blocking event")) + }); + + let _ = temp_dir.close(); + }); + + group.bench_function("multiple_writers", |b| { + b.iter_custom(|iters| { + let temp_dir = + TempDir::new("rolling_file_appender").expect("Failed to create temp dir"); + let file_appender = rolling::hourly(temp_dir.path(), "log"); + let (non_blocking, _guard) = non_blocking(file_appender); + + multi_threaded_bench(non_blocking, iters) + }); + }); +} + +criterion_group!( + benches, + non_blocking_benchmark, + non_blocking_rolling_appender_benchmark +); +criterion_main!(benches); From 1473bedc5dc1a13191da4d050fa1a9aac3b98b30 Mon Sep 17 00:00:00 2001 From: Zeki Sherif Date: Fri, 1 May 2020 13:32:37 -0700 Subject: [PATCH 2/5] Fix clippy warning --- tracing-appender/benches/bench.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tracing-appender/benches/bench.rs b/tracing-appender/benches/bench.rs index 1311548fff..63a1274bae 100644 --- a/tracing-appender/benches/bench.rs +++ b/tracing-appender/benches/bench.rs @@ -47,7 +47,9 @@ fn multi_threaded_bench(non_blocking: NonBlocking, iters: u64) -> Duration { let start = Instant::now(); - let cloned_make_writer = non_blocking.clone(); + let cloned_make_writer = non_blocking; + let cloned_make_writer_2 = cloned_make_writer.clone(); + handles.push(thread::spawn(move || { let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer); tracing::subscriber::with_default(subscriber.finish(), || { @@ -57,8 +59,6 @@ fn multi_threaded_bench(non_blocking: NonBlocking, iters: u64) -> Duration { }); })); - let cloned_make_writer_2 = non_blocking.clone(); - handles.push(thread::spawn(move || { let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer_2); tracing::subscriber::with_default(subscriber.finish(), || { From f4132a7802c2803667504244182c84a6015b1e93 Mon Sep 17 00:00:00 2001 From: Zeki Sherif Date: Fri, 1 May 2020 14:40:32 -0700 Subject: [PATCH 3/5] Add bench for synchronous writer so we can compare to non_blocking --- tracing-appender/benches/bench.rs | 161 ++++++++++++++++++++---------- 1 file changed, 106 insertions(+), 55 deletions(-) diff --git a/tracing-appender/benches/bench.rs b/tracing-appender/benches/bench.rs index 63a1274bae..a4150b1a7f 100644 --- a/tracing-appender/benches/bench.rs +++ b/tracing-appender/benches/bench.rs @@ -2,12 +2,51 @@ use criterion::{criterion_group, criterion_main, Criterion}; use crossbeam_channel::{unbounded, Receiver, Sender}; use std::thread; use std::thread::JoinHandle; -use std::time::{Duration, Instant}; -use tempdir::TempDir; +use std::time::Instant; use tracing::{event, Level}; -use tracing_appender::non_blocking::NonBlocking; -use tracing_appender::{non_blocking, rolling}; +use tracing_appender::non_blocking; use tracing_subscriber::fmt::MakeWriter; +use std::sync::{Arc, Mutex}; + +#[derive(Clone)] +struct SynchronousWriter { + writer: Arc>>, +} + +impl SynchronousWriter { + fn new() -> SynchronousWriter { + SynchronousWriter { + writer: Arc::new(Mutex::new(Vec::new())), + } + } +} + +impl MakeWriter 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)] @@ -42,37 +81,49 @@ impl MakeWriter for SilentWriter { } } -fn multi_threaded_bench(non_blocking: NonBlocking, iters: u64) -> Duration { - let mut handles: Vec> = Vec::new(); - - let start = Instant::now(); - - let cloned_make_writer = non_blocking; - let cloned_make_writer_2 = cloned_make_writer.clone(); - - handles.push(thread::spawn(move || { - let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer); +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::subscriber::with_default(subscriber.finish(), || { - for _ in 0..iters { - event!(Level::INFO, "event"); - } + b.iter(|| event!(Level::INFO, "event")) }); - })); + }); - handles.push(thread::spawn(move || { - let subscriber = tracing_subscriber::fmt().with_writer(cloned_make_writer_2); - tracing::subscriber::with_default(subscriber.finish(), || { - for _ in 0..iters { - 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::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(); } - }); - })); - for handle in handles { - let _ = handle.join(); - } - - start.elapsed() + start.elapsed() + }); + }); } fn non_blocking_benchmark(c: &mut Criterion) { @@ -93,42 +144,42 @@ fn non_blocking_benchmark(c: &mut Criterion) { let (silent_writer, _rx) = SilentWriter::new(); let (non_blocking, _guard) = non_blocking(silent_writer); - multi_threaded_bench(non_blocking, iters) - }); - }); -} + let mut handles: Vec> = Vec::new(); -fn non_blocking_rolling_appender_benchmark(c: &mut Criterion) { - let mut group = c.benchmark_group("non_blocking_rolling_file_appender"); + let start = Instant::now(); - group.bench_function("non_blocking", |b| { - let temp_dir = TempDir::new("rolling_file_appender").expect("Failed to create temp dir"); - let file_appender = rolling::hourly(temp_dir.path(), "log"); - let (non_blocking, _guard) = non_blocking(file_appender); + let cloned_make_writer = non_blocking.clone(); - let subscriber = tracing_subscriber::fmt().with_writer(non_blocking); - tracing::subscriber::with_default(subscriber.finish(), || { - b.iter(|| event!(Level::INFO, "non_blocking event")) - }); + 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"); + } + }); + })); - let _ = temp_dir.close(); - }); + 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"); + } + }); + })); - group.bench_function("multiple_writers", |b| { - b.iter_custom(|iters| { - let temp_dir = - TempDir::new("rolling_file_appender").expect("Failed to create temp dir"); - let file_appender = rolling::hourly(temp_dir.path(), "log"); - let (non_blocking, _guard) = non_blocking(file_appender); + for handle in handles { + let _ = handle.join(); + } - multi_threaded_bench(non_blocking, iters) + start.elapsed() }); }); } criterion_group!( benches, - non_blocking_benchmark, - non_blocking_rolling_appender_benchmark + synchronous_benchmark, + non_blocking_benchmark ); criterion_main!(benches); From 3e982ec867831e85bd1f4918dfcdc8e9e3efaa4a Mon Sep 17 00:00:00 2001 From: Zeki Sherif Date: Fri, 1 May 2020 14:47:16 -0700 Subject: [PATCH 4/5] Cargo fmt --- tracing-appender/benches/bench.rs | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/tracing-appender/benches/bench.rs b/tracing-appender/benches/bench.rs index a4150b1a7f..0215f4811a 100644 --- a/tracing-appender/benches/bench.rs +++ b/tracing-appender/benches/bench.rs @@ -1,12 +1,12 @@ 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; -use std::sync::{Arc, Mutex}; #[derive(Clone)] struct SynchronousWriter { @@ -35,10 +35,10 @@ impl std::io::Write for SynchronousWriter { match self.writer.lock() { Ok(mut guard) => { guard.extend_from_slice(buf); - }, + } Err(e) => { eprintln!("Failed to acquire lock: {:?}", e); - }, + } } Ok(buf_len) } @@ -177,9 +177,5 @@ fn non_blocking_benchmark(c: &mut Criterion) { }); } -criterion_group!( - benches, - synchronous_benchmark, - non_blocking_benchmark -); +criterion_group!(benches, synchronous_benchmark, non_blocking_benchmark); criterion_main!(benches); From 50e341d45ec74035918f13a08d21d8ed2724ca3c Mon Sep 17 00:00:00 2001 From: Zeki Sherif Date: Mon, 4 May 2020 11:52:10 -0700 Subject: [PATCH 5/5] Remove duplicated dev-dependency --- tracing-appender/Cargo.toml | 1 - 1 file changed, 1 deletion(-) diff --git a/tracing-appender/Cargo.toml b/tracing-appender/Cargo.toml index 2172ce2906..f4fbce22a4 100644 --- a/tracing-appender/Cargo.toml +++ b/tracing-appender/Cargo.toml @@ -18,7 +18,6 @@ chrono = "0.4.11" criterion = { version = "0.3", default_features = false } tracing = { path = "../tracing", version = "0.1" } tempdir = "0.3" -tracing = { path = "../tracing", version = "0.1" } [[bench]] name = "bench"