Skip to content

Commit

Permalink
subscriber: add more benchmarks for filters (#581)
Browse files Browse the repository at this point in the history 
## Motivation

Currently, there are a few cases that aren't adequately covered by the
`tracing-subscriber` filtering benchmarks. In particular, we don't have
benchmarks which involve filters with multiple directives, missing a
large amount of potential overhead from iterating over the directive
set, and we don't have benchmarks for events generated by the `log`
integration. Since `log` events can't participate in the callsite
caching mechanism, their performance picture is radically different.

## Solution

This branch adds new benchmarks for filters with multiple static
directives, filters with multiple dynamic directives, and filters with
mixed static and dynamic directives. Additionally, I've added a new set
of benchmarks which are identical to the current ones, except that
`log`'s macros are used to emit events via `tracing-log`, rather than
using `tracing`'s macros directly.

## Current Results

<details> 

<summary>Benchmark environment</summary>

```console
eliza@ares:~$ uname -a
Linux ares 4.9.0-11-amd64 #1 SMP Debian 4.9.189-3+deb9u2 (2019-11-11) x86_64 GNU/Linux
eliza@ares:~$ rustc --version
rustc 1.41.0 (5e1a79984 2020-01-27)
eliza@ares:~$ lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                40
On-line CPU(s) list:   0-39
Thread(s) per core:    2
Core(s) per socket:    10
Socket(s):             2
NUMA node(s):          2
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 79
Model name:            Intel(R) Xeon(R) CPU E5-2630 v4 @ 2.20GHz
Stepping:              1
CPU MHz:               2200.000
CPU max MHz:           2200.0000
CPU min MHz:           1200.0000
BogoMIPS:              4390.06
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              25600K
NUMA node0 CPU(s):     0-9,20-29
NUMA node1 CPU(s):     10-19,30-39
Flags:                 fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch epb invpcid_single kaiser tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm cqm rdseed adx smap intel_pt xsaveopt cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local dtherm arat pln pts
```

 </details>

<details>
<summary>Benchmark results </summary>

```
    Finished bench [optimized] target(s) in 50.95s
     Running target/release/deps/filter-b804f035b8022c0d
static/baseline_single_threaded
                        time:   [109.09 ns 109.37 ns 109.89 ns]
Found 14 outliers among 100 measurements (14.00%)
  4 (4.00%) high mild
  10 (10.00%) high severe
static/single_threaded  time:   [63.893 ns 63.951 ns 64.022 ns]
Found 14 outliers among 100 measurements (14.00%)
  1 (1.00%) low mild
  2 (2.00%) high mild
  11 (11.00%) high severe
static/enabled_one      time:   [28.293 ns 28.321 ns 28.355 ns]
Found 9 outliers among 100 measurements (9.00%)
  3 (3.00%) high mild
  6 (6.00%) high severe
static/enabled_many     time:   [28.278 ns 28.292 ns 28.311 ns]
Found 15 outliers among 100 measurements (15.00%)
  2 (2.00%) low mild
  5 (5.00%) high mild
  8 (8.00%) high severe
static/disabled_level_one
                        time:   [3.6514 ns 3.6545 ns 3.6580 ns]
Found 15 outliers among 100 measurements (15.00%)
  5 (5.00%) high mild
  10 (10.00%) high severe
static/disabled_level_many
                        time:   [4.1064 ns 4.1118 ns 4.1189 ns]
Found 13 outliers among 100 measurements (13.00%)
  2 (2.00%) low mild
  1 (1.00%) high mild
  10 (10.00%) high severe
static/disabled_one     time:   [4.1063 ns 4.1307 ns 4.1673 ns]
Found 12 outliers among 100 measurements (12.00%)
  1 (1.00%) low mild
  11 (11.00%) high severe
static/disabled_many    time:   [4.1091 ns 4.1136 ns 4.1190 ns]
Found 13 outliers among 100 measurements (13.00%)
  3 (3.00%) high mild
  10 (10.00%) high severe
static/baseline_multithreaded
                        time:   [7.2856 us 7.4135 us 7.5423 us]
Found 3 outliers among 100 measurements (3.00%)
  2 (2.00%) high mild
  1 (1.00%) high severe
static/multithreaded    time:   [7.5089 us 7.6710 us 7.8466 us]
Found 4 outliers among 100 measurements (4.00%)
  1 (1.00%) low mild
  2 (2.00%) high mild
  1 (1.00%) high severe

dynamic/baseline_single_threaded
                        time:   [247.58 ns 247.78 ns 247.98 ns]
Found 2 outliers among 100 measurements (2.00%)
  1 (1.00%) high mild
  1 (1.00%) high severe
dynamic/single_threaded time:   [1.2122 us 1.2131 us 1.2141 us]
Found 7 outliers among 100 measurements (7.00%)
  3 (3.00%) high mild
  4 (4.00%) high severe
dynamic/baseline_multithreaded
                        time:   [7.3576 us 7.5858 us 7.8602 us]
Found 5 outliers among 100 measurements (5.00%)
  1 (1.00%) low mild
  2 (2.00%) high mild
  2 (2.00%) high severe
dynamic/multithreaded   time:   [8.2427 us 8.4257 us 8.6156 us]
Found 5 outliers among 100 measurements (5.00%)
  2 (2.00%) high mild
  3 (3.00%) high severe

mixed/disabled          time:   [80.464 ns 80.534 ns 80.611 ns]
Found 7 outliers among 100 measurements (7.00%)
  2 (2.00%) low mild
  3 (3.00%) high mild
  2 (2.00%) high severe
mixed/disabled_by_level time:   [68.077 ns 68.113 ns 68.155 ns]
Found 5 outliers among 100 measurements (5.00%)
  2 (2.00%) low severe
  2 (2.00%) high mild
  1 (1.00%) high severe

     Running target/release/deps/filter_log-b8cedd42cccfa727
log/static/baseline_single_threaded
                        time:   [477.71 ns 478.03 ns 478.40 ns]
Found 9 outliers among 100 measurements (9.00%)
  7 (7.00%) high mild
  2 (2.00%) high severe
log/static/single_threaded
                        time:   [553.40 ns 554.14 ns 555.17 ns]
Found 6 outliers among 100 measurements (6.00%)
  5 (5.00%) high mild
  1 (1.00%) high severe
log/static/enabled_one  time:   [172.29 ns 172.47 ns 172.68 ns]
Found 21 outliers among 100 measurements (21.00%)
  14 (14.00%) high mild
  7 (7.00%) high severe
log/static/enabled_many time:   [172.49 ns 172.61 ns 172.75 ns]
Found 10 outliers among 100 measurements (10.00%)
  4 (4.00%) high mild
  6 (6.00%) high severe
log/static/disabled_level_one
                        time:   [78.422 ns 78.529 ns 78.651 ns]
Found 17 outliers among 100 measurements (17.00%)
  2 (2.00%) high mild
  15 (15.00%) high severe
log/static/disabled_level_many
                        time:   [128.72 ns 128.83 ns 128.98 ns]
Found 8 outliers among 100 measurements (8.00%)
  2 (2.00%) low mild
  6 (6.00%) high severe
log/static/disabled_one time:   [77.385 ns 77.579 ns 77.848 ns]
Found 10 outliers among 100 measurements (10.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
  8 (8.00%) high severe
log/static/disabled_many
                        time:   [123.67 ns 123.84 ns 124.03 ns]
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) high mild
log/static/baseline_multithreaded
                        time:   [7.4644 us 7.6093 us 7.7570 us]
Found 2 outliers among 100 measurements (2.00%)
  2 (2.00%) high mild
log/static/multithreaded
                        time:   [7.5466 us 7.7412 us 7.9768 us]
Found 4 outliers among 100 measurements (4.00%)
  2 (2.00%) low mild
  2 (2.00%) high mild

log/dynamic/baseline_single_threaded
                        time:   [615.96 ns 616.53 ns 617.29 ns]
Found 8 outliers among 100 measurements (8.00%)
  3 (3.00%) high mild
  5 (5.00%) high severe
log/dynamic/single_threaded
                        time:   [1.4436 us 1.4457 us 1.4483 us]
Found 2 outliers among 100 measurements (2.00%)
  1 (1.00%) high mild
  1 (1.00%) high severe
log/dynamic/baseline_multithreaded
                        time:   [7.3015 us 7.5285 us 7.8139 us]
Found 6 outliers among 100 measurements (6.00%)
  1 (1.00%) low severe
  3 (3.00%) high mild
  2 (2.00%) high severe
log/dynamic/multithreaded
                        time:   [7.9638 us 8.2182 us 8.5184 us]
Found 7 outliers among 100 measurements (7.00%)
  2 (2.00%) low mild
  2 (2.00%) high mild
  3 (3.00%) high severe

log/mixed/disabled      time:   [104.93 ns 105.01 ns 105.12 ns]
Found 10 outliers among 100 measurements (10.00%)
  3 (3.00%) low mild
  7 (7.00%) high severe
log/mixed/disabled_by_level
                        time:   [91.754 ns 92.322 ns 93.531 ns]
Found 3 outliers among 100 measurements (3.00%)
  1 (1.00%) low mild
  2 (2.00%) high severe
```

</details>

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
  • Loading branch information
@hawkw
hawkw authored Feb 12, 2020
1 parent 263a154 commit 409baff
Show file tree
Hide file tree
Showing 3 changed files with 426 additions and 78 deletions.
4 changes: 4 additions & 0 deletions tracing-subscriber/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -73,6 +73,10 @@ rustdoc-args = ["--cfg", "docsrs"]
name = "filter"
harness = false

[[bench]]
name = "filter_log"
harness = false

[[bench]]
name = "fmt"
harness = false
185 changes: 107 additions & 78 deletions tracing-subscriber/benches/filter.rs
View file
Original file line number Diff line number Diff line change
@@ -1,12 +1,11 @@
use criterion::{criterion_group, criterion_main, Criterion};
use std::{
sync::{Arc, Barrier},
thread,
time::{Duration, Instant},
};
use std::time::Duration;
use tracing::{dispatcher::Dispatch, span, Event, Id, Metadata};
use tracing_subscriber::{prelude::*, EnvFilter};

mod support;
use support::MultithreadedBench;

/// A subscriber that is enabled but otherwise does nothing.
struct EnabledSubscriber;

Expand Down Expand Up @@ -42,42 +41,6 @@ impl tracing::Subscriber for EnabledSubscriber {
}
}

