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