| use criterion::{criterion_group, criterion_main, BenchmarkId, Criterion, Throughput}; |
| use std::{io, time::Duration}; |
| |
| mod support; |
| use support::MultithreadedBench; |
| |
| /// A fake writer that doesn't actually do anything. |
| /// |
| /// We want to measure the subscriber's overhead, *not* the performance of |
| /// stdout/file writers. Using a no-op Write implementation lets us only measure |
| /// the subscriber's overhead. |
| struct NoWriter; |
| |
| impl io::Write for NoWriter { |
| fn write(&mut self, buf: &[u8]) -> io::Result<usize> { |
| Ok(buf.len()) |
| } |
| |
| fn flush(&mut self) -> io::Result<()> { |
| Ok(()) |
| } |
| } |
| |
| impl NoWriter { |
| fn new() -> Self { |
| Self |
| } |
| } |
| |
| fn bench_new_span(c: &mut Criterion) { |
| bench_thrpt(c, "new_span", |group, i| { |
| group.bench_with_input(BenchmarkId::new("single_thread", i), i, |b, &i| { |
| tracing::dispatcher::with_default(&mk_dispatch(), || { |
| b.iter(|| { |
| for n in 0..i { |
| let _span = tracing::info_span!("span", n); |
| } |
| }) |
| }); |
| }); |
| group.bench_with_input(BenchmarkId::new("multithreaded", i), i, |b, &i| { |
| b.iter_custom(|iters| { |
| let mut total = Duration::from_secs(0); |
| let dispatch = mk_dispatch(); |
| for _ in 0..iters { |
| let bench = MultithreadedBench::new(dispatch.clone()); |
| let elapsed = bench |
| .thread(move || { |
| for n in 0..i { |
| let _span = tracing::info_span!("span", n); |
| } |
| }) |
| .thread(move || { |
| for n in 0..i { |
| let _span = tracing::info_span!("span", n); |
| } |
| }) |
| .thread(move || { |
| for n in 0..i { |
| let _span = tracing::info_span!("span", n); |
| } |
| }) |
| .thread(move || { |
| for n in 0..i { |
| let _span = tracing::info_span!("span", n); |
| } |
| }) |
| .run(); |
| total += elapsed; |
| } |
| total |
| }) |
| }); |
| }); |
| } |
| |
| type Group<'a> = criterion::BenchmarkGroup<'a, criterion::measurement::WallTime>; |
| fn bench_thrpt(c: &mut Criterion, name: &'static str, mut f: impl FnMut(&mut Group<'_>, &usize)) { |
| const N_SPANS: &[usize] = &[1, 10, 50]; |
| |
| let mut group = c.benchmark_group(name); |
| for spans in N_SPANS { |
| group.throughput(Throughput::Elements(*spans as u64)); |
| f(&mut group, spans); |
| } |
| group.finish(); |
| } |
| |
| fn mk_dispatch() -> tracing::Dispatch { |
| let subscriber = tracing_subscriber::FmtSubscriber::builder() |
| .with_writer(NoWriter::new) |
| .finish(); |
| tracing::Dispatch::new(subscriber) |
| } |
| |
| fn bench_event(c: &mut Criterion) { |
| bench_thrpt(c, "event", |group, i| { |
| group.bench_with_input(BenchmarkId::new("root/single_threaded", i), i, |b, &i| { |
| let dispatch = mk_dispatch(); |
| tracing::dispatcher::with_default(&dispatch, || { |
| b.iter(|| { |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| }); |
| }); |
| group.bench_with_input(BenchmarkId::new("root/multithreaded", i), i, |b, &i| { |
| b.iter_custom(|iters| { |
| let mut total = Duration::from_secs(0); |
| let dispatch = mk_dispatch(); |
| for _ in 0..iters { |
| let bench = MultithreadedBench::new(dispatch.clone()); |
| let elapsed = bench |
| .thread(move || { |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| .thread(move || { |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| .thread(move || { |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| .thread(move || { |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| .run(); |
| total += elapsed; |
| } |
| total |
| }) |
| }); |
| group.bench_with_input( |
| BenchmarkId::new("unique_parent/single_threaded", i), |
| i, |
| |b, &i| { |
| tracing::dispatcher::with_default(&mk_dispatch(), || { |
| let span = tracing::info_span!("unique_parent", foo = false); |
| let _guard = span.enter(); |
| b.iter(|| { |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| }); |
| }, |
| ); |
| group.bench_with_input( |
| BenchmarkId::new("unique_parent/multithreaded", i), |
| i, |
| |b, &i| { |
| b.iter_custom(|iters| { |
| let mut total = Duration::from_secs(0); |
| let dispatch = mk_dispatch(); |
| for _ in 0..iters { |
| let bench = MultithreadedBench::new(dispatch.clone()); |
| let elapsed = bench |
| .thread_with_setup(move |start| { |
| let span = tracing::info_span!("unique_parent", foo = false); |
| let _guard = span.enter(); |
| start.wait(); |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| .thread_with_setup(move |start| { |
| let span = tracing::info_span!("unique_parent", foo = false); |
| let _guard = span.enter(); |
| start.wait(); |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| .thread_with_setup(move |start| { |
| let span = tracing::info_span!("unique_parent", foo = false); |
| let _guard = span.enter(); |
| start.wait(); |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| .thread_with_setup(move |start| { |
| let span = tracing::info_span!("unique_parent", foo = false); |
| let _guard = span.enter(); |
| start.wait(); |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }) |
| .run(); |
| total += elapsed; |
| } |
| total |
| }) |
| }, |
| ); |
| group.bench_with_input( |
| BenchmarkId::new("shared_parent/multithreaded", i), |
| i, |
| |b, &i| { |
| b.iter_custom(|iters| { |
| let dispatch = mk_dispatch(); |
| let mut total = Duration::from_secs(0); |
| for _ in 0..iters { |
| let parent = tracing::dispatcher::with_default(&dispatch, || { |
| tracing::info_span!("shared_parent", foo = "hello world") |
| }); |
| let bench = MultithreadedBench::new(dispatch.clone()); |
| let parent2 = parent.clone(); |
| bench.thread_with_setup(move |start| { |
| let _guard = parent2.enter(); |
| start.wait(); |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }); |
| let parent2 = parent.clone(); |
| bench.thread_with_setup(move |start| { |
| let _guard = parent2.enter(); |
| start.wait(); |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }); |
| let parent2 = parent.clone(); |
| bench.thread_with_setup(move |start| { |
| let _guard = parent2.enter(); |
| start.wait(); |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }); |
| let parent2 = parent.clone(); |
| bench.thread_with_setup(move |start| { |
| let _guard = parent2.enter(); |
| start.wait(); |
| for n in 0..i { |
| tracing::info!(n); |
| } |
| }); |
| let elapsed = bench.run(); |
| total += elapsed; |
| } |
| total |
| }) |
| }, |
| ); |
| group.bench_with_input( |
| BenchmarkId::new("multi-parent/multithreaded", i), |
| i, |
| |b, &i| { |
| b.iter_custom(|iters| { |
| let dispatch = mk_dispatch(); |
| let mut total = Duration::from_secs(0); |
| for _ in 0..iters { |
| let parent = tracing::dispatcher::with_default(&dispatch, || { |
| tracing::info_span!("multiparent", foo = "hello world") |
| }); |
| let bench = MultithreadedBench::new(dispatch.clone()); |
| let parent2 = parent.clone(); |
| bench.thread_with_setup(move |start| { |
| let _guard = parent2.enter(); |
| start.wait(); |
| let mut span = tracing::info_span!("parent"); |
| for n in 0..i { |
| let s = tracing::info_span!(parent: &span, "parent2", n, i); |
| s.in_scope(|| { |
| tracing::info!(n); |
| }); |
| span = s; |
| } |
| }); |
| let parent2 = parent.clone(); |
| bench.thread_with_setup(move |start| { |
| let _guard = parent2.enter(); |
| start.wait(); |
| let mut span = tracing::info_span!("parent"); |
| for n in 0..i { |
| let s = tracing::info_span!(parent: &span, "parent2", n, i); |
| s.in_scope(|| { |
| tracing::info!(n); |
| }); |
| span = s; |
| } |
| }); |
| let parent2 = parent.clone(); |
| bench.thread_with_setup(move |start| { |
| let _guard = parent2.enter(); |
| start.wait(); |
| let mut span = tracing::info_span!("parent"); |
| for n in 0..i { |
| let s = tracing::info_span!(parent: &span, "parent2", n, i); |
| s.in_scope(|| { |
| tracing::info!(n); |
| }); |
| span = s; |
| } |
| }); |
| let parent2 = parent.clone(); |
| bench.thread_with_setup(move |start| { |
| let _guard = parent2.enter(); |
| start.wait(); |
| let mut span = tracing::info_span!("parent"); |
| for n in 0..i { |
| let s = tracing::info_span!(parent: &span, "parent2", n, i); |
| s.in_scope(|| { |
| tracing::info!(n); |
| }); |
| span = s; |
| } |
| }); |
| let elapsed = bench.run(); |
| total += elapsed; |
| } |
| total |
| }) |
| }, |
| ); |
| }); |
| } |
| |
| criterion_group!(benches, bench_new_span, bench_event); |
| criterion_main!(benches); |