auto_bench_fct 1.0.1

//! A library for automatically benchmarking function call count and execution time in Rust.
//!
//! Minimal setup is required to use this library, a macro attribute is provided
//! to enable automatic benchmarking of functions, and a function to print the results.
//!
//! - Enable the `disable` feature to disable the library, which will make the macros and
//! functions to do nothing, allowing to keep the code in production without performance overhead.
//! - Enable the `disable_hy` feature to disable only the call stack hierarchy tracking, which will
//! make the macros `#[auto_bench_fct_hy]` behave like `#[auto_bench_fct]`.
//! - Enable the `log` feature to log the results using the `log` crate with the info level.
//!
//! This crate supports multithreaded programs, and uses wall time to measure the execution time of
//! functions, which is suitable for most use cases.
//!
//! # Usage
//!
//! ## Define which functions to benchmark
//!
//! Add the `#[auto_bench_fct]` macro attribute to a function to track its execution time and calls
//! count, or addd the `#[auto_bench_fct_hy]` macro attribute to track its execution time
//! and calls count both globally and in the call stack hierarchy.
//!
//! ## Print the results
//!
//! - Print the benchmark of functions with the macro attribute `#[auto_bench_fct]`
//! or `#[auto_bench_fct_hy]` grouped by function using [`print_bench_fct_results`].
//! - Print the benchmark of functions with the macro attribute `#[auto_bench_fct_hy]` grouped by
//! function and call stack context using [`print_bench_fct_hy_results`].
//!
//! ## Usage recommendations
//!
//! Use the `#[auto_bench_fct_hy]` macro attribute for functions you want to benchmark, and
//! use `#[auto_bench_fct]` instead only if you want to exclude the function from the call stack
//! hierarchy.
//! When not wanting to debug the call stack hierarchy due to the performance overhead,
//! enable the feature `disable_hy`.
//! When not wanting to debug the function calls at all, enable the feature `disable`.
//!
//! # Note about recursive functions
//!
//! Recursive functions are supported and will be tracked correctly,
//! tracking only the root function call execution time.
//! Though, mutual recursion is not supported, meaning that if two functions call each other
//! recursively, it may create a huge number of entries in the metrics.
//!
//! # Note about performance
//!
//! This library is designed to be used in development and testing environments.
//! It may have a large performance overhead, mostly if used on recursive functions
//! or in functions with a large number of calls and a small execution time.
//! The macro `#[auto_bench_fct_hy]` has a larger performance overhead than `#[auto_bench_fct]`
//! and should not be used in non-heavy functions.
//!

pub use auto_bench_fct_macros::auto_bench_fct;
pub use auto_bench_fct_macros::auto_bench_fct_hy;
use std::cell::RefCell;
use colored::Colorize;
use std::collections::HashMap;
use std::sync::Mutex;
use std::time::Duration;
use lazy_static::lazy_static;
#[cfg(feature = "log")]
use log::info;

thread_local! {
    /// Stores the current call stack of function indices.
    /// The function index is a unique u32 identifier for the function.
    pub static CALL_STACK: RefCell<Vec<u32>> = RefCell::new(Vec::new());
}
lazy_static! {
    /// Stores the function call count and total duration for each function.
    /// The function index is a unique u32 identifier for the function.
    /// Mapping: (Function name, Function index) -> (Call count, Total duration)
    pub static ref FUNCTION_METRICS: Mutex<HashMap<(String, u32), (u64, Duration)>> = Mutex::new(HashMap::new());

    /// Stores the function call count and total duration for each function in a specific call stack.
    /// The function index is a unique u32 identifier for the function.
    /// Mapping: (function index stack) -> (Function name, Function index) -> (Call count, Total duration)
    pub static ref FUNCTION_METRICS_HIERARCHY: Mutex<HashMap<Vec<u32>, HashMap<(String, u32), (u64, Duration)>>> = Mutex::new(HashMap::new());
}

/// Gets the raw function metrics.
/// The function index is a unique u32 identifier for the function.
/// Mapping: (Function name, Function index) -> (Call count, Total duration)
/// This map is filled by execution of functions with the macro attribute `#[auto_bench_fct]`
/// or `#[auto_bench_fct_hy]`.
pub fn get_bench_fct_results() -> HashMap<(String, u32), (u64, Duration)> {
    FUNCTION_METRICS.lock().unwrap().clone()
}

