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