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 mut group = c.benchmark_group("static");
46 
47     group.bench_function("baseline_single_threaded", |b| {
48         tracing::subscriber::with_default(EnabledSubscriber, || {
49             b.iter(|| {
50                 tracing::info!(target: "static_filter", "hi");
51                 tracing::debug!(target: "static_filter", "hi");
52                 tracing::warn!(target: "static_filter", "hi");
53                 tracing::trace!(target: "foo", "hi");
54             })
55         });
56     });
57     group.bench_function("single_threaded", |b| {
58         let filter = "static_filter=info"
59             .parse::<EnvFilter>()
60             .expect("should parse");
61         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
62             b.iter(|| {
63                 tracing::info!(target: "static_filter", "hi");
64                 tracing::debug!(target: "static_filter", "hi");
65                 tracing::warn!(target: "static_filter", "hi");
66                 tracing::trace!(target: "foo", "hi");
67             })
68         });
69     });
70     group.bench_function("enabled_one", |b| {
71         let filter = "static_filter=info"
72             .parse::<EnvFilter>()
73             .expect("should parse");
74         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
75             b.iter(|| {
76                 tracing::info!(target: "static_filter", "hi");
77             })
78         });
79     });
80     group.bench_function("enabled_many", |b| {
81         let filter = "foo=debug,bar=trace,baz=error,quux=warn,static_filter=info"
82             .parse::<EnvFilter>()
83             .expect("should parse");
84         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
85             b.iter(|| {
86                 tracing::info!(target: "static_filter", "hi");
87             })
88         });
89     });
90     group.bench_function("disabled_level_one", |b| {
91         let filter = "static_filter=info"
92             .parse::<EnvFilter>()
93             .expect("should parse");
94         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
95             b.iter(|| {
96                 tracing::debug!(target: "static_filter", "hi");
97             })
98         });
99     });
100     group.bench_function("disabled_level_many", |b| {
101         let filter = "foo=debug,bar=info,baz=error,quux=warn,static_filter=info"
102             .parse::<EnvFilter>()
103             .expect("should parse");
104         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
105             b.iter(|| {
106                 tracing::trace!(target: "static_filter", "hi");
107             })
108         });
109     });
110     group.bench_function("disabled_one", |b| {
111         let filter = "foo=info".parse::<EnvFilter>().expect("should parse");
112         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
113             b.iter(|| {
114                 tracing::info!(target: "static_filter", "hi");
115             })
116         });
117     });
118     group.bench_function("disabled_many", |b| {
119         let filter = "foo=debug,bar=trace,baz=error,quux=warn,whibble=info"
120             .parse::<EnvFilter>()
121             .expect("should parse");
122         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
123             b.iter(|| {
124                 tracing::info!(target: "static_filter", "hi");
125             })
126         });
127     });
128     group.bench_function("baseline_multithreaded", |b| {
129         let dispatch = Dispatch::new(EnabledSubscriber);
130         b.iter_custom(|iters| {
131             let mut total = Duration::from_secs(0);
132             for _ in 0..iters {
133                 let bench = MultithreadedBench::new(dispatch.clone());
134                 let elapsed = bench
135                     .thread(|| {
136                         tracing::info!(target: "static_filter", "hi");
137                     })
138                     .thread(|| {
139                         tracing::debug!(target: "static_filter", "hi");
140                     })
141                     .thread(|| {
142                         tracing::warn!(target: "static_filter", "hi");
143                     })
144                     .thread(|| {
145                         tracing::warn!(target: "foo", "hi");
146                     })
147                     .run();
148                 total += elapsed;
149             }
150             total
151         })
152     });
153     group.bench_function("multithreaded", |b| {
154         let filter = "static_filter=info"
155             .parse::<EnvFilter>()
156             .expect("should parse");
157         let dispatch = Dispatch::new(EnabledSubscriber.with(filter));
158         b.iter_custom(|iters| {
159             let mut total = Duration::from_secs(0);
160             for _ in 0..iters {
161                 let bench = MultithreadedBench::new(dispatch.clone());
162                 let elapsed = bench
163                     .thread(|| {
164                         tracing::info!(target: "static_filter", "hi");
165                     })
166                     .thread(|| {
167                         tracing::debug!(target: "static_filter", "hi");
168                     })
169                     .thread(|| {
170                         tracing::warn!(target: "static_filter", "hi");
171                     })
172                     .thread(|| {
173                         tracing::warn!(target: "foo", "hi");
174                     })
175                     .run();
176                 total += elapsed;
177             }
178             total
179         });
180     });
181     group.finish();
182 }
183 
bench_dynamic(c: &mut Criterion)184 fn bench_dynamic(c: &mut Criterion) {
185     let mut group = c.benchmark_group("dynamic");
186 
187     group.bench_function("baseline_single_threaded", |b| {
188         tracing::subscriber::with_default(EnabledSubscriber, || {
189             b.iter(|| {
190                 tracing::info_span!("foo").in_scope(|| {
191                     tracing::info!("hi");
192                     tracing::debug!("hi");
193                 });
194                 tracing::info_span!("bar").in_scope(|| {
195                     tracing::warn!("hi");
196                 });
197                 tracing::trace!("hi");
198             })
199         });
200     });
201     group.bench_function("single_threaded", |b| {
202         let filter = "[foo]=trace".parse::<EnvFilter>().expect("should parse");
203         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
204             b.iter(|| {
205                 tracing::info_span!("foo").in_scope(|| {
206                     tracing::info!("hi");
207                     tracing::debug!("hi");
208                 });
209                 tracing::info_span!("bar").in_scope(|| {
210                     tracing::warn!("hi");
211                 });
212                 tracing::trace!("hi");
213             })
214         });
215     });
216     group.bench_function("baseline_multithreaded", |b| {
217         let dispatch = Dispatch::new(EnabledSubscriber);
218         b.iter_custom(|iters| {
219             let mut total = Duration::from_secs(0);
220             for _ in 0..iters {
221                 let bench = MultithreadedBench::new(dispatch.clone());
222                 let elapsed = bench
223                     .thread(|| {
224                         let span = tracing::info_span!("foo");
225                         let _ = span.enter();
226                         tracing::info!("hi");
227                     })
228                     .thread(|| {
229                         let span = tracing::info_span!("foo");
230                         let _ = span.enter();
231                         tracing::debug!("hi");
232                     })
233                     .thread(|| {
234                         let span = tracing::info_span!("bar");
235                         let _ = span.enter();
236                         tracing::debug!("hi");
237                     })
238                     .thread(|| {
239                         tracing::trace!("hi");
240                     })
241                     .run();
242                 total += elapsed;
243             }
244             total
245         })
246     });
247     group.bench_function("multithreaded", |b| {
248         let filter = "[foo]=trace".parse::<EnvFilter>().expect("should parse");
249         let dispatch = Dispatch::new(EnabledSubscriber.with(filter));
250         b.iter_custom(|iters| {
251             let mut total = Duration::from_secs(0);
252             for _ in 0..iters {
253                 let bench = MultithreadedBench::new(dispatch.clone());
254                 let elapsed = bench
255                     .thread(|| {
256                         let span = tracing::info_span!("foo");
257                         let _ = span.enter();
258                         tracing::info!("hi");
259                     })
260                     .thread(|| {
261                         let span = tracing::info_span!("foo");
262                         let _ = span.enter();
263                         tracing::debug!("hi");
264                     })
265                     .thread(|| {
266                         let span = tracing::info_span!("bar");
267                         let _ = span.enter();
268                         tracing::debug!("hi");
269                     })
270                     .thread(|| {
271                         tracing::trace!("hi");
272                     })
273                     .run();
274                 total += elapsed;
275             }
276             total
277         })
278     });
279 
280     group.finish();
281 }
282 
bench_mixed(c: &mut Criterion)283 fn bench_mixed(c: &mut Criterion) {
284     let mut group = c.benchmark_group("mixed");
285     group.bench_function("disabled", |b| {
286         let filter = "[foo]=trace,bar[quux]=debug,[{baz}]=debug,asdf=warn,wibble=info"
287             .parse::<EnvFilter>()
288             .expect("should parse");
289         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
290             b.iter(|| {
291                 tracing::info!(target: "static_filter", "hi");
292             })
293         });
294     });
295     group.bench_function("disabled_by_level", |b| {
296         let filter = "[foo]=info,bar[quux]=debug,asdf=warn,static_filter=info"
297             .parse::<EnvFilter>()
298             .expect("should parse");
299         tracing::subscriber::with_default(EnabledSubscriber.with(filter), || {
300             b.iter(|| {
301                 tracing::trace!(target: "static_filter", "hi");
302             })
303         });
304     });
305 }
306 
307 criterion_group!(benches, bench_static, bench_dynamic, bench_mixed);
308 criterion_main!(benches);
309