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
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146

//! Diagnostic types and functions for Zebra:
//! - code performance
//! - task handling
//! - errors and panics

pub mod task;

// Tracing the execution time of functions.
//
// TODO:
// - move this to a `timing` submodule
// - also trace polling time for futures, using a `Future` wrapper

use std::time::{Duration, Instant};

use crate::fmt::duration_short;

/// The default minimum info-level message time.
///
/// This is high enough to ignore most slow code.
pub const DEFAULT_MIN_INFO_TIME: Duration = Duration::from_secs(5 * 60);

/// The default minimum warning message time.
///
/// This is a little lower than the block verify timeout.
pub const DEFAULT_MIN_WARN_TIME: Duration = Duration::from_secs(9 * 60);

/// A guard that logs code execution time when dropped.
#[derive(Debug)]
pub struct CodeTimer {
    /// The time that the code started executing.
    start: Instant,

    /// The minimum duration for info-level messages.
    min_info_time: Duration,

    /// The minimum duration for warning messages.
    min_warn_time: Duration,

    /// `true` if this timer has finished.
    has_finished: bool,
}

impl CodeTimer {
    /// Start timing the execution of a function, method, or other code region.
    ///
    /// Returns a guard that finishes timing the code when dropped,
    /// or when [`CodeTimer::finish()`] is called.
    #[track_caller]
    pub fn start() -> Self {
        let start = Instant::now();
        trace!(
            target: "run time",
            ?start,
            "started code timer",
        );

        Self {
            start,
            min_info_time: DEFAULT_MIN_INFO_TIME,
            min_warn_time: DEFAULT_MIN_WARN_TIME,
            has_finished: false,
        }
    }

    /// Finish timing the execution of a function, method, or other code region.
    pub fn finish<S>(
        mut self,
        module_path: &'static str,
        line: u32,
        description: impl Into<Option<S>>,
    ) where
        S: ToString,
    {
        self.finish_inner(Some(module_path), Some(line), description);
    }

    /// Ignore this timer: it will not check the elapsed time or log any warnings.
    pub fn ignore(mut self) {
        self.has_finished = true;
    }

    /// Finish timing the execution of a function, method, or other code region.
    ///
    /// This private method can be called from [`CodeTimer::finish()`] or `drop()`.
    fn finish_inner<S>(
        &mut self,
        module_path: impl Into<Option<&'static str>>,
        line: impl Into<Option<u32>>,
        description: impl Into<Option<S>>,
    ) where
        S: ToString,
    {
        if self.has_finished {
            return;
        }

        self.has_finished = true;

        let execution = self.start.elapsed();
        let time = duration_short(execution);
        let time = time.as_str();

        let module = module_path.into().unwrap_or_default();

        let line = line.into().map(|line| line.to_string()).unwrap_or_default();
        let line = line.as_str();

        let description = description
            .into()
            .map(|desc| desc.to_string())
            .unwrap_or_default();

        if execution >= self.min_warn_time {
            warn!(
                target: "run time",
                %time,
                %module,
                %line,
                "very long {description}",
            );
        } else if execution >= self.min_info_time {
            info!(
                target: "run time",
                %time,
                %module,
                %line,
                "long {description}",
            );
        } else {
            trace!(
                target: "run time",
                %time,
                %module,
                %line,
                "finished {description} code timer",
            );
        }
    }
}

impl Drop for CodeTimer {
    fn drop(&mut self) {
        self.finish_inner(None, None, "(dropped, cancelled, or aborted)")
    }
}