solana/measure/src/measure.rs

use {
    solana_sdk::timing::{duration_as_ms, duration_as_ns, duration_as_s, duration_as_us},
    std::{
        fmt,
        time::{Duration, Instant},
    },
};

#[derive(Debug)]
pub struct Measure {
    name: &'static str,
    start: Instant,
    duration: u64,
}

impl Measure {
    pub fn start(name: &'static str) -> Self {
        Self {
            name,
            start: Instant::now(),
            duration: 0,
        }
    }

    pub fn stop(&mut self) {
        self.duration = duration_as_ns(&self.start.elapsed());
    }

    pub fn as_ns(&self) -> u64 {
        self.duration
    }

    pub fn as_us(&self) -> u64 {
        self.duration / 1000
    }

    pub fn as_ms(&self) -> u64 {
        self.duration / (1000 * 1000)
    }

    pub fn as_s(&self) -> f32 {
        self.duration as f32 / (1000.0f32 * 1000.0f32 * 1000.0f32)
    }

    pub fn as_duration(&self) -> Duration {
        Duration::from_nanos(self.as_ns())
    }

    pub fn end_as_ns(self) -> u64 {
        duration_as_ns(&self.start.elapsed())
    }

    pub fn end_as_us(self) -> u64 {
        duration_as_us(&self.start.elapsed())
    }

    pub fn end_as_ms(self) -> u64 {
        duration_as_ms(&self.start.elapsed())
    }

    pub fn end_as_s(self) -> f32 {
        duration_as_s(&self.start.elapsed())
    }

    pub fn end_as_duration(self) -> Duration {
        self.start.elapsed()
    }
}

impl fmt::Display for Measure {
    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
        if self.duration == 0 {
            write!(f, "{} running", self.name)
        } else if self.as_us() < 1 {
            write!(f, "{} took {}ns", self.name, self.duration)
        } else if self.as_ms() < 1 {
            write!(f, "{} took {}us", self.name, self.as_us())
        } else if self.as_s() < 1. {
            write!(f, "{} took {}ms", self.name, self.as_ms())
        } else {
            write!(f, "{} took {:.1}s", self.name, self.as_s())
        }
    }
}

#[cfg(test)]
mod tests {
    use {
        super::*,
        std::{fmt::Debug, thread::sleep},
    };

    #[test]
    fn test_measure() {
        let mut measure = Measure::start("test");
        sleep(Duration::from_millis(100));
        measure.stop();

        // We have observed failures with margins of 10%, when CI machines are very busy, running
        // multiple tests in parallel.  As we are not testing the timer functionality itself, it is
        // probably OK to increase the margins to 20%.

        assert!(measure.as_s() >= 0.08f32 && measure.as_s() <= 0.12f32);
        assert!(measure.as_ms() >= 80 && measure.as_ms() <= 120);
        assert!(measure.as_us() >= 80_000 && measure.as_us() <= 120_000);
        assert!(measure.as_ns() >= 80_000_000 && measure.as_ns() <= 120_000_000);
        assert!(
            measure.as_duration() >= Duration::from_millis(90)
                && measure.as_duration() <= Duration::from_millis(110)
        );
    }

    #[test]
    fn test_measure_end_as() {
        #[track_caller]
        fn test_end_as<Res>(method: fn(Measure) -> Res, sleep_ms: u64, lower: Res, upper: Res)
        where
            Res: PartialOrd + Debug,
        {
            let measure = Measure::start("test");
            sleep(Duration::from_millis(sleep_ms));
            let result = method(measure);
            assert!(
                result >= lower,
                "Result below the expected bound.\n\
                 Lower bound: {lower:?}\n\
                 Result: {result:?}"
            );
            assert!(
                result <= upper,
                "Result above the expected bound.\n\
                 Upper bound: {upper:?}\n\
                 Result: {result:?}"
            );
        }

        // We have observed failures with margins of 10%, when CI machines are very busy, running
        // multiple tests in parallel.  As we are not testing the timer functionality itself, it is
        // probably OK to increase the margins to 20%.

        test_end_as(Measure::end_as_s, 100, 0.08f32, 0.12f32);
        test_end_as(Measure::end_as_ms, 100, 80, 120);
        test_end_as(Measure::end_as_us, 100, 80_000, 120_000);
        test_end_as(Measure::end_as_ns, 100, 80_000_000, 120_000_000);
        test_end_as(
            Measure::end_as_duration,
            100,
            Duration::from_millis(80),
            Duration::from_millis(120),
        );
    }

    #[test]
    fn test_measure_display() {
        let measure = Measure {
            name: "test_ns",
            start: Instant::now(),
            duration: 1,
        };
        assert_eq!(format!("{measure}"), "test_ns took 1ns");

        let measure = Measure {
            name: "test_us",
            start: Instant::now(),
            duration: 1000,
        };
        assert_eq!(format!("{measure}"), "test_us took 1us");

        let measure = Measure {
            name: "test_ms",
            start: Instant::now(),
            duration: 1000 * 1000,
        };
        assert_eq!(format!("{measure}"), "test_ms took 1ms");

        let measure = Measure {
            name: "test_s",
            start: Instant::now(),
            duration: 1000 * 1000 * 1000,
        };
        assert_eq!(format!("{measure}"), "test_s took 1.0s");

        let measure = Measure::start("test_not_stopped");
        assert_eq!(format!("{measure}"), "test_not_stopped running");
    }
}