/// Gets the raw function metrics grouped by call stack hierarchy.
/// The function index is a unique u32 identifier for the function.
/// Mapping: (function index stack) -> (Function name, Function index) -> (Call count, Total duration)
/// This map is filled by execution of functions with the macro attribute `#[auto_bench_fct_hy]`.
pub fn get_bench_fct_hy_results() -> HashMap<Vec<u32>, HashMap<(String, u32), (u64, Duration)>> {
    FUNCTION_METRICS_HIERARCHY.lock().unwrap().clone()
}

/// Prints the function benchmark results in stdout.
/// If the `log` feature is enabled, it will log the results using `log::info!`.
/// If the `disable` feature is enabled, this function does nothing.
#[cfg(not(feature = "disable"))]
pub fn print_bench_fct_results() {
    let report = FUNCTION_METRICS.lock().unwrap();
    let grouped_report = report.iter().fold(HashMap::new(), |mut acc, el| {
        let ((key_str, key_id), value) = el;
        let (count, duration) = acc
            .entry(key_str.clone())
            .or_insert(HashMap::new())
            .entry(*key_id)
            .or_insert((0, Duration::ZERO));
        *count += value.0;
        *duration += value.1;
        acc
    });
    let mut vec_report = Vec::with_capacity(grouped_report.len());
    for (key_str, map) in grouped_report.iter() {
        if map.len() == 1 {
            let (_key_id, (count, duration)) = map.iter().next().unwrap();
            vec_report.push((key_str, None, *count, *duration));
        } else {
            for (key_id, (count, duration)) in map.iter() {
                vec_report.push((key_str, Some(key_id), *count, *duration));
            }
        }
    }
    vec_report
        .sort_by(|(_, _, count1, duration1), (_, _, count2, duration2)| duration2.div_f64(*count2 as f64).cmp(&duration1.div_f64(*count1 as f64)));

    let vec_report_str = vec_report
        .into_iter()
        .map(|(key_str, key_id, count, duration)| {
            let key = if let Some(id) = key_id {
                format!("{} ({})", key_str, id)
            } else {
                format!("{}", key_str)
            };
            let call_count = format!("{}", count);
            let took_count = format_duration(duration);
            let took_avg_count = format_duration(duration.div_f64(count as f64));
            (
                key.blue().bold(),
                call_count.red().bold(),
                took_count.green().bold(),
                took_avg_count.green().bold(),
            )
        })
        .collect::<Vec<_>>();

    let largest_key_len = vec_report_str.iter().map(|(key, _, _, _)| key.len()).max().unwrap_or(0);
    let largest_count_len = vec_report_str.iter().map(|(_, count, _, _)| count.len()).max().unwrap_or(0);
    let largest_took_len = vec_report_str.iter().map(|(_, _, took, _)| took.len()).max().unwrap_or(0);
    let largest_took_avg_len = vec_report_str.iter().map(|(_, _, _, took_avg)| took_avg.len()).max().unwrap_or(0);

    for (key, call_count, took_count, took_avg_count) in vec_report_str.into_iter() {
        let key = format!("{:width$}", key, width = largest_key_len);
        let call_count = format!("{:>width$}", call_count, width = largest_count_len);
        let took_count = format!("{:>width$}", took_count, width = largest_took_len);
        let took_avg_count = format!("{:>width$}", took_avg_count, width = largest_took_avg_len);
        #[cfg(feature = "log")]
        info!(
            "{} called {} times, took {} ({} on average)",
            key, call_count, took_count, took_avg_count
        );
        #[cfg(not(feature = "log"))]
        println!(
            "{} called {} times, took {} ({} on average)",
            key, call_count, took_count, took_avg_count
        );
    }
}
#[cfg(feature = "disable")]
pub fn print_bench_fct_results() {}

