1 | use criterion::{criterion_group, criterion_main, BenchmarkId, Criterion, Throughput}; |
2 | use std::{io, time::Duration}; |
3 | |
4 | mod support; |
5 | use support::MultithreadedBench; |
6 | |
7 | /// A fake writer that doesn't actually do anything. |
8 | /// |
9 | /// We want to measure the subscriber's overhead, *not* the performance of |
10 | /// stdout/file writers. Using a no-op Write implementation lets us only measure |
11 | /// the subscriber's overhead. |
12 | struct NoWriter; |
13 | |
14 | impl io::Write for NoWriter { |
15 | fn write(&mut self, buf: &[u8]) -> io::Result<usize> { |
16 | Ok(buf.len()) |
17 | } |
18 | |
19 | fn flush(&mut self) -> io::Result<()> { |
20 | Ok(()) |
21 | } |
22 | } |
23 | |
24 | impl NoWriter { |
25 | fn new() -> Self { |
26 | Self |
27 | } |
28 | } |
29 | |
30 | fn bench_new_span(c: &mut Criterion) { |
31 | bench_thrpt(c, "new_span" , |group, i| { |
32 | group.bench_with_input(BenchmarkId::new("single_thread" , i), i, |b, &i| { |
33 | tracing::dispatcher::with_default(&mk_dispatch(), || { |
34 | b.iter(|| { |
35 | for n in 0..i { |
36 | let _span = tracing::info_span!("span" , n); |
37 | } |
38 | }) |
39 | }); |
40 | }); |
41 | group.bench_with_input(BenchmarkId::new("multithreaded" , i), i, |b, &i| { |
42 | b.iter_custom(|iters| { |
43 | let mut total = Duration::from_secs(0); |
44 | let dispatch = mk_dispatch(); |
45 | for _ in 0..iters { |
46 | let bench = MultithreadedBench::new(dispatch.clone()); |
47 | let elapsed = bench |
48 | .thread(move || { |
49 | for n in 0..i { |
50 | let _span = tracing::info_span!("span" , n); |
51 | } |
52 | }) |
53 | .thread(move || { |
54 | for n in 0..i { |
55 | let _span = tracing::info_span!("span" , n); |
56 | } |
57 | }) |
58 | .thread(move || { |
59 | for n in 0..i { |
60 | let _span = tracing::info_span!("span" , n); |
61 | } |
62 | }) |
63 | .thread(move || { |
64 | for n in 0..i { |
65 | let _span = tracing::info_span!("span" , n); |
66 | } |
67 | }) |
68 | .run(); |
69 | total += elapsed; |
70 | } |
71 | total |
72 | }) |
73 | }); |
74 | }); |
75 | } |
76 | |
77 | type Group<'a> = criterion::BenchmarkGroup<'a, criterion::measurement::WallTime>; |
78 | fn bench_thrpt(c: &mut Criterion, name: &'static str, mut f: impl FnMut(&mut Group<'_>, &usize)) { |
79 | const N_SPANS: &[usize] = &[1, 10, 50]; |
80 | |
81 | let mut group = c.benchmark_group(name); |
82 | for spans in N_SPANS { |
83 | group.throughput(Throughput::Elements(*spans as u64)); |
84 | f(&mut group, spans); |
85 | } |
86 | group.finish(); |
87 | } |
88 | |
89 | fn mk_dispatch() -> tracing::Dispatch { |
90 | let subscriber = tracing_subscriber::FmtSubscriber::builder() |
91 | .with_writer(NoWriter::new) |
92 | .finish(); |
93 | tracing::Dispatch::new(subscriber) |
94 | } |
95 | |
96 | fn bench_event(c: &mut Criterion) { |
97 | bench_thrpt(c, "event" , |group, i| { |
98 | group.bench_with_input(BenchmarkId::new("root/single_threaded" , i), i, |b, &i| { |
99 | let dispatch = mk_dispatch(); |
100 | tracing::dispatcher::with_default(&dispatch, || { |
101 | b.iter(|| { |
102 | for n in 0..i { |
103 | tracing::info!(n); |
104 | } |
105 | }) |
106 | }); |
107 | }); |
108 | group.bench_with_input(BenchmarkId::new("root/multithreaded" , i), i, |b, &i| { |
109 | b.iter_custom(|iters| { |
110 | let mut total = Duration::from_secs(0); |
111 | let dispatch = mk_dispatch(); |
112 | for _ in 0..iters { |
113 | let bench = MultithreadedBench::new(dispatch.clone()); |
114 | let elapsed = bench |
115 | .thread(move || { |
116 | for n in 0..i { |
117 | tracing::info!(n); |
118 | } |
119 | }) |
120 | .thread(move || { |
121 | for n in 0..i { |
122 | tracing::info!(n); |
123 | } |
124 | }) |
125 | .thread(move || { |
126 | for n in 0..i { |
127 | tracing::info!(n); |
128 | } |
129 | }) |
130 | .thread(move || { |
131 | for n in 0..i { |
132 | tracing::info!(n); |
133 | } |
134 | }) |
135 | .run(); |
136 | total += elapsed; |
137 | } |
138 | total |
139 | }) |
140 | }); |
141 | group.bench_with_input( |
142 | BenchmarkId::new("unique_parent/single_threaded" , i), |
143 | i, |
144 | |b, &i| { |
145 | tracing::dispatcher::with_default(&mk_dispatch(), || { |
146 | let span = tracing::info_span!("unique_parent" , foo = false); |
147 | let _guard = span.enter(); |
148 | b.iter(|| { |
149 | for n in 0..i { |
150 | tracing::info!(n); |
151 | } |
152 | }) |
153 | }); |
154 | }, |
155 | ); |
156 | group.bench_with_input( |
157 | BenchmarkId::new("unique_parent/multithreaded" , i), |
158 | i, |
159 | |b, &i| { |
160 | b.iter_custom(|iters| { |
161 | let mut total = Duration::from_secs(0); |
162 | let dispatch = mk_dispatch(); |
163 | for _ in 0..iters { |
164 | let bench = MultithreadedBench::new(dispatch.clone()); |
165 | let elapsed = bench |
166 | .thread_with_setup(move |start| { |
167 | let span = tracing::info_span!("unique_parent" , foo = false); |
168 | let _guard = span.enter(); |
169 | start.wait(); |
170 | for n in 0..i { |
171 | tracing::info!(n); |
172 | } |
173 | }) |
174 | .thread_with_setup(move |start| { |
175 | let span = tracing::info_span!("unique_parent" , foo = false); |
176 | let _guard = span.enter(); |
177 | start.wait(); |
178 | for n in 0..i { |
179 | tracing::info!(n); |
180 | } |
181 | }) |
182 | .thread_with_setup(move |start| { |
183 | let span = tracing::info_span!("unique_parent" , foo = false); |
184 | let _guard = span.enter(); |
185 | start.wait(); |
186 | for n in 0..i { |
187 | tracing::info!(n); |
188 | } |
189 | }) |
190 | .thread_with_setup(move |start| { |
191 | let span = tracing::info_span!("unique_parent" , foo = false); |
192 | let _guard = span.enter(); |
193 | start.wait(); |
194 | for n in 0..i { |
195 | tracing::info!(n); |
196 | } |
197 | }) |
198 | .run(); |
199 | total += elapsed; |
200 | } |
201 | total |
202 | }) |
203 | }, |
204 | ); |
205 | group.bench_with_input( |
206 | BenchmarkId::new("shared_parent/multithreaded" , i), |
207 | i, |
208 | |b, &i| { |
209 | b.iter_custom(|iters| { |
210 | let dispatch = mk_dispatch(); |
211 | let mut total = Duration::from_secs(0); |
212 | for _ in 0..iters { |
213 | let parent = tracing::dispatcher::with_default(&dispatch, || { |
214 | tracing::info_span!("shared_parent" , foo = "hello world" ) |
215 | }); |
216 | let bench = MultithreadedBench::new(dispatch.clone()); |
217 | let parent2 = parent.clone(); |
218 | bench.thread_with_setup(move |start| { |
219 | let _guard = parent2.enter(); |
220 | start.wait(); |
221 | for n in 0..i { |
222 | tracing::info!(n); |
223 | } |
224 | }); |
225 | let parent2 = parent.clone(); |
226 | bench.thread_with_setup(move |start| { |
227 | let _guard = parent2.enter(); |
228 | start.wait(); |
229 | for n in 0..i { |
230 | tracing::info!(n); |
231 | } |
232 | }); |
233 | let parent2 = parent.clone(); |
234 | bench.thread_with_setup(move |start| { |
235 | let _guard = parent2.enter(); |
236 | start.wait(); |
237 | for n in 0..i { |
238 | tracing::info!(n); |
239 | } |
240 | }); |
241 | let parent2 = parent.clone(); |
242 | bench.thread_with_setup(move |start| { |
243 | let _guard = parent2.enter(); |
244 | start.wait(); |
245 | for n in 0..i { |
246 | tracing::info!(n); |
247 | } |
248 | }); |
249 | let elapsed = bench.run(); |
250 | total += elapsed; |
251 | } |
252 | total |
253 | }) |
254 | }, |
255 | ); |
256 | group.bench_with_input( |
257 | BenchmarkId::new("multi-parent/multithreaded" , i), |
258 | i, |
259 | |b, &i| { |
260 | b.iter_custom(|iters| { |
261 | let dispatch = mk_dispatch(); |
262 | let mut total = Duration::from_secs(0); |
263 | for _ in 0..iters { |
264 | let parent = tracing::dispatcher::with_default(&dispatch, || { |
265 | tracing::info_span!("multiparent" , foo = "hello world" ) |
266 | }); |
267 | let bench = MultithreadedBench::new(dispatch.clone()); |
268 | let parent2 = parent.clone(); |
269 | bench.thread_with_setup(move |start| { |
270 | let _guard = parent2.enter(); |
271 | start.wait(); |
272 | let mut span = tracing::info_span!("parent" ); |
273 | for n in 0..i { |
274 | let s = tracing::info_span!(parent: &span, "parent2" , n, i); |
275 | s.in_scope(|| { |
276 | tracing::info!(n); |
277 | }); |
278 | span = s; |
279 | } |
280 | }); |
281 | let parent2 = parent.clone(); |
282 | bench.thread_with_setup(move |start| { |
283 | let _guard = parent2.enter(); |
284 | start.wait(); |
285 | let mut span = tracing::info_span!("parent" ); |
286 | for n in 0..i { |
287 | let s = tracing::info_span!(parent: &span, "parent2" , n, i); |
288 | s.in_scope(|| { |
289 | tracing::info!(n); |
290 | }); |
291 | span = s; |
292 | } |
293 | }); |
294 | let parent2 = parent.clone(); |
295 | bench.thread_with_setup(move |start| { |
296 | let _guard = parent2.enter(); |
297 | start.wait(); |
298 | let mut span = tracing::info_span!("parent" ); |
299 | for n in 0..i { |
300 | let s = tracing::info_span!(parent: &span, "parent2" , n, i); |
301 | s.in_scope(|| { |
302 | tracing::info!(n); |
303 | }); |
304 | span = s; |
305 | } |
306 | }); |
307 | let parent2 = parent.clone(); |
308 | bench.thread_with_setup(move |start| { |
309 | let _guard = parent2.enter(); |
310 | start.wait(); |
311 | let mut span = tracing::info_span!("parent" ); |
312 | for n in 0..i { |
313 | let s = tracing::info_span!(parent: &span, "parent2" , n, i); |
314 | s.in_scope(|| { |
315 | tracing::info!(n); |
316 | }); |
317 | span = s; |
318 | } |
319 | }); |
320 | let elapsed = bench.run(); |
321 | total += elapsed; |
322 | } |
323 | total |
324 | }) |
325 | }, |
326 | ); |
327 | }); |
328 | } |
329 | |
330 | criterion_group!(benches, bench_new_span, bench_event); |
331 | criterion_main!(benches); |
332 | |