#[derive(Clone)]
struct MultithreadedBench {
start: Arc<Barrier>,
end: Arc<Barrier>,
dispatch: Dispatch,
}

impl MultithreadedBench {
fn new(dispatch: Dispatch) -> Self {
Self {
start: Arc::new(Barrier::new(5)),
end: Arc::new(Barrier::new(5)),
dispatch,
}
}

fn thread(&self, f: impl FnOnce(&Barrier) + Send + 'static) -> &Self {
let this = self.clone();
thread::spawn(move || {
let dispatch = this.dispatch.clone();
tracing::dispatcher::with_default(&dispatch, move || {
f(&*this.start);
this.end.wait();
})
});
self
}

fn run(&self) -> Duration {
self.start.wait();
let t0 = Instant::now();
self.end.wait();
t0.elapsed()
}
}

fn bench_static(c: &mut Criterion) {
let mut group = c.benchmark_group("static");

Expand All @@ -104,27 +67,81 @@ fn bench_static(c: &mut Criterion) {
})
});
});
group.bench_function("enabled_one", |b| {
let filter = "static_filter=info"
.parse::<EnvFilter>()
.expect("should parse");
tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
b.iter(|| {
tracing::info!(target: "static_filter", "hi");
})
});
});
group.bench_function("enabled_many", |b| {
let filter = "foo=debug,bar=trace,baz=error,quux=warn,static_filter=info"
.parse::<EnvFilter>()
.expect("should parse");
tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
b.iter(|| {
tracing::info!(target: "static_filter", "hi");
})
});
});
group.bench_function("disabled_level_one", |b| {
let filter = "static_filter=info"
.parse::<EnvFilter>()
.expect("should parse");
tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
b.iter(|| {
tracing::debug!(target: "static_filter", "hi");
})
});
});
group.bench_function("disabled_level_many", |b| {
let filter = "foo=debug,bar=info,baz=error,quux=warn,static_filter=info"
.parse::<EnvFilter>()
.expect("should parse");
tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
b.iter(|| {
tracing::trace!(target: "static_filter", "hi");
})
});
});
group.bench_function("disabled_one", |b| {
let filter = "foo=info".parse::<EnvFilter>().expect("should parse");
tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
b.iter(|| {
tracing::info!(target: "static_filter", "hi");
})
});
});
group.bench_function("disabled_many", |b| {
let filter = "foo=debug,bar=trace,baz=error,quux=warn,whibble=info"
.parse::<EnvFilter>()
.expect("should parse");
tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
b.iter(|| {
tracing::info!(target: "static_filter", "hi");
})
});
});
group.bench_function("baseline_multithreaded", |b| {
let dispatch = tracing::dispatcher::Dispatch::new(EnabledSubscriber);
let dispatch = Dispatch::new(EnabledSubscriber);
b.iter_custom(|iters| {
let mut total = Duration::from_secs(0);
for _ in 0..iters {
let bench = MultithreadedBench::new(dispatch.clone());
let elapsed = bench
.thread(|start| {
start.wait();
.thread(|| {
tracing::info!(target: "static_filter", "hi");
})
.thread(|start| {
start.wait();
.thread(|| {
tracing::debug!(target: "static_filter", "hi");
})
.thread(|start| {
start.wait();
.thread(|| {
tracing::warn!(target: "static_filter", "hi");
})
.thread(|start| {
start.wait();
.thread(|| {
tracing::warn!(target: "foo", "hi");
})
.run();
Expand All @@ -137,26 +154,22 @@ fn bench_static(c: &mut Criterion) {
let filter = "static_filter=info"
.parse::<EnvFilter>()
.expect("should parse");
let dispatch = tracing::dispatcher::Dispatch::new(EnabledSubscriber.with(filter));
let dispatch = Dispatch::new(EnabledSubscriber.with(filter));
b.iter_custom(|iters| {
let mut total = Duration::from_secs(0);
for _ in 0..iters {
let bench = MultithreadedBench::new(dispatch.clone());
let elapsed = bench
.thread(|start| {
start.wait();
.thread(|| {
tracing::info!(target: "static_filter", "hi");
})
.thread(|start| {
start.wait();
.thread(|| {
tracing::debug!(target: "static_filter", "hi");
})
.thread(|start| {
start.wait();
.thread(|| {
tracing::warn!(target: "static_filter", "hi");
})
.thread(|start| {
start.wait();
.thread(|| {
tracing::warn!(target: "foo", "hi");
})
.run();
Expand Down Expand Up @@ -201,32 +214,28 @@ fn bench_dynamic(c: &mut Criterion) {
});
});
group.bench_function("baseline_multithreaded", |b| {
let dispatch = tracing::dispatcher::Dispatch::new(EnabledSubscriber);
let dispatch = Dispatch::new(EnabledSubscriber);
b.iter_custom(|iters| {
let mut total = Duration::from_secs(0);
for _ in 0..iters {
let bench = MultithreadedBench::new(dispatch.clone());
let elapsed = bench
.thread(|start| {
.thread(|| {
let span = tracing::info_span!("foo");
start.wait();
let _ = span.enter();
tracing::info!("hi");
})
.thread(|start| {
.thread(|| {
let span = tracing::info_span!("foo");
start.wait();
let _ = span.enter();
tracing::debug!("hi");
})
.thread(|start| {
.thread(|| {
let span = tracing::info_span!("bar");
start.wait();
let _ = span.enter();
tracing::debug!("hi");
})
.thread(|start| {
start.wait();
.thread(|| {
tracing::trace!("hi");
})
.run();
Expand All @@ -237,32 +246,28 @@ fn bench_dynamic(c: &mut Criterion) {
});
group.bench_function("multithreaded", |b| {
let filter = "[foo]=trace".parse::<EnvFilter>().expect("should parse");
let dispatch = tracing::dispatcher::Dispatch::new(EnabledSubscriber.with(filter));
let dispatch = Dispatch::new(EnabledSubscriber.with(filter));
b.iter_custom(|iters| {
let mut total = Duration::from_secs(0);
for _ in 0..iters {
let bench = MultithreadedBench::new(dispatch.clone());
let elapsed = bench
.thread(|start| {
.thread(|| {
let span = tracing::info_span!("foo");
start.wait();
let _ = span.enter();
tracing::info!("hi");
})
.thread(|start| {
.thread(|| {
let span = tracing::info_span!("foo");
start.wait();
let _ = span.enter();
tracing::debug!("hi");
})
.thread(|start| {
.thread(|| {
let span = tracing::info_span!("bar");
start.wait();
let _ = span.enter();
tracing::debug!("hi");
})
.thread(|start| {
start.wait();
.thread(|| {
tracing::trace!("hi");
})
.run();
Expand All @@ -275,5 +280,29 @@ fn bench_dynamic(c: &mut Criterion) {
group.finish();
}

criterion_group!(benches, bench_static, bench_dynamic);
fn bench_mixed(c: &mut Criterion) {
let mut group = c.benchmark_group("mixed");
group.bench_function("disabled", |b| {
let filter = "[foo]=trace,bar[quux]=debug,[{baz}]=debug,asdf=warn,wibble=info"
.parse::<EnvFilter>()
.expect("should parse");
tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
b.iter(|| {
tracing::info!(target: "static_filter", "hi");
})
});
});
group.bench_function("disabled_by_level", |b| {
let filter = "[foo]=info,bar[quux]=debug,asdf=warn,static_filter=info"
.parse::<EnvFilter>()
.expect("should parse");
tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
b.iter(|| {
tracing::trace!(target: "static_filter", "hi");
})
});
});
}

criterion_group!(benches, bench_static, bench_dynamic, bench_mixed);
criterion_main!(benches);
Loading

0 comments on commit 409baff

Please sign in to comment.