grafeo_engine/query/
profile.rs

1//! PROFILE statement: per-operator execution metrics.
2//!
3//! After a profiled query executes, the results are collected into a
4//! [`ProfileNode`] tree that mirrors the physical operator tree, annotated
5//! with actual row counts, timing, and call counts.
6
7use std::fmt::Write;
8use std::sync::Arc;
9
10use grafeo_common::types::{LogicalType, Value};
11use grafeo_core::execution::profile::{ProfileStats, SharedProfileStats};
12use parking_lot::Mutex;
13
14use super::plan::LogicalOperator;
15use crate::database::QueryResult;
16
17/// A node in the profile output tree, corresponding to one physical operator.
18#[derive(Debug)]
19pub struct ProfileNode {
20    /// Operator name (e.g., "NodeScan", "Filter", "Expand").
21    pub name: String,
22    /// Display label (e.g., "(n:Person)", "(n.age > 25) [label-first]").
23    pub label: String,
24    /// Shared stats handle, populated during execution.
25    pub stats: SharedProfileStats,
26    /// Child nodes.
27    pub children: Vec<ProfileNode>,
28}
29
30/// An entry collected during physical planning, used to build the profile tree.
31pub struct ProfileEntry {
32    /// Operator name from `Operator::name()`.
33    pub name: String,
34    /// Human-readable label from the logical operator.
35    pub label: String,
36    /// Shared stats handle passed to the `ProfiledOperator` wrapper.
37    pub stats: SharedProfileStats,
38}
39
40impl ProfileEntry {
41    /// Creates a new profile entry with fresh (empty) stats.
42    pub fn new(name: &str, label: String) -> (Self, SharedProfileStats) {
43        let stats = Arc::new(Mutex::new(ProfileStats::default()));
44        let entry = Self {
45            name: name.to_string(),
46            label,
47            stats: Arc::clone(&stats),
48        };
49        (entry, stats)
50    }
51}
52
53/// Builds a `ProfileNode` tree from the logical plan and a list of
54/// [`ProfileEntry`] items collected during physical planning.
55///
56/// The entries must be in **post-order** (children before parents),
57/// matching the order in which `plan_operator()` processes operators.
58///
59/// # Panics
60///
61/// Panics if the iterator yields fewer entries than there are logical operators.
62pub fn build_profile_tree(
63    logical: &LogicalOperator,
64    entries: &mut impl Iterator<Item = ProfileEntry>,
65) -> ProfileNode {
66    // Recurse into children first (post-order)
67    let children: Vec<ProfileNode> = logical
68        .children()
69        .into_iter()
70        .map(|child| build_profile_tree(child, entries))
71        .collect();
72
73    // Consume the entry for this node
74    let entry = entries
75        .next()
76        .expect("profile entry count must match logical operator count");
77
78    ProfileNode {
79        name: entry.name,
80        label: entry.label,
81        stats: entry.stats,
82        children,
83    }
84}
85
86/// Formats a `ProfileNode` tree into a human-readable text representation
87/// and wraps it in a `QueryResult` with a single "profile" column.
88pub fn profile_result(root: &ProfileNode, total_time_ms: f64) -> QueryResult {
89    let mut output = String::new();
90    format_node(&mut output, root, 0);
91    let _ = writeln!(output);
92    let _ = write!(output, "Total time: {total_time_ms:.2}ms");
93
94    QueryResult {
95        columns: vec!["profile".to_string()],
96        column_types: vec![LogicalType::String],
97        rows: vec![vec![Value::String(output.into())]],
98        execution_time_ms: Some(total_time_ms),
99        rows_scanned: None,
100        status_message: None,
101        gql_status: grafeo_common::utils::GqlStatus::SUCCESS,
102    }
103}
104
105/// Recursively formats a profile node with indentation.
106fn format_node(out: &mut String, node: &ProfileNode, depth: usize) {
107    let indent = "  ".repeat(depth);
108
109    // Compute self-time before locking stats (self_time_ns also locks).
110    let self_time_ns = self_time_ns(node);
111    let self_time_ms = self_time_ns as f64 / 1_000_000.0;
112
113    let rows_out = node.stats.lock().rows_out;
114
115    let _ = writeln!(
116        out,
117        "{indent}{name} ({label})  rows={rows}  time={time:.2}ms",
118        name = node.name,
119        label = node.label,
120        rows = rows_out,
121        time = self_time_ms,
122    );
123
124    for child in &node.children {
125        format_node(out, child, depth + 1);
126    }
127}
128
129/// Computes self-time: wall time minus children's wall time.
130fn self_time_ns(node: &ProfileNode) -> u64 {
131    let own_time = node.stats.lock().time_ns;
132    let child_time: u64 = node.children.iter().map(|c| c.stats.lock().time_ns).sum();
133    own_time.saturating_sub(child_time)
134}
135
136#[cfg(test)]
137mod tests {
138    use super::*;
139    use crate::query::plan::{
140        FilterOp, LogicalExpression, LogicalOperator, NodeScanOp, ReturnItem, ReturnOp,
141    };
142
143    /// Builds a simple `Return(Filter(NodeScan))` tree for profile-tree tests.
144    fn three_level_plan() -> LogicalOperator {
145        LogicalOperator::Return(ReturnOp {
146            items: vec![ReturnItem {
147                expression: LogicalExpression::Variable("n".to_string()),
148                alias: None,
149            }],
150            distinct: false,
151            input: Box::new(LogicalOperator::Filter(FilterOp {
152                predicate: LogicalExpression::Literal(grafeo_common::types::Value::Bool(true)),
153                input: Box::new(LogicalOperator::NodeScan(NodeScanOp {
154                    variable: "n".to_string(),
155                    label: Some("Person".to_string()),
156                    input: None,
157                })),
158                pushdown_hint: None,
159            })),
160        })
161    }
162
163    /// Verifies the builder walks in post-order: children must be consumed
164    /// before their parent. Also checks that self-time subtracts child time.
165    #[test]
166    fn test_profile_tree_post_order() {
167        let plan = three_level_plan();
168
169        // Provide three entries, ordered post-order: NodeScan, Filter, Return.
170        // Pre-set distinct wall-times on each so we can check self_time subtraction.
171        let (scan_entry, scan_stats) = ProfileEntry::new("NodeScan", "n:Person".to_string());
172        let (filter_entry, filter_stats) = ProfileEntry::new("Filter", "true".to_string());
173        let (return_entry, return_stats) = ProfileEntry::new("Return", "n".to_string());
174
175        scan_stats.lock().time_ns = 100;
176        scan_stats.lock().rows_out = 10;
177        filter_stats.lock().time_ns = 250; // Includes child (100) + 150 own
178        filter_stats.lock().rows_out = 10;
179        return_stats.lock().time_ns = 400; // Includes child (250) + 150 own
180        return_stats.lock().rows_out = 10;
181
182        let mut iter = vec![scan_entry, filter_entry, return_entry].into_iter();
183        let root = build_profile_tree(&plan, &mut iter);
184
185        // Root is Return, its child is Filter, whose child is NodeScan.
186        assert_eq!(root.name, "Return");
187        assert_eq!(root.children.len(), 1);
188        let filter = &root.children[0];
189        assert_eq!(filter.name, "Filter");
190        assert_eq!(filter.children.len(), 1);
191        let scan = &filter.children[0];
192        assert_eq!(scan.name, "NodeScan");
193        assert!(scan.children.is_empty());
194
195        // Self-time subtracts children: Return = 400 - 250 = 150; Filter = 250 - 100 = 150.
196        assert_eq!(self_time_ns(&root), 150);
197        assert_eq!(self_time_ns(filter), 150);
198        // Leaf has no children, so self = own time.
199        assert_eq!(self_time_ns(scan), 100);
200    }
201
202    /// Sanity check for the formatted output produced by `profile_result`.
203    #[test]
204    fn test_profile_result_formatting_and_saturating_self_time() {
205        // Build a tree where child time exceeds parent time: saturating_sub
206        // should produce 0 rather than underflowing.
207        let plan = LogicalOperator::Filter(FilterOp {
208            predicate: LogicalExpression::Literal(grafeo_common::types::Value::Bool(true)),
209            input: Box::new(LogicalOperator::NodeScan(NodeScanOp {
210                variable: "n".to_string(),
211                label: None,
212                input: None,
213            })),
214            pushdown_hint: None,
215        });
216        let (scan_entry, scan_stats) = ProfileEntry::new("NodeScan", "n:*".to_string());
217        let (filter_entry, filter_stats) = ProfileEntry::new("Filter", "true".to_string());
218        // Child dwarfs parent: child=500, parent=100 -> self should saturate at 0.
219        scan_stats.lock().time_ns = 500;
220        filter_stats.lock().time_ns = 100;
221        filter_stats.lock().rows_out = 3;
222
223        let mut iter = vec![scan_entry, filter_entry].into_iter();
224        let root = build_profile_tree(&plan, &mut iter);
225        assert_eq!(self_time_ns(&root), 0);
226
227        let result = profile_result(&root, 1.23);
228        assert_eq!(result.columns, vec!["profile".to_string()]);
229        let text = match &result.rows[0][0] {
230            grafeo_common::types::Value::String(s) => s.to_string(),
231            other => panic!("expected String, got {other:?}"),
232        };
233        assert!(text.contains("Filter"));
234        assert!(text.contains("NodeScan"));
235        assert!(text.contains("Total time: 1.23ms"));
236    }
237}
grafeo_engine/query/profile.rs

grafeo_engine/query/
profile.rs
