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 std::sync::LazyLock;
35
36use instant::Instant;
37
38use crate::debug_output::{self, Category, DebugEvent};
39
40/// Debug level from VIBESQL_DEBUG environment variable (lazily initialized)
41/// 0 = disabled, 1 = all, 2 = optimizer, 3 = scan, 4 = dml
42static DEBUG_LEVEL: LazyLock<u8> = LazyLock::new(|| {
43    std::env::var("VIBESQL_DEBUG")
44        .ok()
45        .and_then(|v| match v.to_lowercase().as_str() {
46            "1" | "true" | "all" => Some(1),
47            "optimizer" => Some(2),
48            "scan" => Some(3),
49            "dml" => Some(4),
50            _ => v.parse().ok(),
51        })
52        .unwrap_or(0)
53});
54
55/// Profiling enabled flag (lazily initialized from VIBESQL_PROFILE)
56static PROFILING_ENABLED: LazyLock<bool> =
57    LazyLock::new(|| std::env::var("VIBESQL_PROFILE").is_ok());
58
59/// Debug categories enabled via VIBESQL_DEBUG
60#[derive(Clone, Copy, PartialEq, Eq)]
61pub enum DebugCategory {
62    /// All debug logging enabled
63    All,
64    /// Optimizer decisions (join reorder, subquery transform, table elimination)
65    Optimizer,
66    /// Scan path selection (index vs table scan, columnar)
67    Scan,
68    /// DML operations (cost model, delete profiling)
69    Dml,
70    /// Disabled
71    None,
72}
73
74// Thread-local cache for debug checks to avoid repeated env var lookups
75thread_local! {
76    static SCAN_PATH_VERBOSE_ENABLED: std::cell::Cell<Option<bool>> = const { std::cell::Cell::new(None) };
77}
78
79/// Initialize profiling based on environment variable.
80/// Also initializes the debug output format.
81pub fn init() {
82    // Initialize debug output format first
83    debug_output::init();
84
85    // Force lazy initialization of profiling flag
86    if *PROFILING_ENABLED {
87        debug_output::debug_event(Category::Profile, "init", "PROFILE")
88            .text("Profiling enabled")
89            .field_bool("enabled", true)
90            .emit();
91    }
92}
93
94/// Check if profiling is enabled
95pub fn is_enabled() -> bool {
96    *PROFILING_ENABLED
97}
98
99/// Get the current debug category
100pub fn debug_category() -> DebugCategory {
101    match *DEBUG_LEVEL {
102        0 => DebugCategory::None,
103        1 => DebugCategory::All,
104        2 => DebugCategory::Optimizer,
105        3 => DebugCategory::Scan,
106        4 => DebugCategory::Dml,
107        _ => DebugCategory::None,
108    }
109}
110
111/// Check if a specific debug category is enabled
112pub fn is_debug_enabled(category: DebugCategory) -> bool {
113    let current = debug_category();
114    current == DebugCategory::All || current == category
115}
116
117/// Check if scan path debug logging is enabled
118/// Returns true if VIBESQL_DEBUG=1, VIBESQL_DEBUG=scan, or SCAN_PATH_VERBOSE=1
119#[inline]
120pub fn is_scan_debug_enabled() -> bool {
121    // Use thread-local cache to avoid repeated env var lookups
122    SCAN_PATH_VERBOSE_ENABLED.with(|cache| {
123        if let Some(enabled) = cache.get() {
124            return enabled;
125        }
126
127        let enabled =
128            is_debug_enabled(DebugCategory::Scan) || std::env::var("SCAN_PATH_VERBOSE").is_ok();
129
130        cache.set(Some(enabled));
131        enabled
132    })
133}
134
135/// A profiling timer that logs elapsed time when dropped
136pub struct ProfileTimer {
137    label: &'static str,
138    start: Instant,
139    enabled: bool,
140}
141
142impl ProfileTimer {
143    /// Create a new profiling timer
144    pub fn new(label: &'static str) -> Self {
145        let enabled = is_enabled();
146        Self { label, start: Instant::now(), enabled }
147    }
148}
149
150impl Drop for ProfileTimer {
151    fn drop(&mut self) {
152        if self.enabled {
153            let elapsed = self.start.elapsed();
154            DebugEvent::new(Category::Profile, "timer", "PROFILE")
155                .text(format!(
156                    "{} took {:.3}ms ({:.0}µs)",
157                    self.label,
158                    elapsed.as_secs_f64() * 1000.0,
159                    elapsed.as_micros()
160                ))
161                .field_str("label", self.label)
162                .field_duration_ms("duration_ms", elapsed)
163                .field_duration_us("duration_us", elapsed)
164                .emit();
165        }
166    }
167}
168
169/// Macro to create a profiling scope
170#[macro_export]
171macro_rules! profile {
172    ($label:expr) => {
173        let _timer = $crate::profiling::ProfileTimer::new($label);
174    };
175}
vibesql_executor/profiling.rs

vibesql_executor/
profiling.rs
