vibesql_executor/
profiling.rs

1//! Performance profiling and debug utilities for understanding bottlenecks
2//!
3//! This module provides profiling infrastructure that integrates with the
4//! structured debug output system. When `VIBESQL_DEBUG_FORMAT=json`, profiling
5//! output is emitted as JSON for machine parsing.
6//!
7//! # Environment Variables
8//!
9//! ## Umbrella Debug Flag
10//!
11//! `VIBESQL_DEBUG` provides unified control over all semantic debug logging:
12//!
13//! - `VIBESQL_DEBUG=1` - Enable all semantic logging (optimizer decisions)
14//! - `VIBESQL_DEBUG=optimizer` - Enable only optimizer-related logging
15//! - `VIBESQL_DEBUG=scan` - Enable only scan path logging
16//! - `VIBESQL_DEBUG=dml` - Enable only DML-related logging
17//!
18//! ## Individual Flags (for fine-grained control)
19//!
20//! These flags work independently or are auto-enabled by `VIBESQL_DEBUG`:
21//!
22//! - `JOIN_REORDER_VERBOSE` - Join reorder decisions and costs
23//! - `SUBQUERY_TRANSFORM_VERBOSE` - Subquery-to-join transformations
24//! - `TABLE_ELIM_VERBOSE` - Table elimination decisions
25//! - `SCAN_PATH_VERBOSE` - Scan path selection (index vs table scan)
26//! - `INDEX_SELECT_DEBUG` - Index selection decisions
27//!
28//! ## Phase Timing Flags
29//!
30//! - `DELETE_PROFILE` - Delete operation phase timing
31//! - `JOIN_PROFILE` - Join execution phase timing
32//! - `RANGE_SCAN_PROFILE` - Range scan phase timing
33
34use crate::debug_output::{self, Category, DebugEvent};
35use instant::Instant;
36use std::sync::LazyLock;
37
38/// Debug level from VIBESQL_DEBUG environment variable (lazily initialized)
39/// 0 = disabled, 1 = all, 2 = optimizer, 3 = scan, 4 = dml
40static DEBUG_LEVEL: LazyLock<u8> = LazyLock::new(|| {
41    std::env::var("VIBESQL_DEBUG")
42        .ok()
43        .and_then(|v| match v.to_lowercase().as_str() {
44            "1" | "true" | "all" => Some(1),
45            "optimizer" => Some(2),
46            "scan" => Some(3),
47            "dml" => Some(4),
48            _ => v.parse().ok(),
49        })
50        .unwrap_or(0)
51});
52
53/// Profiling enabled flag (lazily initialized from VIBESQL_PROFILE)
54static PROFILING_ENABLED: LazyLock<bool> =
55    LazyLock::new(|| std::env::var("VIBESQL_PROFILE").is_ok());
56
57/// Debug categories enabled via VIBESQL_DEBUG
58#[derive(Clone, Copy, PartialEq, Eq)]
59pub enum DebugCategory {
60    /// All debug logging enabled
61    All,
62    /// Optimizer decisions (join reorder, subquery transform, table elimination)
63    Optimizer,
64    /// Scan path selection (index vs table scan, columnar)
65    Scan,
66    /// DML operations (cost model, delete profiling)
67    Dml,
68    /// Disabled
69    None,
70}
71
72// Thread-local cache for debug checks to avoid repeated env var lookups
73thread_local! {
74    static SCAN_PATH_VERBOSE_ENABLED: std::cell::Cell<Option<bool>> = const { std::cell::Cell::new(None) };
75}
76
77/// Initialize profiling based on environment variable.
78/// Also initializes the debug output format.
79pub fn init() {
80    // Initialize debug output format first
81    debug_output::init();
82
83    // Force lazy initialization of profiling flag
84    if *PROFILING_ENABLED {
85        debug_output::debug_event(Category::Profile, "init", "PROFILE")
86            .text("Profiling enabled")
87            .field_bool("enabled", true)
88            .emit();
89    }
90}
91
92/// Check if profiling is enabled
93pub fn is_enabled() -> bool {
94    *PROFILING_ENABLED
95}
96
97/// Get the current debug category
98pub fn debug_category() -> DebugCategory {
99    match *DEBUG_LEVEL {
100        0 => DebugCategory::None,
101        1 => DebugCategory::All,
102        2 => DebugCategory::Optimizer,
103        3 => DebugCategory::Scan,
104        4 => DebugCategory::Dml,
105        _ => DebugCategory::None,
106    }
107}
108
109/// Check if a specific debug category is enabled
110pub fn is_debug_enabled(category: DebugCategory) -> bool {
111    let current = debug_category();
112    current == DebugCategory::All || current == category
113}
114
115/// Check if scan path debug logging is enabled
116/// Returns true if VIBESQL_DEBUG=1, VIBESQL_DEBUG=scan, or SCAN_PATH_VERBOSE=1
117#[inline]
118pub fn is_scan_debug_enabled() -> bool {
119    // Use thread-local cache to avoid repeated env var lookups
120    SCAN_PATH_VERBOSE_ENABLED.with(|cache| {
121        if let Some(enabled) = cache.get() {
122            return enabled;
123        }
124
125        let enabled =
126            is_debug_enabled(DebugCategory::Scan) || std::env::var("SCAN_PATH_VERBOSE").is_ok();
127
128        cache.set(Some(enabled));
129        enabled
130    })
131}
132
133/// A profiling timer that logs elapsed time when dropped
134pub struct ProfileTimer {
135    label: &'static str,
136    start: Instant,
137    enabled: bool,
138}
139
140impl ProfileTimer {
141    /// Create a new profiling timer
142    pub fn new(label: &'static str) -> Self {
143        let enabled = is_enabled();
144        Self { label, start: Instant::now(), enabled }
145    }
146}
147
148impl Drop for ProfileTimer {
149    fn drop(&mut self) {
150        if self.enabled {
151            let elapsed = self.start.elapsed();
152            DebugEvent::new(Category::Profile, "timer", "PROFILE")
153                .text(format!(
154                    "{} took {:.3}ms ({:.0}µs)",
155                    self.label,
156                    elapsed.as_secs_f64() * 1000.0,
157                    elapsed.as_micros()
158                ))
159                .field_str("label", self.label)
160                .field_duration_ms("duration_ms", elapsed)
161                .field_duration_us("duration_us", elapsed)
162                .emit();
163        }
164    }
165}
166
167/// Macro to create a profiling scope
168#[macro_export]
169macro_rules! profile {
170    ($label:expr) => {
171        let _timer = $crate::profiling::ProfileTimer::new($label);
172    };
173}
vibesql_executor/profiling.rs

vibesql_executor/
profiling.rs
