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 _ = 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 | |
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 | |
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 | |