67340e911f## Motivation We've tried very hard to make sure that entering and exiting spans is lightweight...in the `tracing-core` core machinery. Unfortunately, we haven't done any benchmarking of how subscriber implementations actually handle enter/exit events. It turns out that in `tracing-subscriber`'s `Registry`, there's actually significant overhead for entering a span: calling `span.enter()` may take as long as 69 ns (on my machine). ## Solution I've written some microbenchmarks for entering and exiting enabled spans using `tracing-subscriber::fmt`, comparing them with the overhead of calling `enter` on an enabled span. Based on this, I've made some performance improvements. These optimizations include: - Removing the `HashSet` that's used for tracking previously entered span IDs, in favor of linear search. Span stacks probably never deep enough for a hashmap to be faster than iterating over a couple of vec indices. - Preallocating the vec used for the span stack to hold at least 64 elements. This means we'll never have a lag spike from reallocating, as I think it'll almost never be deeper than 64 IDs. - Only cloning/dropping an ID's ref count for the _first_ ID in the stack. This makes entering and exiting enabled spans significantly faster:  It would be nice to continue optimizing this, but this might be about the best it gets given the other requirements that we're now making assertions about. Signed-off-by: Eliza Weisman <eliza@buoyant.io>
64 lines
2.1 KiB
Rust
64 lines
2.1 KiB
Rust
use criterion::{criterion_group, criterion_main, Criterion};
|
|
use tracing_subscriber::prelude::*;
|
|
|
|
fn enter(c: &mut Criterion) {
|
|
let mut group = c.benchmark_group("enter");
|
|
let _subscriber = tracing_subscriber::fmt()
|
|
.with_max_level(tracing::Level::INFO)
|
|
.finish()
|
|
.set_default();
|
|
group.bench_function("enabled", |b| {
|
|
let span = tracing::info_span!("foo");
|
|
b.iter_with_large_drop(|| span.enter())
|
|
});
|
|
group.bench_function("disabled", |b| {
|
|
let span = tracing::debug_span!("foo");
|
|
b.iter_with_large_drop(|| span.enter())
|
|
});
|
|
}
|
|
|
|
fn enter_exit(c: &mut Criterion) {
|
|
let mut group = c.benchmark_group("enter_exit");
|
|
let _subscriber = tracing_subscriber::fmt()
|
|
.with_max_level(tracing::Level::INFO)
|
|
.finish()
|
|
.set_default();
|
|
group.bench_function("enabled", |b| {
|
|
let span = tracing::info_span!("foo");
|
|
b.iter(|| span.enter())
|
|
});
|
|
group.bench_function("disabled", |b| {
|
|
let span = tracing::debug_span!("foo");
|
|
b.iter(|| span.enter())
|
|
});
|
|
}
|
|
|
|
fn enter_many(c: &mut Criterion) {
|
|
let mut group = c.benchmark_group("enter_many");
|
|
let _subscriber = tracing_subscriber::fmt()
|
|
.with_max_level(tracing::Level::INFO)
|
|
.finish()
|
|
.set_default();
|
|
group.bench_function("enabled", |b| {
|
|
let span1 = tracing::info_span!("span1");
|
|
let _e1 = span1.enter();
|
|
let span2 = tracing::info_span!("span2");
|
|
let _e2 = span2.enter();
|
|
let span3 = tracing::info_span!("span3");
|
|
let _e3 = span3.enter();
|
|
let span = tracing::info_span!("foo");
|
|
b.iter_with_large_drop(|| span.enter())
|
|
});
|
|
group.bench_function("disabled", |b| {
|
|
let span1 = tracing::info_span!("span1");
|
|
let _e1 = span1.enter();
|
|
let span2 = tracing::info_span!("span2");
|
|
let _e2 = span2.enter();
|
|
let span3 = tracing::info_span!("span3");
|
|
let _e3 = span3.enter();
|
|
let span = tracing::debug_span!("foo");
|
|
b.iter_with_large_drop(|| span.enter())
|
|
});
|
|
}
|
|
criterion_group!(benches, enter, enter_exit, enter_many);
|
|
criterion_main!(benches);
|