Skip to main content

chie_core/
profiler.rs

1//! Performance profiling utilities for CHIE Protocol.
2//!
3//! This module provides lightweight profiling tools to track operation timings,
4//! identify bottlenecks, and generate performance reports.
5//!
6//! # Examples
7//!
8//! ```
9//! use chie_core::profiler::{Profiler, ProfileScope};
10//! use std::time::Duration;
11//!
12//! let mut profiler = Profiler::new();
13//!
14//! // Profile a code section
15//! {
16//!     let _scope = profiler.scope("chunk_encryption");
17//!     // ... encryption work ...
18//!     std::thread::sleep(Duration::from_millis(10));
19//! }
20//!
21//! // Get statistics
22//! let report = profiler.generate_report();
23//! println!("{}", report);
24//! ```
25
26use rand::RngExt as _;
27use std::collections::HashMap;
28use std::time::{Duration, Instant};
29
30/// Maximum number of histogram buckets for percentile tracking.
31const MAX_HISTOGRAM_SAMPLES: usize = 10_000;
32
33/// Latency histogram for accurate percentile calculations.
34#[derive(Debug, Clone)]
35struct LatencyHistogram {
36    /// Sorted samples (maintained up to MAX_HISTOGRAM_SAMPLES).
37    samples: Vec<Duration>,
38    /// Total number of samples recorded (including those not stored).
39    total_count: u64,
40}
41
42impl LatencyHistogram {
43    /// Create a new histogram.
44    fn new() -> Self {
45        Self {
46            samples: Vec::with_capacity(1000),
47            total_count: 0,
48        }
49    }
50
51    /// Record a latency sample.
52    fn record(&mut self, duration: Duration) {
53        self.total_count += 1;
54
55        // Use reservoir sampling to maintain a representative sample
56        if self.samples.len() < MAX_HISTOGRAM_SAMPLES {
57            self.samples.push(duration);
58        } else if self.total_count > 0 {
59            // Reservoir sampling: replace random element with probability
60            let idx = (rand::rng().random::<u64>() as usize % (self.total_count as usize))
61                .min(MAX_HISTOGRAM_SAMPLES - 1);
62            if idx < MAX_HISTOGRAM_SAMPLES {
63                self.samples[idx] = duration;
64            }
65        }
66    }
67
68    /// Calculate percentile (p should be between 0.0 and 1.0).
69    fn percentile(&self, p: f64) -> Duration {
70        if self.samples.is_empty() {
71            return Duration::ZERO;
72        }
73
74        // Sort samples for percentile calculation
75        let mut sorted = self.samples.clone();
76        sorted.sort();
77
78        let index = ((sorted.len() as f64) * p).floor() as usize;
79        let index = index.min(sorted.len() - 1);
80        sorted[index]
81    }
82
83    /// Get p50 (median).
84    #[inline]
85    fn p50(&self) -> Duration {
86        self.percentile(0.50)
87    }
88
89    /// Get p95.
90    #[inline]
91    fn p95(&self) -> Duration {
92        self.percentile(0.95)
93    }
94
95    /// Get p99.
96    #[inline]
97    fn p99(&self) -> Duration {
98        self.percentile(0.99)
99    }
100
101    /// Get p999.
102    #[inline]
103    fn p999(&self) -> Duration {
104        self.percentile(0.999)
105    }
106}
107
108/// Performance statistics for a profiled operation.
109#[derive(Debug, Clone)]
110pub struct OperationStats {
111    /// Number of times the operation was executed.
112    pub count: u64,
113    /// Total time spent in this operation.
114    pub total_duration: Duration,
115    /// Minimum execution time.
116    pub min_duration: Duration,
117    /// Maximum execution time.
118    pub max_duration: Duration,
119    /// Average execution time.
120    pub avg_duration: Duration,
121    /// Latency histogram for percentile tracking.
122    histogram: LatencyHistogram,
123}
124
125impl OperationStats {
126    /// Create new operation statistics.
127    fn new() -> Self {
128        Self {
129            count: 0,
130            total_duration: Duration::ZERO,
131            min_duration: Duration::MAX,
132            max_duration: Duration::ZERO,
133            avg_duration: Duration::ZERO,
134            histogram: LatencyHistogram::new(),
135        }
136    }
137
138    /// Record a new timing sample.
139    fn record(&mut self, duration: Duration) {
140        self.count += 1;
141        self.total_duration += duration;
142        self.min_duration = self.min_duration.min(duration);
143        self.max_duration = self.max_duration.max(duration);
144        self.avg_duration = self.total_duration / self.count as u32;
145        self.histogram.record(duration);
146    }
147
148    /// Get operations per second based on total time.
149    #[must_use]
150    #[inline]
151    pub fn ops_per_second(&self) -> f64 {
152        if self.total_duration.is_zero() {
153            return 0.0;
154        }
155        self.count as f64 / self.total_duration.as_secs_f64()
156    }
157
158    /// Get 50th percentile (median).
159    #[must_use]
160    #[inline]
161    pub fn p50(&self) -> Duration {
162        self.histogram.p50()
163    }
164
165    /// Get 95th percentile.
166    #[must_use]
167    #[inline]
168    pub fn p95(&self) -> Duration {
169        self.histogram.p95()
170    }
171
172    /// Get 99th percentile.
173    #[must_use]
174    #[inline]
175    pub fn p99(&self) -> Duration {
176        self.histogram.p99()
177    }
178
179    /// Get 99.9th percentile.
180    #[must_use]
181    #[inline]
182    pub fn p999(&self) -> Duration {
183        self.histogram.p999()
184    }
185
186    /// Get 99th percentile estimate (deprecated, use p99() instead).
187    #[deprecated(
188        since = "0.1.0",
189        note = "Use p99() for accurate histogram-based percentile"
190    )]
191    #[must_use]
192    #[inline]
193    pub fn p99_estimate(&self) -> Duration {
194        self.p99()
195    }
196}
197
198/// Performance profiler for tracking operation timings.
199pub struct Profiler {
200    /// Operation statistics by name.
201    stats: HashMap<String, OperationStats>,
202    /// Whether profiling is enabled.
203    enabled: bool,
204}
205
206impl Profiler {
207    /// Create a new profiler.
208    #[must_use]
209    #[inline]
210    pub fn new() -> Self {
211        Self {
212            stats: HashMap::new(),
213            enabled: true,
214        }
215    }
216
217    /// Create a profiler with profiling disabled.
218    #[must_use]
219    #[inline]
220    pub fn disabled() -> Self {
221        Self {
222            stats: HashMap::new(),
223            enabled: false,
224        }
225    }
226
227    /// Enable profiling.
228    #[inline]
229    pub fn enable(&mut self) {
230        self.enabled = true;
231    }
232
233    /// Disable profiling.
234    #[inline]
235    pub fn disable(&mut self) {
236        self.enabled = false;
237    }
238
239    /// Check if profiling is enabled.
240    #[must_use]
241    #[inline]
242    pub fn is_enabled(&self) -> bool {
243        self.enabled
244    }
245
246    /// Create a profile scope for an operation.
247    #[must_use]
248    #[inline]
249    pub fn scope(&mut self, name: &str) -> ProfileScope<'_> {
250        ProfileScope::new(self, name.to_string())
251    }
252
253    /// Record a timing manually.
254    #[inline]
255    pub fn record(&mut self, name: &str, duration: Duration) {
256        if !self.enabled {
257            return;
258        }
259
260        let stats = self
261            .stats
262            .entry(name.to_string())
263            .or_insert_with(OperationStats::new);
264        stats.record(duration);
265    }
266
267    /// Get statistics for an operation.
268    #[must_use]
269    #[inline]
270    pub fn get_stats(&self, name: &str) -> Option<&OperationStats> {
271        self.stats.get(name)
272    }
273
274    /// Get all operation names.
275    #[must_use]
276    #[inline]
277    pub fn operation_names(&self) -> Vec<&str> {
278        self.stats.keys().map(|s| s.as_str()).collect()
279    }
280
281    /// Clear all statistics.
282    #[inline]
283    pub fn clear(&mut self) {
284        self.stats.clear();
285    }
286
287    /// Get total number of profiled operations.
288    #[must_use]
289    #[inline]
290    pub fn total_operations(&self) -> usize {
291        self.stats.len()
292    }
293
294    /// Get total time spent across all operations.
295    #[must_use]
296    #[inline]
297    pub fn total_time(&self) -> Duration {
298        self.stats.values().map(|s| s.total_duration).sum()
299    }
300
301    /// Generate a performance report.
302    #[must_use]
303    pub fn generate_report(&self) -> String {
304        let mut lines = vec![
305            "Performance Profile Report".to_string(),
306            "=========================".to_string(),
307            String::new(),
308        ];
309
310        if self.stats.is_empty() {
311            lines.push("No profiling data available.".to_string());
312            return lines.join("\n");
313        }
314
315        // Sort by total duration (highest first)
316        let mut sorted_stats: Vec<_> = self.stats.iter().collect();
317        sorted_stats.sort_by(|a, b| b.1.total_duration.cmp(&a.1.total_duration));
318
319        // Header
320        lines.push(format!(
321            "{:<25} {:>8} {:>10} {:>10} {:>10} {:>10} {:>10} {:>10} {:>10}",
322            "Operation",
323            "Count",
324            "Avg(ms)",
325            "Min(ms)",
326            "p50(ms)",
327            "p95(ms)",
328            "p99(ms)",
329            "p999(ms)",
330            "Max(ms)"
331        ));
332        lines.push("-".repeat(120));
333
334        // Data rows
335        for (name, stats) in sorted_stats {
336            lines.push(format!(
337                "{:<25} {:>8} {:>10.2} {:>10.2} {:>10.2} {:>10.2} {:>10.2} {:>10.2} {:>10.2}",
338                truncate_str(name, 25),
339                stats.count,
340                stats.avg_duration.as_secs_f64() * 1000.0,
341                stats.min_duration.as_secs_f64() * 1000.0,
342                stats.p50().as_secs_f64() * 1000.0,
343                stats.p95().as_secs_f64() * 1000.0,
344                stats.p99().as_secs_f64() * 1000.0,
345                stats.p999().as_secs_f64() * 1000.0,
346                stats.max_duration.as_secs_f64() * 1000.0,
347            ));
348        }
349
350        lines.push(String::new());
351        lines.push(format!("Total operations: {}", self.total_operations()));
352        lines.push(format!(
353            "Total time: {:.2}ms",
354            self.total_time().as_secs_f64() * 1000.0
355        ));
356
357        lines.join("\n")
358    }
359
360    /// Export statistics as JSON (simple format).
361    #[must_use]
362    pub fn export_json(&self) -> String {
363        use serde_json::json;
364
365        let operations: Vec<_> = self
366            .stats
367            .iter()
368            .map(|(name, stats)| {
369                json!({
370                    "name": name,
371                    "count": stats.count,
372                    "total_ms": stats.total_duration.as_secs_f64() * 1000.0,
373                    "avg_ms": stats.avg_duration.as_secs_f64() * 1000.0,
374                    "min_ms": stats.min_duration.as_secs_f64() * 1000.0,
375                    "p50_ms": stats.p50().as_secs_f64() * 1000.0,
376                    "p95_ms": stats.p95().as_secs_f64() * 1000.0,
377                    "p99_ms": stats.p99().as_secs_f64() * 1000.0,
378                    "p999_ms": stats.p999().as_secs_f64() * 1000.0,
379                    "max_ms": stats.max_duration.as_secs_f64() * 1000.0,
380                    "ops_per_sec": stats.ops_per_second(),
381                })
382            })
383            .collect();
384
385        json!({
386            "total_operations": self.total_operations(),
387            "total_time_ms": self.total_time().as_secs_f64() * 1000.0,
388            "operations": operations,
389        })
390        .to_string()
391    }
392}
393
394impl Default for Profiler {
395    #[inline]
396    fn default() -> Self {
397        Self::new()
398    }
399}
400
401/// RAII guard for profiling a scope.
402pub struct ProfileScope<'a> {
403    profiler: &'a mut Profiler,
404    name: String,
405    start: Instant,
406}
407
408impl<'a> ProfileScope<'a> {
409    #[inline]
410    fn new(profiler: &'a mut Profiler, name: String) -> Self {
411        Self {
412            profiler,
413            name,
414            start: Instant::now(),
415        }
416    }
417}
418
419impl Drop for ProfileScope<'_> {
420    fn drop(&mut self) {
421        let duration = self.start.elapsed();
422        self.profiler.record(&self.name, duration);
423    }
424}
425
426/// Truncate a string to a maximum length.
427fn truncate_str(s: &str, max_len: usize) -> String {
428    if s.len() <= max_len {
429        s.to_string()
430    } else {
431        format!("{}...", &s[..max_len.saturating_sub(3)])
432    }
433}
434
435/// Global profiler instance for convenience.
436static GLOBAL_PROFILER: std::sync::Mutex<Option<Profiler>> = std::sync::Mutex::new(None);
437
438/// Initialize the global profiler.
439pub fn init_global_profiler() {
440    let mut guard = GLOBAL_PROFILER.lock().unwrap();
441    *guard = Some(Profiler::new());
442}
443
444/// Get a reference to the global profiler.
445pub fn global_profiler<F, R>(f: F) -> R
446where
447    F: FnOnce(&mut Profiler) -> R,
448{
449    let mut guard = GLOBAL_PROFILER.lock().unwrap();
450    if guard.is_none() {
451        *guard = Some(Profiler::new());
452    }
453    f(guard.as_mut().unwrap())
454}
455
456/// Macro for easy profiling of code blocks.
457#[macro_export]
458macro_rules! profile {
459    ($profiler:expr, $name:expr, $block:block) => {{
460        let _scope = $profiler.scope($name);
461        $block
462    }};
463}
464
465#[cfg(test)]
466mod tests {
467    use super::*;
468    use std::thread;
469
470    #[test]
471    fn test_profiler_basic() {
472        let mut profiler = Profiler::new();
473
474        {
475            let _scope = profiler.scope("test_op");
476            thread::sleep(Duration::from_millis(10));
477        }
478
479        let stats = profiler.get_stats("test_op").unwrap();
480        assert_eq!(stats.count, 1);
481        assert!(stats.total_duration >= Duration::from_millis(10));
482    }
483
484    #[test]
485    fn test_profiler_multiple_operations() {
486        let mut profiler = Profiler::new();
487
488        for _ in 0..5 {
489            let _scope = profiler.scope("op1");
490            thread::sleep(Duration::from_millis(1));
491        }
492
493        for _ in 0..3 {
494            let _scope = profiler.scope("op2");
495            thread::sleep(Duration::from_millis(2));
496        }
497
498        let stats1 = profiler.get_stats("op1").unwrap();
499        assert_eq!(stats1.count, 5);
500
501        let stats2 = profiler.get_stats("op2").unwrap();
502        assert_eq!(stats2.count, 3);
503
504        assert_eq!(profiler.total_operations(), 2);
505    }
506
507    #[test]
508    fn test_profiler_disabled() {
509        let mut profiler = Profiler::disabled();
510
511        {
512            let _scope = profiler.scope("test_op");
513            thread::sleep(Duration::from_millis(10));
514        }
515
516        assert!(profiler.get_stats("test_op").is_none());
517        assert_eq!(profiler.total_operations(), 0);
518    }
519
520    #[test]
521    fn test_profiler_stats() {
522        let mut profiler = Profiler::new();
523
524        profiler.record("test", Duration::from_millis(100));
525        profiler.record("test", Duration::from_millis(200));
526        profiler.record("test", Duration::from_millis(300));
527
528        let stats = profiler.get_stats("test").unwrap();
529        assert_eq!(stats.count, 3);
530        assert_eq!(stats.min_duration, Duration::from_millis(100));
531        assert_eq!(stats.max_duration, Duration::from_millis(300));
532        assert_eq!(stats.avg_duration, Duration::from_millis(200));
533    }
534
535    #[test]
536    fn test_generate_report() {
537        let mut profiler = Profiler::new();
538
539        profiler.record("encryption", Duration::from_millis(100));
540        profiler.record("decryption", Duration::from_millis(50));
541
542        let report = profiler.generate_report();
543        assert!(report.contains("encryption"));
544        assert!(report.contains("decryption"));
545        assert!(report.contains("Performance Profile Report"));
546    }
547
548    #[test]
549    fn test_export_json() {
550        let mut profiler = Profiler::new();
551        profiler.record("test_op", Duration::from_millis(100));
552
553        let json = profiler.export_json();
554        assert!(json.contains("test_op"));
555        assert!(json.contains("total_operations"));
556    }
557
558    #[test]
559    fn test_profiler_clear() {
560        let mut profiler = Profiler::new();
561        profiler.record("test", Duration::from_millis(100));
562
563        assert_eq!(profiler.total_operations(), 1);
564
565        profiler.clear();
566        assert_eq!(profiler.total_operations(), 0);
567    }
568
569    #[test]
570    fn test_operation_stats_ops_per_second() {
571        let mut stats = OperationStats::new();
572        stats.record(Duration::from_millis(100));
573        stats.record(Duration::from_millis(100));
574        stats.record(Duration::from_millis(100));
575
576        // 3 operations in 300ms = 10 ops/sec
577        let ops_per_sec = stats.ops_per_second();
578        assert!((ops_per_sec - 10.0).abs() < 0.1);
579    }
580
581    #[test]
582    fn test_percentiles() {
583        let mut stats = OperationStats::new();
584
585        // Record samples with known distribution
586        for i in 1..=100 {
587            stats.record(Duration::from_millis(i));
588        }
589
590        // Test percentiles are in expected ranges
591        assert_eq!(stats.count, 100);
592
593        let p50 = stats.p50();
594        assert!(p50 >= Duration::from_millis(45) && p50 <= Duration::from_millis(55));
595
596        let p95 = stats.p95();
597        assert!(p95 >= Duration::from_millis(90) && p95 <= Duration::from_millis(100));
598
599        let p99 = stats.p99();
600        assert!(p99 >= Duration::from_millis(95) && p99 <= Duration::from_millis(100));
601    }
602
603    #[test]
604    fn test_histogram_with_few_samples() {
605        let mut stats = OperationStats::new();
606
607        stats.record(Duration::from_millis(10));
608        stats.record(Duration::from_millis(20));
609        stats.record(Duration::from_millis(30));
610
611        // With only 3 samples, percentiles should still work
612        assert!(stats.p50() > Duration::ZERO);
613        assert!(stats.p95() > Duration::ZERO);
614        assert!(stats.p99() > Duration::ZERO);
615    }
616
617    #[test]
618    fn test_percentiles_empty() {
619        let stats = OperationStats::new();
620
621        // Empty stats should return zero for percentiles
622        assert_eq!(stats.p50(), Duration::ZERO);
623        assert_eq!(stats.p95(), Duration::ZERO);
624        assert_eq!(stats.p99(), Duration::ZERO);
625        assert_eq!(stats.p999(), Duration::ZERO);
626    }
627
628    #[test]
629    fn test_export_json_with_percentiles() {
630        let mut profiler = Profiler::new();
631
632        for i in 1..=50 {
633            profiler.record("test_op", Duration::from_millis(i));
634        }
635
636        let json = profiler.export_json();
637
638        // Verify JSON contains percentile fields
639        assert!(json.contains("p50_ms"));
640        assert!(json.contains("p95_ms"));
641        assert!(json.contains("p99_ms"));
642        assert!(json.contains("p999_ms"));
643        assert!(json.contains("ops_per_sec"));
644    }
645
646    #[test]
647    fn test_generate_report_with_percentiles() {
648        let mut profiler = Profiler::new();
649
650        for i in 1..=100 {
651            profiler.record("encryption", Duration::from_millis(i));
652        }
653
654        let report = profiler.generate_report();
655
656        // Verify report contains percentile columns
657        assert!(report.contains("p50(ms)"));
658        assert!(report.contains("p95(ms)"));
659        assert!(report.contains("p99(ms)"));
660        assert!(report.contains("p999(ms)"));
661        assert!(report.contains("encryption"));
662    }
663}