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 {
write(&mut self, buf: &[u8]) -> io::Result<usize>15 fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
16 Ok(buf.len())
17 }
18
flush(&mut self) -> io::Result<()>19 fn flush(&mut self) -> io::Result<()> {
20 Ok(())
21 }
22 }
23
24 impl NoWriter {
new() -> Self25 fn new() -> Self {
26 Self
27 }
28 }
29
bench_new_span(c: &mut Criterion)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>;
bench_thrpt(c: &mut Criterion, name: &'static str, mut f: impl FnMut(&mut Group<'_>, &usize))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
mk_dispatch() -> tracing::Dispatch89 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
bench_event(c: &mut Criterion)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