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 { |
13 | fn new_span(&self, span: &span::Attributes<'_>) -> Id { |
14 | let _ = span; |
15 | Id::from_u64(0xDEAD_FACE) |
16 | } |
17 | |
18 | fn event(&self, event: &Event<'_>) { |
19 | let _ = event; |
20 | } |
21 | |
22 | fn record(&self, span: &Id, values: &span::Record<'_>) { |
23 | let _ = (span, values); |
24 | } |
25 | |
26 | fn record_follows_from(&self, span: &Id, follows: &Id) { |
27 | let _ = (span, follows); |
28 | } |
29 | |
30 | fn enabled(&self, metadata: &Metadata<'_>) -> bool { |
31 | let _ = metadata; |
32 | true |
33 | } |
34 | |
35 | fn enter(&self, span: &Id) { |
36 | let _ = span; |
37 | } |
38 | |
39 | fn exit(&self, span: &Id) { |
40 | let _ = span; |
41 | } |
42 | } |
43 | |
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 | |
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 | |
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 | |