xlog_runtime/
profiler.rs

1//! Performance profiler for execution statistics
2//!
3//! This module provides [`Profiler`] for tracking per-operation and per-stratum
4//! statistics during query execution. It can be used to identify performance
5//! bottlenecks and understand resource usage patterns.
6//!
7//! # Example
8//!
9//! ```
10//! use xlog_runtime::profiler::{Profiler, OpStats};
11//!
12//! let mut profiler = Profiler::new(true);
13//!
14//! // Record operation statistics
15//! profiler.record(OpStats {
16//!     op_name: "hash_join".to_string(),
17//!     input_rows: 1000,
18//!     output_rows: 500,
19//!     duration_us: 1500,
20//!     memory_bytes: 4096,
21//! });
22//!
23//! // Get summary
24//! println!("{}", profiler.summary());
25//! ```
26
27use std::collections::HashMap;
28use std::time::Instant;
29
30/// Statistics for a single operation
31///
32/// Tracks the name, row counts, duration, and memory usage for an operation.
33#[derive(Debug, Clone, Default, PartialEq, Eq)]
34pub struct OpStats {
35    /// Name of the operation (e.g., "hash_join", "filter", "scan")
36    pub op_name: String,
37    /// Number of input rows processed
38    pub input_rows: u64,
39    /// Number of output rows produced
40    pub output_rows: u64,
41    /// Duration in microseconds
42    pub duration_us: u64,
43    /// Memory used in bytes
44    pub memory_bytes: u64,
45}
46
47impl OpStats {
48    /// Create a new OpStats with all fields
49    pub fn new(
50        op_name: impl Into<String>,
51        input_rows: u64,
52        output_rows: u64,
53        duration_us: u64,
54        memory_bytes: u64,
55    ) -> Self {
56        Self {
57            op_name: op_name.into(),
58            input_rows,
59            output_rows,
60            duration_us,
61            memory_bytes,
62        }
63    }
64
65    /// Create OpStats for an operation with no memory tracking
66    pub fn timed(
67        op_name: impl Into<String>,
68        input_rows: u64,
69        output_rows: u64,
70        duration_us: u64,
71    ) -> Self {
72        Self {
73            op_name: op_name.into(),
74            input_rows,
75            output_rows,
76            duration_us,
77            memory_bytes: 0,
78        }
79    }
80}
81
82/// Statistics for a single stratum
83#[derive(Debug, Clone, Default)]
84pub struct StratumStats {
85    /// Stratum index (0-based)
86    pub stratum_id: usize,
87    /// Number of rules in this stratum
88    pub num_rules: usize,
89    /// Whether this stratum contains recursive rules
90    pub is_recursive: bool,
91    /// Number of iterations (1 for non-recursive, N for fixpoint)
92    pub iterations: usize,
93    /// Total duration in microseconds
94    pub duration_us: u64,
95    /// Operations within this stratum
96    pub ops: Vec<OpStats>,
97}
98
99impl StratumStats {
100    /// Create a new StratumStats
101    pub fn new(stratum_id: usize, num_rules: usize, is_recursive: bool) -> Self {
102        Self {
103            stratum_id,
104            num_rules,
105            is_recursive,
106            iterations: if is_recursive { 0 } else { 1 },
107            duration_us: 0,
108            ops: Vec::new(),
109        }
110    }
111
112    /// Get aggregated operation counts by operation name
113    pub fn op_summary(&self) -> HashMap<String, (usize, u64)> {
114        let mut summary: HashMap<String, (usize, u64)> = HashMap::new();
115        for op in &self.ops {
116            let entry = summary.entry(op.op_name.clone()).or_insert((0, 0));
117            entry.0 += 1;
118            entry.1 += op.duration_us;
119        }
120        summary
121    }
122}
123
124/// Final execution statistics returned to CLI
125#[derive(Debug, Clone, Default)]
126pub struct ExecutionStats {
127    /// Total execution duration in microseconds
128    pub total_duration_us: u64,
129    /// Per-stratum statistics
130    pub strata: Vec<StratumStats>,
131    /// Peak memory usage in bytes
132    pub peak_memory_bytes: u64,
133    /// Memory budget in bytes
134    pub memory_budget_bytes: u64,
135    /// Total output rows across all queries
136    pub total_output_rows: u64,
137}
138
139impl ExecutionStats {
140    /// Format stats as human-readable string
141    pub fn format_human(&self) -> String {
142        let total_secs = self.total_duration_us as f64 / 1_000_000.0;
143        let mut output = String::new();
144
145        output.push_str(&format!("Execution completed in {:.2}s\n\n", total_secs));
146
147        for stratum in &self.strata {
148            let stratum_secs = stratum.duration_us as f64 / 1_000_000.0;
149            let recursive_info = if stratum.is_recursive {
150                format!(", recursive, {} iterations", stratum.iterations)
151            } else {
152                String::new()
153            };
154
155            output.push_str(&format!(
156                "Stratum {}: {:.2}s ({} rules{})\n",
157                stratum.stratum_id, stratum_secs, stratum.num_rules, recursive_info
158            ));
159
160            // Aggregate operations by name
161            let op_summary = stratum.op_summary();
162            let mut ops: Vec<_> = op_summary.into_iter().collect();
163            ops.sort_by_key(|op| std::cmp::Reverse(op.1 .1)); // Sort by duration descending
164
165            for (op_name, (count, duration_us)) in ops {
166                let op_secs = duration_us as f64 / 1_000_000.0;
167                output.push_str(&format!(
168                    "  - {}: {:.2}s ({} calls)\n",
169                    op_name, op_secs, count
170                ));
171            }
172        }
173
174        let peak_mb = self.peak_memory_bytes as f64 / (1024.0 * 1024.0);
175        let budget_mb = self.memory_budget_bytes as f64 / (1024.0 * 1024.0);
176        output.push_str(&format!(
177            "\nMemory: {:.0} MB peak / {:.0} MB budget\n",
178            peak_mb, budget_mb
179        ));
180        output.push_str(&format!(
181            "Output: {} rows\n",
182            format_rows(self.total_output_rows)
183        ));
184
185        output
186    }
187
188    /// Format stats as JSON string
189    pub fn format_json(&self) -> String {
190        let total_ms = self.total_duration_us / 1000;
191        let strata_json: Vec<String> = self.strata.iter().map(|s| {
192            let ops_json: Vec<String> = s.op_summary().iter().map(|(name, (count, duration))| {
193                format!(
194                    r#"{{"op":"{}","calls":{},"duration_ms":{}}}"#,
195                    name, count, duration / 1000
196                )
197            }).collect();
198            format!(
199                r#"{{"stratum":{},"rules":{},"recursive":{},"iterations":{},"duration_ms":{},"ops":[{}]}}"#,
200                s.stratum_id, s.num_rules, s.is_recursive, s.iterations, s.duration_us / 1000,
201                ops_json.join(",")
202            )
203        }).collect();
204
205        format!(
206            r#"{{"total_ms":{},"strata":[{}],"peak_memory_mb":{},"budget_memory_mb":{},"output_rows":{}}}"#,
207            total_ms,
208            strata_json.join(","),
209            self.peak_memory_bytes / (1024 * 1024),
210            self.memory_budget_bytes / (1024 * 1024),
211            self.total_output_rows
212        )
213    }
214}
215
216/// Format row count with commas for readability
217fn format_rows(rows: u64) -> String {
218    let s = rows.to_string();
219    let mut result = String::new();
220    for (i, c) in s.chars().rev().enumerate() {
221        if i > 0 && i % 3 == 0 {
222            result.insert(0, ',');
223        }
224        result.insert(0, c);
225    }
226    result
227}
228
229/// Execution profiler for tracking operation statistics
230///
231/// The profiler collects statistics for each operation during query execution.
232/// It can be enabled or disabled; when disabled, `record` is a no-op for
233/// minimal overhead.
234///
235/// # Thread Safety
236///
237/// This implementation is NOT thread-safe. It is designed for single-threaded
238/// execution in the MVP.
239///
240/// # Example
241///
242/// ```
243/// use xlog_runtime::profiler::{Profiler, OpStats};
244///
245/// // Create an enabled profiler
246/// let mut profiler = Profiler::new(true);
247///
248/// // Record some stats
249/// profiler.record(OpStats::timed("scan", 0, 1000, 100));
250/// profiler.record(OpStats::timed("filter", 1000, 500, 200));
251///
252/// // Check totals
253/// assert_eq!(profiler.total_duration_us(), 300);
254///
255/// // Get summary
256/// println!("{}", profiler.summary());
257/// ```
258pub struct Profiler {
259    /// Whether profiling is enabled
260    enabled: bool,
261    /// Collected operation statistics (flat list for backward compatibility)
262    stats: Vec<OpStats>,
263    /// Per-stratum statistics
264    strata: Vec<StratumStats>,
265    /// Currently active stratum index
266    current_stratum: Option<usize>,
267    /// Stratum start time
268    stratum_start: Option<Instant>,
269    /// Peak memory observed during execution
270    peak_memory_bytes: u64,
271    /// Memory budget
272    memory_budget_bytes: u64,
273}
274
275impl Profiler {
276    /// Create a new profiler
277    ///
278    /// # Arguments
279    /// * `enabled` - Whether to collect statistics. When disabled, `record` is a no-op.
280    pub fn new(enabled: bool) -> Self {
281        Self {
282            enabled,
283            stats: Vec::new(),
284            strata: Vec::new(),
285            current_stratum: None,
286            stratum_start: None,
287            peak_memory_bytes: 0,
288            memory_budget_bytes: 0,
289        }
290    }
291
292    /// Set memory budget for reporting
293    pub fn set_memory_budget(&mut self, budget_bytes: u64) {
294        self.memory_budget_bytes = budget_bytes;
295    }
296
297    /// Begin timing a stratum
298    ///
299    /// # Arguments
300    /// * `stratum_id` - The stratum index
301    /// * `num_rules` - Number of rules in the stratum
302    /// * `is_recursive` - Whether the stratum is recursive
303    pub fn begin_stratum(&mut self, stratum_id: usize, num_rules: usize, is_recursive: bool) {
304        if !self.enabled {
305            return;
306        }
307        self.current_stratum = Some(stratum_id);
308        self.stratum_start = Some(Instant::now());
309        self.strata
310            .push(StratumStats::new(stratum_id, num_rules, is_recursive));
311    }
312
313    /// End timing the current stratum
314    pub fn end_stratum(&mut self) {
315        if !self.enabled {
316            return;
317        }
318        if let (Some(start), Some(_idx)) = (self.stratum_start.take(), self.current_stratum.take())
319        {
320            let duration = start.elapsed();
321            if let Some(stratum) = self.strata.last_mut() {
322                stratum.duration_us = duration.as_micros() as u64;
323            }
324        }
325    }
326
327    /// Record fixpoint iteration count for the current stratum
328    pub fn record_iterations(&mut self, iterations: usize) {
329        if !self.enabled {
330            return;
331        }
332        if let Some(stratum) = self.strata.last_mut() {
333            stratum.iterations = iterations;
334        }
335    }
336
337    /// Record an operation with timing
338    ///
339    /// This is a convenience method that calculates duration from a start time.
340    ///
341    /// # Arguments
342    /// * `op_name` - Name of the operation (e.g., "join", "filter", "scan")
343    /// * `input_rows` - Number of input rows
344    /// * `output_rows` - Number of output rows
345    /// * `start` - The instant when the operation started
346    /// * `memory_bytes` - Memory used by the operation
347    pub fn record_op(
348        &mut self,
349        op_name: impl Into<String>,
350        input_rows: u64,
351        output_rows: u64,
352        start: Instant,
353        memory_bytes: u64,
354    ) {
355        if !self.enabled {
356            return;
357        }
358        let duration = start.elapsed();
359        self.record(OpStats {
360            op_name: op_name.into(),
361            input_rows,
362            output_rows,
363            duration_us: duration.as_micros() as u64,
364            memory_bytes,
365        });
366    }
367
368    /// Start timing an operation
369    ///
370    /// Returns the current instant if profiling is enabled, None otherwise.
371    /// This allows zero-overhead timing when profiling is disabled.
372    #[inline]
373    pub fn start_op(&self) -> Option<Instant> {
374        if self.enabled {
375            Some(Instant::now())
376        } else {
377            None
378        }
379    }
380
381    /// Record peak memory observation
382    pub fn record_peak_memory(&mut self, memory_bytes: u64) {
383        if !self.enabled {
384            return;
385        }
386        if memory_bytes > self.peak_memory_bytes {
387            self.peak_memory_bytes = memory_bytes;
388        }
389    }
390
391    /// Get execution stats for CLI output
392    pub fn execution_stats(&self, total_output_rows: u64) -> ExecutionStats {
393        ExecutionStats {
394            total_duration_us: self.strata.iter().map(|s| s.duration_us).sum(),
395            strata: self.strata.clone(),
396            peak_memory_bytes: self.peak_memory_bytes,
397            memory_budget_bytes: self.memory_budget_bytes,
398            total_output_rows,
399        }
400    }
401
402    /// Check if profiling is enabled
403    pub fn is_enabled(&self) -> bool {
404        self.enabled
405    }
406
407    /// Record operation statistics
408    ///
409    /// If the profiler is disabled, this is a no-op.
410    /// If a stratum is active, the operation is also recorded in the stratum.
411    ///
412    /// # Arguments
413    /// * `stats` - The operation statistics to record
414    pub fn record(&mut self, stats: OpStats) {
415        if self.enabled {
416            // Also add to current stratum if one is active
417            if self.current_stratum.is_some() {
418                if let Some(stratum) = self.strata.last_mut() {
419                    stratum.ops.push(stats.clone());
420                }
421            }
422            self.stats.push(stats);
423        }
424    }
425
426    /// Get all recorded statistics
427    ///
428    /// Returns a slice of all operation statistics collected so far.
429    pub fn stats(&self) -> &[OpStats] {
430        &self.stats
431    }
432
433    /// Clear all recorded statistics
434    ///
435    /// Removes all collected statistics but keeps the profiler enabled/disabled state.
436    pub fn clear(&mut self) {
437        self.stats.clear();
438        self.strata.clear();
439        self.current_stratum = None;
440        self.stratum_start = None;
441        self.peak_memory_bytes = 0;
442    }
443
444    /// Get total duration across all operations in microseconds
445    pub fn total_duration_us(&self) -> u64 {
446        self.stats.iter().map(|s| s.duration_us).sum()
447    }
448
449    /// Get total memory usage across all operations in bytes
450    ///
451    /// Note: This is the sum of memory reported by each operation, which may
452    /// include overlapping allocations. It represents total memory activity
453    /// rather than peak memory usage.
454    pub fn total_memory_bytes(&self) -> u64 {
455        self.stats.iter().map(|s| s.memory_bytes).sum()
456    }
457
458    /// Get peak memory usage across all operations in bytes
459    ///
460    /// Returns the maximum memory_bytes value across all recorded operations.
461    /// Returns 0 if no operations have been recorded.
462    pub fn peak_memory_bytes(&self) -> u64 {
463        self.stats.iter().map(|s| s.memory_bytes).max().unwrap_or(0)
464    }
465
466    /// Get the number of recorded operations
467    pub fn operation_count(&self) -> usize {
468        self.stats.len()
469    }
470
471    /// Generate a human-readable summary of the profiling data
472    ///
473    /// The summary includes:
474    /// - Total operation count
475    /// - Total duration in milliseconds
476    /// - Total memory usage
477    /// - Per-operation breakdown with timing and row counts
478    pub fn summary(&self) -> String {
479        if self.stats.is_empty() {
480            return "Profiler: No operations recorded".to_string();
481        }
482
483        let total_duration_us = self.total_duration_us();
484        let total_duration_ms = total_duration_us as f64 / 1000.0;
485        let total_memory = self.total_memory_bytes();
486        let peak_memory = self.peak_memory_bytes();
487
488        let mut output = String::new();
489        output.push_str("=== Execution Profile ===\n");
490        output.push_str(&format!("Operations: {}\n", self.stats.len()));
491        output.push_str(&format!(
492            "Total duration: {:.3} ms ({} us)\n",
493            total_duration_ms, total_duration_us
494        ));
495        output.push_str(&format!("Total memory: {} bytes\n", total_memory));
496        output.push_str(&format!("Peak memory: {} bytes\n", peak_memory));
497        output.push_str("\n--- Operations ---\n");
498
499        for (i, stat) in self.stats.iter().enumerate() {
500            let duration_ms = stat.duration_us as f64 / 1000.0;
501            let percentage = if total_duration_us > 0 {
502                (stat.duration_us as f64 / total_duration_us as f64) * 100.0
503            } else {
504                0.0
505            };
506
507            output.push_str(&format!(
508                "{:3}. {:<20} | {:>10} -> {:>10} rows | {:>8.3} ms ({:>5.1}%) | {:>10} bytes\n",
509                i + 1,
510                truncate_name(&stat.op_name, 20),
511                stat.input_rows,
512                stat.output_rows,
513                duration_ms,
514                percentage,
515                stat.memory_bytes
516            ));
517        }
518
519        output
520    }
521
522    /// Enable or disable the profiler
523    ///
524    /// When disabled, `record` becomes a no-op. Existing stats are preserved.
525    pub fn set_enabled(&mut self, enabled: bool) {
526        self.enabled = enabled;
527    }
528}
529
530impl Default for Profiler {
531    /// Creates a disabled profiler by default
532    fn default() -> Self {
533        Self {
534            enabled: false,
535            stats: Vec::new(),
536            strata: Vec::new(),
537            current_stratum: None,
538            stratum_start: None,
539            peak_memory_bytes: 0,
540            memory_budget_bytes: 0,
541        }
542    }
543}
544
545/// RAII guard for measuring operation timing
546///
547/// Records the operation duration when dropped.
548pub struct MeasureGuard<'a> {
549    profiler: &'a mut Profiler,
550    op_name: String,
551    input_rows: u64,
552    start: Instant,
553    output_rows: Option<u64>,
554}
555
556impl<'a> MeasureGuard<'a> {
557    /// Create a new measure guard
558    pub fn new(profiler: &'a mut Profiler, op_name: impl Into<String>, input_rows: u64) -> Self {
559        Self {
560            profiler,
561            op_name: op_name.into(),
562            input_rows,
563            start: Instant::now(),
564            output_rows: None,
565        }
566    }
567
568    /// Set the output row count and finish timing
569    pub fn finish(mut self, output_rows: u64) {
570        self.output_rows = Some(output_rows);
571        // Drop will record the stats
572    }
573}
574
575impl<'a> Drop for MeasureGuard<'a> {
576    fn drop(&mut self) {
577        if self.profiler.is_enabled() {
578            let duration = self.start.elapsed();
579            self.profiler.record(OpStats {
580                op_name: std::mem::take(&mut self.op_name),
581                input_rows: self.input_rows,
582                output_rows: self.output_rows.unwrap_or(0),
583                duration_us: duration.as_micros() as u64,
584                memory_bytes: 0,
585            });
586        }
587    }
588}
589
590/// Truncate a name to fit within max_len characters
591fn truncate_name(name: &str, max_len: usize) -> String {
592    if name.len() <= max_len {
593        name.to_string()
594    } else {
595        format!("{}...", &name[..max_len.saturating_sub(3)])
596    }
597}
598
599#[cfg(test)]
600mod tests {
601    use super::*;
602
603    // ============== OpStats Tests ==============
604
605    #[test]
606    fn test_opstats_new() {
607        let stats = OpStats::new("hash_join", 1000, 500, 1500, 4096);
608
609        assert_eq!(stats.op_name, "hash_join");
610        assert_eq!(stats.input_rows, 1000);
611        assert_eq!(stats.output_rows, 500);
612        assert_eq!(stats.duration_us, 1500);
613        assert_eq!(stats.memory_bytes, 4096);
614    }
615
616    #[test]
617    fn test_opstats_timed() {
618        let stats = OpStats::timed("filter", 1000, 800, 200);
619
620        assert_eq!(stats.op_name, "filter");
621        assert_eq!(stats.input_rows, 1000);
622        assert_eq!(stats.output_rows, 800);
623        assert_eq!(stats.duration_us, 200);
624        assert_eq!(stats.memory_bytes, 0);
625    }
626
627    #[test]
628    fn test_opstats_default() {
629        let stats = OpStats::default();
630
631        assert_eq!(stats.op_name, "");
632        assert_eq!(stats.input_rows, 0);
633        assert_eq!(stats.output_rows, 0);
634        assert_eq!(stats.duration_us, 0);
635        assert_eq!(stats.memory_bytes, 0);
636    }
637
638    #[test]
639    fn test_opstats_clone() {
640        let stats = OpStats::new("scan", 0, 1000, 100, 2048);
641        let cloned = stats.clone();
642
643        assert_eq!(stats, cloned);
644    }
645
646    #[test]
647    fn test_opstats_debug() {
648        let stats = OpStats::new("test_op", 100, 50, 10, 1024);
649        let debug_str = format!("{:?}", stats);
650
651        assert!(debug_str.contains("test_op"));
652        assert!(debug_str.contains("100"));
653        assert!(debug_str.contains("50"));
654    }
655
656    // ============== Profiler Creation Tests ==============
657
658    #[test]
659    fn test_profiler_new_enabled() {
660        let profiler = Profiler::new(true);
661
662        assert!(profiler.is_enabled());
663        assert!(profiler.stats().is_empty());
664    }
665
666    #[test]
667    fn test_profiler_new_disabled() {
668        let profiler = Profiler::new(false);
669
670        assert!(!profiler.is_enabled());
671        assert!(profiler.stats().is_empty());
672    }
673
674    #[test]
675    fn test_profiler_default() {
676        let profiler = Profiler::default();
677
678        assert!(!profiler.is_enabled());
679        assert!(profiler.stats().is_empty());
680    }
681
682    // ============== Profiler Recording Tests ==============
683
684    #[test]
685    fn test_profiler_record_when_enabled() {
686        let mut profiler = Profiler::new(true);
687
688        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
689        profiler.record(OpStats::new("op2", 50, 25, 5, 512));
690
691        assert_eq!(profiler.stats().len(), 2);
692        assert_eq!(profiler.stats()[0].op_name, "op1");
693        assert_eq!(profiler.stats()[1].op_name, "op2");
694    }
695
696    #[test]
697    fn test_profiler_record_when_disabled() {
698        let mut profiler = Profiler::new(false);
699
700        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
701        profiler.record(OpStats::new("op2", 50, 25, 5, 512));
702
703        assert!(profiler.stats().is_empty());
704    }
705
706    #[test]
707    fn test_profiler_set_enabled() {
708        let mut profiler = Profiler::new(false);
709
710        // Initially disabled, record should be no-op
711        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
712        assert!(profiler.stats().is_empty());
713
714        // Enable and record
715        profiler.set_enabled(true);
716        assert!(profiler.is_enabled());
717        profiler.record(OpStats::new("op2", 50, 25, 5, 512));
718        assert_eq!(profiler.stats().len(), 1);
719        assert_eq!(profiler.stats()[0].op_name, "op2");
720
721        // Disable again
722        profiler.set_enabled(false);
723        assert!(!profiler.is_enabled());
724        profiler.record(OpStats::new("op3", 25, 10, 2, 256));
725        assert_eq!(profiler.stats().len(), 1); // Still only op2
726    }
727
728    // ============== Profiler Clear Tests ==============
729
730    #[test]
731    fn test_profiler_clear() {
732        let mut profiler = Profiler::new(true);
733
734        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
735        profiler.record(OpStats::new("op2", 50, 25, 5, 512));
736        assert_eq!(profiler.stats().len(), 2);
737
738        profiler.clear();
739
740        assert!(profiler.stats().is_empty());
741        assert!(profiler.is_enabled()); // Enabled state preserved
742    }
743
744    #[test]
745    fn test_profiler_clear_preserves_enabled_state() {
746        let mut profiler = Profiler::new(true);
747        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
748        profiler.clear();
749
750        assert!(profiler.is_enabled());
751
752        profiler.set_enabled(false);
753        profiler.clear();
754
755        assert!(!profiler.is_enabled());
756    }
757
758    // ============== Profiler Aggregation Tests ==============
759
760    #[test]
761    fn test_total_duration_us() {
762        let mut profiler = Profiler::new(true);
763
764        profiler.record(OpStats::new("op1", 100, 50, 100, 0));
765        profiler.record(OpStats::new("op2", 50, 25, 200, 0));
766        profiler.record(OpStats::new("op3", 25, 10, 150, 0));
767
768        assert_eq!(profiler.total_duration_us(), 450);
769    }
770
771    #[test]
772    fn test_total_duration_us_empty() {
773        let profiler = Profiler::new(true);
774
775        assert_eq!(profiler.total_duration_us(), 0);
776    }
777
778    #[test]
779    fn test_total_memory_bytes() {
780        let mut profiler = Profiler::new(true);
781
782        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
783        profiler.record(OpStats::new("op2", 50, 25, 5, 2048));
784        profiler.record(OpStats::new("op3", 25, 10, 2, 512));
785
786        assert_eq!(profiler.total_memory_bytes(), 3584);
787    }
788
789    #[test]
790    fn test_total_memory_bytes_empty() {
791        let profiler = Profiler::new(true);
792
793        assert_eq!(profiler.total_memory_bytes(), 0);
794    }
795
796    #[test]
797    fn test_peak_memory_bytes() {
798        let mut profiler = Profiler::new(true);
799
800        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
801        profiler.record(OpStats::new("op2", 50, 25, 5, 4096));
802        profiler.record(OpStats::new("op3", 25, 10, 2, 2048));
803
804        assert_eq!(profiler.peak_memory_bytes(), 4096);
805    }
806
807    #[test]
808    fn test_peak_memory_bytes_empty() {
809        let profiler = Profiler::new(true);
810
811        assert_eq!(profiler.peak_memory_bytes(), 0);
812    }
813
814    #[test]
815    fn test_operation_count() {
816        let mut profiler = Profiler::new(true);
817
818        assert_eq!(profiler.operation_count(), 0);
819
820        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
821        assert_eq!(profiler.operation_count(), 1);
822
823        profiler.record(OpStats::new("op2", 50, 25, 5, 512));
824        assert_eq!(profiler.operation_count(), 2);
825
826        profiler.clear();
827        assert_eq!(profiler.operation_count(), 0);
828    }
829
830    // ============== Profiler Summary Tests ==============
831
832    #[test]
833    fn test_summary_empty() {
834        let profiler = Profiler::new(true);
835        let summary = profiler.summary();
836
837        assert!(summary.contains("No operations recorded"));
838    }
839
840    #[test]
841    fn test_summary_with_operations() {
842        let mut profiler = Profiler::new(true);
843
844        profiler.record(OpStats::new("scan", 0, 1000, 100, 4096));
845        profiler.record(OpStats::new("filter", 1000, 500, 200, 2048));
846        profiler.record(OpStats::new("hash_join", 500, 250, 500, 8192));
847
848        let summary = profiler.summary();
849
850        // Check header
851        assert!(summary.contains("=== Execution Profile ==="));
852        assert!(summary.contains("Operations: 3"));
853
854        // Check timing
855        assert!(summary.contains("Total duration:"));
856        assert!(summary.contains("800 us"));
857
858        // Check memory
859        assert!(summary.contains("Total memory: 14336 bytes"));
860        assert!(summary.contains("Peak memory: 8192 bytes"));
861
862        // Check operations listed
863        assert!(summary.contains("scan"));
864        assert!(summary.contains("filter"));
865        assert!(summary.contains("hash_join"));
866
867        // Check row counts are present
868        assert!(summary.contains("1000"));
869        assert!(summary.contains("500"));
870        assert!(summary.contains("250"));
871    }
872
873    #[test]
874    fn test_summary_percentages() {
875        let mut profiler = Profiler::new(true);
876
877        // Two operations with known durations for percentage calculation
878        profiler.record(OpStats::new("fast_op", 100, 50, 250, 0));
879        profiler.record(OpStats::new("slow_op", 100, 50, 750, 0));
880
881        let summary = profiler.summary();
882
883        // fast_op should be 25%, slow_op should be 75%
884        assert!(summary.contains("25.0%") || summary.contains("25."));
885        assert!(summary.contains("75.0%") || summary.contains("75."));
886    }
887
888    // ============== Truncate Name Tests ==============
889
890    #[test]
891    fn test_truncate_name_short() {
892        let result = truncate_name("short", 20);
893        assert_eq!(result, "short");
894    }
895
896    #[test]
897    fn test_truncate_name_exact() {
898        let name = "exactly_twenty_chars"; // 20 chars
899        let result = truncate_name(name, 20);
900        assert_eq!(result, name);
901    }
902
903    #[test]
904    fn test_truncate_name_long() {
905        let name = "this_is_a_very_long_operation_name";
906        let result = truncate_name(name, 20);
907        assert_eq!(result.len(), 20);
908        assert!(result.ends_with("..."));
909    }
910
911    // ============== Integration Tests ==============
912
913    #[test]
914    fn test_profiler_full_workflow() {
915        // Simulate a typical profiling workflow
916        let mut profiler = Profiler::new(true);
917
918        // Simulate query execution
919        profiler.record(OpStats::new("scan_edge", 0, 10000, 500, 40000));
920        profiler.record(OpStats::new("scan_node", 0, 1000, 100, 4000));
921        profiler.record(OpStats::new("hash_join", 11000, 5000, 2000, 100000));
922        profiler.record(OpStats::new("filter", 5000, 2000, 300, 20000));
923        profiler.record(OpStats::new("project", 2000, 2000, 50, 8000));
924        profiler.record(OpStats::new("dedup", 2000, 1500, 400, 12000));
925
926        // Verify stats
927        assert_eq!(profiler.operation_count(), 6);
928        assert_eq!(profiler.total_duration_us(), 3350);
929        assert_eq!(profiler.total_memory_bytes(), 184000);
930        assert_eq!(profiler.peak_memory_bytes(), 100000);
931
932        // Generate summary
933        let summary = profiler.summary();
934        assert!(summary.contains("6"));
935        assert!(summary.contains("scan_edge"));
936        assert!(summary.contains("hash_join"));
937        assert!(summary.contains("dedup"));
938
939        // Clear and verify
940        profiler.clear();
941        assert_eq!(profiler.operation_count(), 0);
942        assert!(profiler.is_enabled());
943    }
944
945    #[test]
946    fn test_profiler_disabled_has_zero_overhead() {
947        // When disabled, nothing should be stored
948        let mut profiler = Profiler::new(false);
949
950        for i in 0..1000 {
951            profiler.record(OpStats::new(
952                format!("op_{}", i),
953                i as u64,
954                i as u64,
955                i as u64,
956                i as u64,
957            ));
958        }
959
960        // Should have zero stats
961        assert_eq!(profiler.operation_count(), 0);
962        assert_eq!(profiler.total_duration_us(), 0);
963        assert_eq!(profiler.total_memory_bytes(), 0);
964    }
965
966    #[test]
967    fn test_profiler_stats_immutable_reference() {
968        let mut profiler = Profiler::new(true);
969
970        profiler.record(OpStats::new("op1", 100, 50, 10, 1024));
971
972        // Get immutable reference
973        let stats = profiler.stats();
974        assert_eq!(stats.len(), 1);
975        assert_eq!(stats[0].op_name, "op1");
976
977        // Can still record after getting immutable reference (in separate scope)
978        profiler.record(OpStats::new("op2", 50, 25, 5, 512));
979        assert_eq!(profiler.stats().len(), 2);
980    }
981
982    #[test]
983    fn test_opstats_equality() {
984        let stats1 = OpStats::new("op", 100, 50, 10, 1024);
985        let stats2 = OpStats::new("op", 100, 50, 10, 1024);
986        let stats3 = OpStats::new("op", 100, 50, 10, 2048); // Different memory
987
988        assert_eq!(stats1, stats2);
989        assert_ne!(stats1, stats3);
990    }
991}
xlog_runtime/profiler.rs

xlog_runtime/
profiler.rs
