rumdl_lib/
profiling.rs

1//!
2//! This module provides profiling utilities for measuring and reporting execution times in rumdl.
3
4use std::collections::HashMap;
5use std::sync::LazyLock;
6use std::sync::Mutex;
7use std::time::{Duration, Instant};
8
9// Global profiler state
10static PROFILER: LazyLock<Mutex<Profiler>> = LazyLock::new(|| Mutex::new(Profiler::new()));
11
12// Enable/disable profiling with a feature flag
13#[cfg(feature = "profiling")]
14pub(crate) const PROFILING_ENABLED: bool = true;
15
16#[cfg(not(feature = "profiling"))]
17pub(crate) const PROFILING_ENABLED: bool = false;
18
19/// A simple profiling utility to measure and report execution times
20pub struct Profiler {
21    measurements: HashMap<String, (Duration, usize)>,
22    active_timers: HashMap<String, Instant>,
23}
24
25impl Default for Profiler {
26    fn default() -> Self {
27        Self::new()
28    }
29}
30
31impl Profiler {
32    /// Create a new profiler instance
33    pub fn new() -> Self {
34        Profiler {
35            measurements: HashMap::new(),
36            active_timers: HashMap::new(),
37        }
38    }
39
40    /// Start a timer for a specific section of code
41    pub fn start_timer(&mut self, section: &str) {
42        if PROFILING_ENABLED {
43            let section_name = section.to_string();
44            self.active_timers.insert(section_name, Instant::now());
45        }
46    }
47
48    /// Stop the timer for a section and record the elapsed time
49    pub fn stop_timer(&mut self, section: &str) {
50        if PROFILING_ENABLED {
51            let section_name = section.to_string();
52            if let Some(start_time) = self.active_timers.remove(&section_name) {
53                let elapsed = start_time.elapsed();
54
55                // Update or insert the measurement
56                let entry = self
57                    .measurements
58                    .entry(section_name)
59                    .or_insert((Duration::new(0, 0), 0));
60                entry.0 += elapsed;
61                entry.1 += 1;
62            }
63        }
64    }
65
66    /// Get a report of all measurements
67    pub fn get_report(&self) -> String {
68        if !PROFILING_ENABLED || self.measurements.is_empty() {
69            return "Profiling disabled or no measurements recorded.".to_string();
70        }
71
72        // Sort measurements by total time (descending)
73        let mut sorted_measurements: Vec<_> = self.measurements.iter().collect();
74        sorted_measurements.sort_by(|a, b| b.1.0.cmp(&a.1.0));
75
76        // Calculate total time across all sections
77        let total_time: Duration = sorted_measurements.iter().map(|(_, (duration, _))| duration).sum();
78
79        // Generate the report
80        let mut report = String::new();
81        report.push_str("=== Profiling Report ===\n");
82        report.push_str(&format!(
83            "Total execution time: {:.6} seconds\n\n",
84            total_time.as_secs_f64()
85        ));
86        report.push_str(
87            "Section                                  | Total Time (s) | Calls | Avg Time (ms) | % of Total\n",
88        );
89        report.push_str(
90            "------------------------------------------|----------------|-------|---------------|----------\n",
91        );
92
93        for (section, (duration, calls)) in sorted_measurements {
94            let total_seconds = duration.as_secs_f64();
95            let avg_ms = (duration.as_nanos() as f64) / (calls * 1_000_000) as f64;
96            let percentage = (total_seconds / total_time.as_secs_f64()) * 100.0;
97
98            report.push_str(&format!(
99                "{section:<42} | {total_seconds:<14.6} | {calls:<5} | {avg_ms:<13.3} | {percentage:<8.2}%\n"
100            ));
101        }
102
103        report
104    }
105
106    /// Reset all measurements
107    pub fn reset(&mut self) {
108        self.measurements.clear();
109        self.active_timers.clear();
110    }
111}
112
113/// Start a timer for a section
114pub fn start_timer(section: &str) {
115    if PROFILING_ENABLED {
116        let mut profiler = PROFILER.lock().expect("Profiler mutex poisoned");
117        profiler.start_timer(section);
118    }
119}
120
121/// Stop a timer for a section
122pub fn stop_timer(section: &str) {
123    if PROFILING_ENABLED {
124        let mut profiler = PROFILER.lock().expect("Profiler mutex poisoned");
125        profiler.stop_timer(section);
126    }
127}
128
129/// Get a report of all measurements
130pub fn get_report() -> String {
131    if PROFILING_ENABLED {
132        let profiler = PROFILER.lock().expect("Profiler mutex poisoned");
133        profiler.get_report()
134    } else {
135        "Profiling is disabled.".to_string()
136    }
137}
138
139/// Reset all measurements
140pub fn reset() {
141    if PROFILING_ENABLED {
142        let mut profiler = PROFILER.lock().expect("Profiler mutex poisoned");
143        profiler.reset();
144    }
145}
146
147/// A utility struct to time a section of code using RAII
148pub struct ScopedTimer {
149    section: String,
150    enabled: bool,
151}
152
153impl ScopedTimer {
154    /// Create a new scoped timer
155    pub fn new(section: &str) -> Self {
156        let enabled = PROFILING_ENABLED;
157        if enabled {
158            start_timer(section);
159        }
160        ScopedTimer {
161            section: section.to_string(),
162            enabled,
163        }
164    }
165}
166
167impl Drop for ScopedTimer {
168    fn drop(&mut self) {
169        if self.enabled {
170            stop_timer(&self.section);
171        }
172    }
173}
174
175/// Convenience macro to time a block of code
176#[macro_export]
177macro_rules! time_section {
178    ($section:expr, $block:block) => {{
179        let _timer = $crate::profiling::ScopedTimer::new($section);
180        $block
181    }};
182}
183
184/// Convenience macro to time a function call
185#[macro_export]
186macro_rules! time_function {
187    ($section:expr, $func:expr) => {{
188        let _timer = $crate::profiling::ScopedTimer::new($section);
189        $func
190    }};
191}
192
193#[cfg(test)]
194mod tests {
195    use super::*;
196    use std::thread;
197    use std::time::Duration;
198
199    #[test]
200    fn test_profiler_new() {
201        let profiler = Profiler::new();
202        assert!(profiler.measurements.is_empty());
203        assert!(profiler.active_timers.is_empty());
204    }
205
206    #[test]
207    fn test_profiler_default() {
208        let profiler = Profiler::default();
209        assert!(profiler.measurements.is_empty());
210        assert!(profiler.active_timers.is_empty());
211    }
212
213    #[test]
214    fn test_profiler_start_stop_timer() {
215        let mut profiler = Profiler::new();
216
217        // Force profiling to be enabled for this test
218        if PROFILING_ENABLED {
219            profiler.start_timer("test_section");
220            thread::sleep(Duration::from_millis(10));
221            profiler.stop_timer("test_section");
222
223            assert!(profiler.measurements.contains_key("test_section"));
224            let (duration, count) = profiler.measurements.get("test_section").unwrap();
225            assert!(*count == 1);
226            assert!(duration.as_millis() >= 10);
227        }
228    }
229
230    #[test]
231    fn test_profiler_multiple_measurements() {
232        let mut profiler = Profiler::new();
233
234        if PROFILING_ENABLED {
235            // Multiple measurements of same section
236            for _ in 0..3 {
237                profiler.start_timer("test_section");
238                thread::sleep(Duration::from_millis(5));
239                profiler.stop_timer("test_section");
240            }
241
242            assert!(profiler.measurements.contains_key("test_section"));
243            let (duration, count) = profiler.measurements.get("test_section").unwrap();
244            assert_eq!(*count, 3);
245            assert!(duration.as_millis() >= 15);
246        }
247    }
248
249    #[test]
250    fn test_profiler_get_report() {
251        let mut profiler = Profiler::new();
252
253        if PROFILING_ENABLED {
254            profiler.start_timer("section1");
255            thread::sleep(Duration::from_millis(20));
256            profiler.stop_timer("section1");
257
258            profiler.start_timer("section2");
259            thread::sleep(Duration::from_millis(10));
260            profiler.stop_timer("section2");
261
262            let report = profiler.get_report();
263            assert!(report.contains("Profiling Report"));
264            assert!(report.contains("section1"));
265            assert!(report.contains("section2"));
266            assert!(report.contains("Total execution time"));
267        } else {
268            let report = profiler.get_report();
269            assert_eq!(report, "Profiling disabled or no measurements recorded.");
270        }
271    }
272
273    #[test]
274    fn test_profiler_reset() {
275        let mut profiler = Profiler::new();
276
277        if PROFILING_ENABLED {
278            profiler.start_timer("test_section");
279            profiler.stop_timer("test_section");
280
281            assert!(!profiler.measurements.is_empty());
282
283            profiler.reset();
284            assert!(profiler.measurements.is_empty());
285            assert!(profiler.active_timers.is_empty());
286        }
287    }
288
289    #[test]
290    fn test_profiler_stop_without_start() {
291        let mut profiler = Profiler::new();
292
293        // Should not panic
294        profiler.stop_timer("nonexistent_section");
295        assert!(profiler.measurements.is_empty());
296    }
297
298    #[test]
299    #[serial_test::serial]
300    fn test_global_start_stop_timer() {
301        if PROFILING_ENABLED {
302            reset(); // Clear any previous measurements
303
304            start_timer("global_test");
305            thread::sleep(Duration::from_millis(10));
306            stop_timer("global_test");
307
308            let report = get_report();
309            assert!(report.contains("global_test"));
310        }
311    }
312
313    #[test]
314    fn test_global_get_report() {
315        let report = get_report();
316        if PROFILING_ENABLED {
317            assert!(report.contains("Profiling Report") || report.contains("no measurements"));
318        } else {
319            assert_eq!(report, "Profiling is disabled.");
320        }
321    }
322
323    #[test]
324    #[serial_test::serial]
325    fn test_global_reset() {
326        if PROFILING_ENABLED {
327            start_timer("test_reset");
328            stop_timer("test_reset");
329
330            reset();
331            let report = get_report();
332            assert!(!report.contains("test_reset"));
333        }
334    }
335
336    #[test]
337    #[serial_test::serial]
338    fn test_scoped_timer() {
339        if PROFILING_ENABLED {
340            reset();
341
342            {
343                let _timer = ScopedTimer::new("scoped_test");
344                thread::sleep(Duration::from_millis(10));
345            } // Timer should stop here
346
347            let report = get_report();
348            assert!(report.contains("scoped_test"));
349        }
350    }
351
352    #[test]
353    fn test_scoped_timer_drop() {
354        let timer = ScopedTimer::new("drop_test");
355        assert_eq!(timer.section, "drop_test");
356        assert_eq!(timer.enabled, PROFILING_ENABLED);
357        // Timer will be dropped and stop_timer called
358    }
359
360    #[test]
361    fn test_empty_report() {
362        let profiler = Profiler::new();
363        let report = profiler.get_report();
364
365        if PROFILING_ENABLED {
366            assert_eq!(report, "Profiling disabled or no measurements recorded.");
367        }
368    }
369
370    #[test]
371    fn test_report_formatting() {
372        let mut profiler = Profiler::new();
373
374        if PROFILING_ENABLED {
375            // Create predictable measurements
376            profiler
377                .measurements
378                .insert("test1".to_string(), (Duration::from_secs(1), 10));
379            profiler
380                .measurements
381                .insert("test2".to_string(), (Duration::from_millis(500), 5));
382
383            let report = profiler.get_report();
384
385            // Check report structure
386            assert!(report.contains("Section"));
387            assert!(report.contains("Total Time (s)"));
388            assert!(report.contains("Calls"));
389            assert!(report.contains("Avg Time (ms)"));
390            assert!(report.contains("% of Total"));
391
392            // Check that test1 appears before test2 (sorted by duration)
393            let test1_pos = report.find("test1").unwrap();
394            let test2_pos = report.find("test2").unwrap();
395            assert!(test1_pos < test2_pos);
396        }
397    }
398
399    #[test]
400    #[serial_test::serial]
401    fn test_concurrent_access() {
402        use std::sync::Arc;
403        use std::sync::Barrier;
404
405        if PROFILING_ENABLED {
406            reset();
407
408            let barrier = Arc::new(Barrier::new(3));
409            let mut handles = vec![];
410
411            for i in 0..3 {
412                let b = barrier.clone();
413                let handle = thread::spawn(move || {
414                    b.wait();
415                    start_timer(&format!("thread_{i}"));
416                    thread::sleep(Duration::from_millis(10));
417                    stop_timer(&format!("thread_{i}"));
418                });
419                handles.push(handle);
420            }
421
422            for handle in handles {
423                handle.join().unwrap();
424            }
425
426            let report = get_report();
427            assert!(report.contains("thread_0"));
428            assert!(report.contains("thread_1"));
429            assert!(report.contains("thread_2"));
430        }
431    }
432}
rumdl_lib/profiling.rs

rumdl_lib/
profiling.rs
