near_delay_detector/
lib.rs

1use cpu_time::ProcessTime;
2use log::{info, warn};
3use std::borrow::Cow;
4use std::time::{Duration, Instant};
5
6struct Snapshot {
7    real_time: Duration,
8    cpu_time: Duration,
9}
10
11struct SnapshotInstant {
12    real_time: Instant,
13    cpu_time: ProcessTime,
14}
15
16pub struct DelayDetector<'a> {
17    min_delay: Duration,
18    msg: Cow<'a, str>,
19    started: Instant,
20    started_cpu_time: ProcessTime,
21    snapshots: Vec<((String, String), Snapshot)>,
22    last_snapshot: Option<(String, SnapshotInstant)>,
23}
24
25impl<'a> DelayDetector<'a> {
26    pub fn new(msg: Cow<'a, str>) -> Self {
27        Self {
28            msg,
29            started: Instant::now(),
30            started_cpu_time: ProcessTime::now(),
31            snapshots: vec![],
32            last_snapshot: None,
33            min_delay: Duration::from_millis(50),
34        }
35    }
36
37    pub fn min_delay(mut self, min_delay: Duration) -> Self {
38        self.min_delay = min_delay;
39        self
40    }
41
42    pub fn snapshot(&mut self, msg: &str) {
43        let now = Instant::now();
44        let cpu_time = ProcessTime::now();
45        if let Some((s, started)) = self.last_snapshot.take() {
46            self.snapshots.push((
47                (s, msg.to_string()),
48                Snapshot {
49                    real_time: now - started.real_time,
50                    cpu_time: started.cpu_time.elapsed(),
51                },
52            ));
53        }
54        self.last_snapshot = Some((msg.to_string(), SnapshotInstant { real_time: now, cpu_time }));
55    }
56}
57
58impl<'a> Drop for DelayDetector<'a> {
59    fn drop(&mut self) {
60        let elapsed = self.started_cpu_time.elapsed();
61        let elapsed_real = self.started.elapsed();
62        let long_delay = self.min_delay * 10;
63        if self.min_delay < elapsed && elapsed <= long_delay {
64            info!(target: "delay_detector", "Took {:?} cpu_time, {:?} real_time processing {}", elapsed, elapsed_real, self.msg);
65        }
66        if elapsed > long_delay {
67            warn!(target: "delay_detector", "LONG DELAY! Took {:?} cpu_time, {:?} real_time processing {}", elapsed, elapsed_real, self.msg);
68            if self.last_snapshot.is_some() {
69                self.snapshot("end");
70            }
71            self.snapshots.sort_by(|a, b| b.1.cpu_time.cmp(&a.1.cpu_time));
72            for ((s1, s2), Snapshot { cpu_time, real_time }) in self.snapshots.drain(..) {
73                info!(target: "delay_detector", "Took {:?} cpu_time, {:?} real_time between {} and {}", cpu_time, real_time, s1, s2);
74            }
75        }
76    }
77}
near_delay_detector/lib.rs

near_delay_detector/
lib.rs
