Skip to main content

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