1 use criterion::{criterion_group, criterion_main, Criterion};
2 use std::time::Duration;
3 use tracing::{dispatcher::Dispatch, span, Event, Id, Metadata};
4 use tracing_subscriber::{prelude::*, EnvFilter};
5
6 mod support;
7 use support::MultithreadedBench;
8
9 /// A subscriber that is enabled but otherwise does nothing.
10 struct EnabledSubscriber;
11
12 impl tracing::Subscriber for EnabledSubscriber {
new_span(&self, span: &span::Attributes<'_>) -> Id13 fn new_span(&self, span: &span::Attributes<'_>) -> Id {
14 let _ = span;
15 Id::from_u64(0xDEAD_FACE)
16 }
17
event(&self, event: &Event<'_>)18 fn event(&self, event: &Event<'_>) {
19 let _ = event;
20 }
21
record(&self, span: &Id, values: &span::Record<'_>)22 fn record(&self, span: &Id, values: &span::Record<'_>) {
23 let _ = (span, values);
24 }
25
record_follows_from(&self, span: &Id, follows: &Id)26 fn record_follows_from(&self, span: &Id, follows: &Id) {
27 let _ = (span, follows);
28 }
29
enabled(&self, metadata: &Metadata<'_>) -> bool30 fn enabled(&self, metadata: &Metadata<'_>) -> bool {
31 let _ = metadata;
32 true
33 }
34
enter(&self, span: &Id)35 fn enter(&self, span: &Id) {
36 let _ = span;
37 }
38
exit(&self, span: &Id)39 fn exit(&self, span: &Id) {
40 let _ = span;
41 }
42 }
43
bench_static(c: &mut Criterion)44 fn bench_static(c: &mut Criterion) {
45 let _ = tracing_log::LogTracer::init();
46
47 let mut group = c.benchmark_group("log/static");
48
49 group.bench_function("baseline_single_threaded", |b| {
50 tracing::subscriber::with_default(EnabledSubscriber, || {
51 b.iter(|| {
52 log::info!(target: "static_filter", "hi");
53 log::debug!(target: "static_filter", "hi");
54 log::warn!(target: "static_filter", "hi");
55 log::trace!(target: "foo", "hi");
56 })
57 });
58 });
59 group.bench_function("single_threaded", |b| {
60 let filter = "static_filter=info"
61 .parse::<EnvFilter>()
62 .expect("should parse");
63 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
64 b.iter(|| {
65 log::info!(target: "static_filter", "hi");
66 log::debug!(target: "static_filter", "hi");
67 log::warn!(target: "static_filter", "hi");
68 log::trace!(target: "foo", "hi");
69 })
70 });
71 });
72 group.bench_function("enabled_one", |b| {
73 let filter = "static_filter=info"
74 .parse::<EnvFilter>()
75 .expect("should parse");
76 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
77 b.iter(|| {
78 log::info!(target: "static_filter", "hi");
79 })
80 });
81 });
82 group.bench_function("enabled_many", |b| {
83 let filter = "foo=debug,bar=trace,baz=error,quux=warn,static_filter=info"
84 .parse::<EnvFilter>()
85 .expect("should parse");
86 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
87 b.iter(|| {
88 log::info!(target: "static_filter", "hi");
89 })
90 });
91 });
92 group.bench_function("disabled_level_one", |b| {
93 let filter = "static_filter=info"
94 .parse::<EnvFilter>()
95 .expect("should parse");
96 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
97 b.iter(|| {
98 log::debug!(target: "static_filter", "hi");
99 })
100 });
101 });
102 group.bench_function("disabled_level_many", |b| {
103 let filter = "foo=debug,bar=info,baz=error,quux=warn,static_filter=info"
104 .parse::<EnvFilter>()
105 .expect("should parse");
106 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
107 b.iter(|| {
108 log::trace!(target: "static_filter", "hi");
109 })
110 });
111 });
112 group.bench_function("disabled_one", |b| {
113 let filter = "foo=info".parse::<EnvFilter>().expect("should parse");
114 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
115 b.iter(|| {
116 log::info!(target: "static_filter", "hi");
117 })
118 });
119 });
120 group.bench_function("disabled_many", |b| {
121 let filter = "foo=debug,bar=trace,baz=error,quux=warn,whibble=info"
122 .parse::<EnvFilter>()
123 .expect("should parse");
124 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
125 b.iter(|| {
126 log::info!(target: "static_filter", "hi");
127 })
128 });
129 });
130 group.bench_function("baseline_multithreaded", |b| {
131 let dispatch = Dispatch::new(EnabledSubscriber);
132 b.iter_custom(|iters| {
133 let mut total = Duration::from_secs(0);
134 for _ in 0..iters {
135 let bench = MultithreadedBench::new(dispatch.clone());
136 let elapsed = bench
137 .thread(|| {
138 log::info!(target: "static_filter", "hi");
139 })
140 .thread(|| {
141 log::debug!(target: "static_filter", "hi");
142 })
143 .thread(|| {
144 log::warn!(target: "static_filter", "hi");
145 })
146 .thread(|| {
147 log::warn!(target: "foo", "hi");
148 })
149 .run();
150 total += elapsed;
151 }
152 total
153 })
154 });
155 group.bench_function("multithreaded", |b| {
156 let filter = "static_filter=info"
157 .parse::<EnvFilter>()
158 .expect("should parse");
159 let dispatch = Dispatch::new(EnabledSubscriber.with(filter));
160 b.iter_custom(|iters| {
161 let mut total = Duration::from_secs(0);
162 for _ in 0..iters {
163 let bench = MultithreadedBench::new(dispatch.clone());
164 let elapsed = bench
165 .thread(|| {
166 log::info!(target: "static_filter", "hi");
167 })
168 .thread(|| {
169 log::debug!(target: "static_filter", "hi");
170 })
171 .thread(|| {
172 log::warn!(target: "static_filter", "hi");
173 })
174 .thread(|| {
175 log::warn!(target: "foo", "hi");
176 })
177 .run();
178 total += elapsed;
179 }
180 total
181 });
182 });
183 group.finish();
184 }
185
bench_dynamic(c: &mut Criterion)186 fn bench_dynamic(c: &mut Criterion) {
187 let _ = tracing_log::LogTracer::init();
188
189 let mut group = c.benchmark_group("log/dynamic");
190
191 group.bench_function("baseline_single_threaded", |b| {
192 tracing::subscriber::with_default(EnabledSubscriber, || {
193 b.iter(|| {
194 tracing::info_span!("foo").in_scope(|| {
195 log::info!("hi");
196 log::debug!("hi");
197 });
198 tracing::info_span!("bar").in_scope(|| {
199 log::warn!("hi");
200 });
201 log::trace!("hi");
202 })
203 });
204 });
205 group.bench_function("single_threaded", |b| {
206 let filter = "[foo]=trace".parse::<EnvFilter>().expect("should parse");
207 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
208 b.iter(|| {
209 tracing::info_span!("foo").in_scope(|| {
210 log::info!("hi");
211 log::debug!("hi");
212 });
213 tracing::info_span!("bar").in_scope(|| {
214 log::warn!("hi");
215 });
216 log::trace!("hi");
217 })
218 });
219 });
220 group.bench_function("baseline_multithreaded", |b| {
221 let dispatch = Dispatch::new(EnabledSubscriber);
222 b.iter_custom(|iters| {
223 let mut total = Duration::from_secs(0);
224 for _ in 0..iters {
225 let bench = MultithreadedBench::new(dispatch.clone());
226 let elapsed = bench
227 .thread(|| {
228 let span = tracing::info_span!("foo");
229 let _ = span.enter();
230 log::info!("hi");
231 })
232 .thread(|| {
233 let span = tracing::info_span!("foo");
234 let _ = span.enter();
235 log::debug!("hi");
236 })
237 .thread(|| {
238 let span = tracing::info_span!("bar");
239 let _ = span.enter();
240 log::debug!("hi");
241 })
242 .thread(|| {
243 log::trace!("hi");
244 })
245 .run();
246 total += elapsed;
247 }
248 total
249 })
250 });
251 group.bench_function("multithreaded", |b| {
252 let filter = "[foo]=trace".parse::<EnvFilter>().expect("should parse");
253 let dispatch = Dispatch::new(EnabledSubscriber.with(filter));
254 b.iter_custom(|iters| {
255 let mut total = Duration::from_secs(0);
256 for _ in 0..iters {
257 let bench = MultithreadedBench::new(dispatch.clone());
258 let elapsed = bench
259 .thread(|| {
260 let span = tracing::info_span!("foo");
261 let _ = span.enter();
262 log::info!("hi");
263 })
264 .thread(|| {
265 let span = tracing::info_span!("foo");
266 let _ = span.enter();
267 log::debug!("hi");
268 })
269 .thread(|| {
270 let span = tracing::info_span!("bar");
271 let _ = span.enter();
272 log::debug!("hi");
273 })
274 .thread(|| {
275 log::trace!("hi");
276 })
277 .run();
278 total += elapsed;
279 }
280 total
281 })
282 });
283
284 group.finish();
285 }
286
bench_mixed(c: &mut Criterion)287 fn bench_mixed(c: &mut Criterion) {
288 let _ = tracing_log::LogTracer::init();
289
290 let mut group = c.benchmark_group("log/mixed");
291
292 group.bench_function("disabled", |b| {
293 let filter = "[foo]=trace,bar[quux]=debug,[{baz}]=debug,asdf=warn,wibble=info"
294 .parse::<EnvFilter>()
295 .expect("should parse");
296 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
297 b.iter(|| {
298 log::info!(target: "static_filter", "hi");
299 })
300 });
301 });
302 group.bench_function("disabled_by_level", |b| {
303 let filter = "[foo]=info,bar[quux]=debug,asdf=warn,static_filter=info"
304 .parse::<EnvFilter>()
305 .expect("should parse");
306 tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
307 b.iter(|| {
308 log::trace!(target: "static_filter", "hi");
309 })
310 });
311 });
312 }
313
314 criterion_group!(benches, bench_static, bench_dynamic, bench_mixed);
315 criterion_main!(benches);
316