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