time_logging.rs

use std::time::{Duration, Instant, SystemTime};
use std::hint::black_box;
use clap::Parser;

#[derive(Parser, Debug)]
#[command(author, version, about, long_about = None)]
struct Args {
    /// Number of outer iterations for each timing method
    #[arg(long, default_value_t = 15_000)]
    iterations: u64,

    /// Number of time measurements per iteration
    #[arg(long, default_value_t = 10)]
    measurements_per_iter: u64,
}

#[cfg(target_arch = "aarch64")]
#[inline(always)]
fn read_cycle_counter() -> u64 {
    // CNTVCT_EL0 is the virtual counter register on ARM
    unsafe {
        let val: u64;
        std::arch::asm!("mrs {}, CNTVCT_EL0", out(reg) val);
        val
    }
}

#[cfg(target_arch = "x86_64")]
#[inline(always)]
fn read_cycle_counter() -> u64 {
    unsafe { std::arch::x86_64::_rdtsc() }
}

fn main() {
    let args = Args::parse();
    println!("Running with args: {:?}", args);
    
    // Benchmark SystemTime
    let start = Instant::now();
    for _ in 0..args.iterations {
        for _ in 0..args.measurements_per_iter {
            black_box(SystemTime::now());
        }
    }
    let system_time_duration = start.elapsed();

    // Benchmark Instant (monotonic clock)
    let start = Instant::now();
    for _ in 0..args.iterations {
        for _ in 0..args.measurements_per_iter {
            black_box(Instant::now());
        }
    }
    let instant_duration = start.elapsed();

    // Benchmark CPU cycles
    let cycles_duration = {
        let start = Instant::now();
        for _ in 0..args.iterations {
            for _ in 0..args.measurements_per_iter {
                black_box(read_cycle_counter());
            }
        }
        start.elapsed()
    };

    let total_measurements = args.iterations * args.measurements_per_iter;
    println!("Time measurements over {} total measurements ({} iterations × {} per iteration):", 
        total_measurements, args.iterations, args.measurements_per_iter);
    println!("SystemTime::now(): {:?} ({:?} per call)", 
        system_time_duration, system_time_duration / total_measurements as u32);
    println!("Instant::now(): {:?} ({:?} per call)", 
        instant_duration, instant_duration / total_measurements as u32);
    println!("CPU cycles: {:?} ({:?} per call)", 
        cycles_duration, cycles_duration / total_measurements as u32);
}

Calling Instant::now() over and over is not so cheap:

Running with args: Args { iterations: 15000, measurements_per_iter: 10 }
Time measurements over 150000 total measurements (15000 iterations × 10 per iteration):
SystemTime::now(): 2.905833ms (19ns per call)
Instant::now(): 3.045417ms (20ns per call)
CPU cycles: 806.917µs (5ns per call)

Better to do it once and reuse it:

Running with args: Args { iterations: 15000, measurements_per_iter: 1 }
Time measurements over 15000 total measurements (15000 iterations × 1 per iteration):
SystemTime::now(): 345.833µs (23ns per call)
Instant::now(): 342.625µs (22ns per call)
CPU cycles: 158.042µs (10ns per call)