functionrustbenchmarking

Two empty functions produce different runtime when measured in Rust with Instant::now calls


I wrote two empty functions in rust with the hope of using each to test the use of retain on vectors or the use of filter on iterators, after writing the empty function for each case, on running the program, i noticed a huge dissimilarity between the duration of each function, this means that adding any logic to the currently empty function would lead to erroneous conclusions on their execution time.

use std::time::Instant;

fn use_filter() {
    
}

fn use_retain() {
    
}

fn run_multiple(f: fn(), times: u64) {
    for _ in 0..times {
        f()
    }
} 

fn main() {
    let iter_count: u32 = 1_000_000_000;
    
    let _start_1 = Instant::now();
    run_multiple(use_filter, iter_count as u64);
    let duration = Instant::now() - _start_1;
    println!("Use Filter duration: {:?}", duration / iter_count);
    
    let _start_2 = Instant::now();
    run_multiple(use_retain, iter_count as u64);
    let duration = Instant::now() - _start_2;
    println!("Use Retain duration: {:?}", duration / iter_count);
}

Expected output

Use Filter duration: xns
Use Retain duration: xns

where x is the same for both function, since they are both empty and do nothing

Actual Output

Use Filter duration: 8ns
Use Retain duration: 10ns

what could explain empty functions having very different execution time in rust programming language.


Solution

  • The result as given in the question is entirely due to noise, and carries no useful information. What the code compiles down to is

        movq    std::time::Instant::now@GOTPCREL(%rip), %r14
        callq   *%r14       // First call to `Instant::now()`
        movq    %rax, %rbx
                            // `use_filter` went away entirely, as one would expect
        movl    %edx, %ebp
        callq   *%r14       // Second call to `Instand::now()`
        movq    %rax, %rdi
        movl    %edx, %esi
        movq    %rbx, %rdx
        movl    %ebp, %ecx
        callq   *<std::time::Instant as core::ops::arith::Sub>::sub@GOTPCREL(%rip)
                            // [...] print result
        callq   *%r14       // Third call to `Instant::now()`
        movq    %rax, %rbx
                            // `use_retention` went away entirely
        movl    %edx, %ebp
        callq   *%r14       // Third call to `Instant::now()`
        movq    %rax, %rdi
        movl    %edx, %esi
        movq    %rbx, %rdx
        movl    %ebp, %ecx
        callq   *<std::time::Instant as core::ops::arith::Sub>::sub@GOTPCREL(%rip)
                            // [...] print result
    

    That is, the time difference you are measuring is the time it took to issue the two calls to Instant::now(), with nothing in between. There is no difference. The time difference you are seeing is caused by inaccuracies in the implementation of Instant::now(), thread-scheduling, or general noise.