nextest_runner/time/
stopwatch.rs

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
// Copyright (c) The nextest Contributors
// SPDX-License-Identifier: MIT OR Apache-2.0

//! Stopwatch for tracking how long it takes to run tests.
//!
//! Tests need to track a start time and a duration. For that we use a combination of a `SystemTime`
//! (realtime clock) and an `Instant` (monotonic clock). Once the stopwatch transitions to the "end"
//! state, we can report the elapsed time using the monotonic clock.

use chrono::{DateTime, Local};
use std::time::{Duration, Instant};

pub(crate) fn stopwatch() -> StopwatchStart {
    StopwatchStart::new()
}

/// The start state of a stopwatch.
#[derive(Clone, Debug)]
pub(crate) struct StopwatchStart {
    start_time: DateTime<Local>,
    instant: Instant,
    paused_time: Duration,
    pause_state: StopwatchPauseState,
}

impl StopwatchStart {
    fn new() -> Self {
        Self {
            // These two syscalls will happen imperceptibly close to each other, which is good
            // enough for our purposes.
            start_time: Local::now(),
            instant: Instant::now(),
            paused_time: Duration::ZERO,
            pause_state: StopwatchPauseState::Running,
        }
    }

    pub(crate) fn is_paused(&self) -> bool {
        matches!(self.pause_state, StopwatchPauseState::Paused { .. })
    }

    pub(crate) fn pause(&mut self) {
        match &self.pause_state {
            StopwatchPauseState::Running => {
                self.pause_state = StopwatchPauseState::Paused {
                    paused_at: Instant::now(),
                };
            }
            StopwatchPauseState::Paused { .. } => {
                panic!("illegal state transition: pause() called while stopwatch was paused")
            }
        }
    }

    pub(crate) fn resume(&mut self) {
        match &self.pause_state {
            StopwatchPauseState::Paused { paused_at } => {
                self.paused_time += paused_at.elapsed();
                self.pause_state = StopwatchPauseState::Running;
            }
            StopwatchPauseState::Running => {
                panic!("illegal state transition: resume() called while stopwatch was running")
            }
        }
    }

    pub(crate) fn snapshot(&self) -> StopwatchSnapshot {
        StopwatchSnapshot {
            start_time: self.start_time,
            // self.instant is supposed to be monotonic but might not be so on
            // some weird systems. If the duration underflows, just return 0.
            active: self.instant.elapsed().saturating_sub(self.paused_time),
            paused: self.paused_time,
        }
    }
}

/// A snapshot of the state of the stopwatch.
#[derive(Clone, Copy, Debug)]
pub(crate) struct StopwatchSnapshot {
    /// The time at which the stopwatch was started.
    pub(crate) start_time: DateTime<Local>,

    /// The amount of time spent while the stopwatch was active.
    pub(crate) active: Duration,

    /// The amount of time spent while the stopwatch was paused.
    #[expect(dead_code)]
    pub(crate) paused: Duration,
}

#[derive(Clone, Debug)]
enum StopwatchPauseState {
    Running,
    Paused { paused_at: Instant },
}

#[cfg(test)]
mod tests {
    use super::*;

    #[test]
    fn stopwatch_pause() {
        let mut start = stopwatch();
        let unpaused_start = start.clone();

        start.pause();
        std::thread::sleep(Duration::from_millis(250));
        start.resume();

        start.pause();
        std::thread::sleep(Duration::from_millis(300));
        start.resume();

        let end = start.snapshot();
        let unpaused_end = unpaused_start.snapshot();

        // The total time we've paused is 550ms. We can assume that unpaused_end is at least 550ms
        // greater than end. Add a a fudge factor of 100ms.
        //
        // (Previously, this used to cap the difference at 650ms, but empirically, the test would
        // sometimes fail on GitHub CI. Just setting a minimum bound is enough.)
        let difference = unpaused_end.active - end.active;
        assert!(
            difference > Duration::from_millis(450),
            "difference between unpaused_end and end ({difference:?}) is at least 450ms"
        );
    }
}