Hi all,

I’m trying to analyze the runtime of a function f() and understand which of its components contribute most to its total execution time.

Using both Criterion and manual timing with Instant::now() (i.e. by doing let start = Instant::now(); at the beginning and then printing start.elapsed() at the end.), I measured f() to take roughly 40 ms.

When I use the latter technique on its components, one function g() inside f() seems to take about 17ms, and another h() takes 23ms; this adds up!

When I use criterion however, the latter function h() only takes about 12ms. I've tried two variants, but both give the same result:

fn bench_h(c: &mut Criterion) {
     let x = g();
     c.bench_function(“…”,
          |b| {
             b.iter(|| {
               let y = h(x);           
               black_box(y);
             });      
           });

fn bench_h(c: &mut Criterion) {
   c.bench_function(“…” |b| {
        b.iter_with_setup(
             let x = g();
             }, 
             |x| {
                let y = h(x);
                black_box(y);
              }

This discrepancy is confusing. I'd like to understand:

• Why does Criterion report such a different number?

• Is it due to optimization, warm-up, CPU frequency scaling, or something else?

• What’s the best way to get realistic per-component timings within a larger function?

Manually printing timing info gets messy fast, so I’m hoping there’s a better, more reliable way.

3 posts - 3 participants

Read full topic