/// Prints the function hierarchy benchmark results in stdout.
/// If the `log` feature is enabled, it will log the results using `log::info!`.
/// If the `disable_hy` feature is enabled, this function does nothing.
/// If the `disable` feature is enabled, this function does nothing.
#[cfg(not(feature = "disable"))]
pub fn print_bench_fct_hy_results() {
    let report = FUNCTION_METRICS_HIERARCHY.lock().unwrap();
    print_hierarchy_helper(&report, Vec::new(), 0);
}
#[cfg(feature = "disable")]
pub fn print_bench_fct_hy_results() {}

#[cfg(not(feature = "disable"))]
fn print_hierarchy_helper(report: &HashMap<Vec<u32>, HashMap<(String, u32), (u64, Duration)>>, mut stack: Vec<u32>, indent: usize) {
    if let Some(children) = report.get(&stack) {
        let mut children = children
            .iter()
            .map(|((func_name, func_id), (count, duration))| (func_name.clone(), *func_id, *count, *duration))
            .collect::<Vec<_>>();

        children.sort_by(|(_, _, count1, duration1), (_, _, count2, duration2)| {
            let avg1 = duration1.as_secs_f64() / (*count1 as f64);
            let avg2 = duration2.as_secs_f64() / (*count2 as f64);
            avg2.partial_cmp(&avg1).unwrap()
        });

        let formatted_data: Vec<_> = children
            .into_iter()
            .map(|(func_name, func_id, count, duration)| (func_id, format_benchmark_data(&func_name, count, duration)))
            .collect();

        let max_key_len = formatted_data.iter().map(|(_, (key, _, _, _))| key.len()).max().unwrap_or(0);
        let max_count_len = formatted_data.iter().map(|(_, (_, count, _, _))| count.len()).max().unwrap_or(0);
        let max_took_len = formatted_data.iter().map(|(_, (_, _, took, _))| took.len()).max().unwrap_or(0);
        let max_took_avg_len = formatted_data.iter().map(|(_, (_, _, _, took_avg))| took_avg.len()).max().unwrap_or(0);

        for (func_id, (key, count, took, took_avg)) in formatted_data {
            print_benchmark_formatted_data(key, count, took, took_avg, max_key_len, max_count_len, max_took_len, max_took_avg_len, indent);
            stack.push(func_id);
            print_hierarchy_helper(report, stack.clone(), indent + 2);
            stack.pop();
        }
    }
}

#[cfg(not(feature = "disable"))]
fn print_benchmark_formatted_data(
    key: String,
    count: String,
    took: String,
    took_avg: String,
    max_key: usize,
    max_count: usize,
    max_took: usize,
    max_took_avg: usize,
    indent: usize,
) {
    let key = format!("{:width$}", key, width = max_key);
    let count = format!("{:>width$}", count, width = max_count);
    let took = format!("{:>width$}", took, width = max_took);
    let took_avg = format!("{:>width$}", took_avg, width = max_took_avg);
    let indent_str = if indent > 0 {
        " ".repeat(indent)
    } else {
        String::new()
    };
    #[cfg(feature = "log")]
    info!(
        "{}{}: called {} times, took {} ({} on average)",
        indent_str,
        key.blue().bold(),
        count.red().bold(),
        took.green().bold(),
        took_avg.green().bold()
    );
    #[cfg(not(feature = "log"))]
    println!(
        "{}{}: called {} times, took {} ({} on average)",
        indent_str,
        key.blue().bold(),
        count.red().bold(),
        took.green().bold(),
        took_avg.green().bold()
    );
}

#[cfg(not(feature = "disable"))]
fn format_benchmark_data(func_name: &String, count: u64, duration: Duration) -> (String, String, String, String) {
    let func_key = func_name.to_string();

    let call_count = format!("{}", count);
    let took_count = format_duration(duration);
    let took_avg_count = format_duration(duration.div_f64(count as f64));

    (func_key, call_count, took_count, took_avg_count)
}

#[cfg(not(feature = "disable"))]
fn format_duration(duration: Duration) -> String {
    if duration.as_secs() < 10 {
        if duration.as_millis() < 10 {
            if duration.as_micros() < 10 {
                format!("{:.0}ns", duration.as_nanos())
            } else {
                format!("{:.0}µs", duration.as_micros())
            }
        } else {
            format!("{:.0}ms", duration.as_millis())
        }
    } else {
        format!("{:.0}s ", duration.as_secs_f64())
    }
}