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.next().unwrap_or_else(|| {
75        panic!(
76            "profile entry count must match logical operator count: \
77             ran out of entries while building tree node for logical \
78             operator: {:?} (label='{}')",
79            std::mem::discriminant(logical),
80            logical.display_label(),
81        )
82    });
83
84    ProfileNode {
85        name: entry.name,
86        label: entry.label,
87        stats: entry.stats,
88        children,
89    }
90}
91
92/// Formats a `ProfileNode` tree into a human-readable text representation
93/// and wraps it in a `QueryResult` with a single "profile" column.
94pub fn profile_result(root: &ProfileNode, total_time_ms: f64) -> QueryResult {
95    let mut output = String::new();
96    format_node(&mut output, root, 0);
97    let _ = writeln!(output);
98    let _ = write!(output, "Total time: {total_time_ms:.2}ms");
99
100    QueryResult {
101        columns: vec!["profile".to_string()],
102        column_types: vec![LogicalType::String],
103        rows: vec![vec![Value::String(output.into())]],
104        execution_time_ms: Some(total_time_ms),
105        rows_scanned: None,
106        status_message: None,
107        gql_status: grafeo_common::utils::GqlStatus::SUCCESS,
108    }
109}
110
111/// Recursively formats a profile node with indentation.
112fn format_node(out: &mut String, node: &ProfileNode, depth: usize) {
113    let indent = "  ".repeat(depth);
114
115    // Compute self-time before locking stats (self_time_ns also locks).
116    let self_time_ns = self_time_ns(node);
117    let self_time_ms = self_time_ns as f64 / 1_000_000.0;
118
119    let rows_out = node.stats.lock().rows_out;
120
121    let _ = writeln!(
122        out,
123        "{indent}{name} ({label})  rows={rows}  time={time:.2}ms",
124        name = node.name,
125        label = node.label,
126        rows = rows_out,
127        time = self_time_ms,
128    );
129
130    for child in &node.children {
131        format_node(out, child, depth + 1);
132    }
133}
134
135/// Computes self-time: wall time minus children's wall time.
136fn self_time_ns(node: &ProfileNode) -> u64 {
137    let own_time = node.stats.lock().time_ns;
138    let child_time: u64 = node.children.iter().map(|c| c.stats.lock().time_ns).sum();
139    own_time.saturating_sub(child_time)
140}
141
142#[cfg(test)]
143mod tests {
144    use super::*;
145    use crate::query::plan::{
146        FilterOp, LogicalExpression, LogicalOperator, NodeScanOp, ReturnItem, ReturnOp,
147    };
148
149    /// Builds a simple `Return(Filter(NodeScan))` tree for profile-tree tests.
150    fn three_level_plan() -> LogicalOperator {
151        LogicalOperator::Return(ReturnOp {
152            items: vec![ReturnItem {
153                expression: LogicalExpression::Variable("n".to_string()),
154                alias: None,
155            }],
156            distinct: false,
157            input: Box::new(LogicalOperator::Filter(FilterOp {
158                predicate: LogicalExpression::Literal(grafeo_common::types::Value::Bool(true)),
159                input: Box::new(LogicalOperator::NodeScan(NodeScanOp {
160                    variable: "n".to_string(),
161                    label: Some("Person".to_string()),
162                    input: None,
163                })),
164                pushdown_hint: None,
165            })),
166        })
167    }
168
169    /// Verifies the builder walks in post-order: children must be consumed
170    /// before their parent. Also checks that self-time subtracts child time.
171    #[test]
172    fn test_profile_tree_post_order() {
173        let plan = three_level_plan();
174
175        // Provide three entries, ordered post-order: NodeScan, Filter, Return.
176        // Pre-set distinct wall-times on each so we can check self_time subtraction.
177        let (scan_entry, scan_stats) = ProfileEntry::new("NodeScan", "n:Person".to_string());
178        let (filter_entry, filter_stats) = ProfileEntry::new("Filter", "true".to_string());
179        let (return_entry, return_stats) = ProfileEntry::new("Return", "n".to_string());
180
181        scan_stats.lock().time_ns = 100;
182        scan_stats.lock().rows_out = 10;
183        filter_stats.lock().time_ns = 250; // Includes child (100) + 150 own
184        filter_stats.lock().rows_out = 10;
185        return_stats.lock().time_ns = 400; // Includes child (250) + 150 own
186        return_stats.lock().rows_out = 10;
187
188        let mut iter = vec![scan_entry, filter_entry, return_entry].into_iter();
189        let root = build_profile_tree(&plan, &mut iter);
190
191        // Root is Return, its child is Filter, whose child is NodeScan.
192        assert_eq!(root.name, "Return");
193        assert_eq!(root.children.len(), 1);
194        let filter = &root.children[0];
195        assert_eq!(filter.name, "Filter");
196        assert_eq!(filter.children.len(), 1);
197        let scan = &filter.children[0];
198        assert_eq!(scan.name, "NodeScan");
199        assert!(scan.children.is_empty());
200
201        // Self-time subtracts children: Return = 400 - 250 = 150; Filter = 250 - 100 = 150.
202        assert_eq!(self_time_ns(&root), 150);
203        assert_eq!(self_time_ns(filter), 150);
204        // Leaf has no children, so self = own time.
205        assert_eq!(self_time_ns(scan), 100);
206    }
207
208    /// Sanity check for the formatted output produced by `profile_result`.
209    #[test]
210    fn test_profile_result_formatting_and_saturating_self_time() {
211        // Build a tree where child time exceeds parent time: saturating_sub
212        // should produce 0 rather than underflowing.
213        let plan = LogicalOperator::Filter(FilterOp {
214            predicate: LogicalExpression::Literal(grafeo_common::types::Value::Bool(true)),
215            input: Box::new(LogicalOperator::NodeScan(NodeScanOp {
216                variable: "n".to_string(),
217                label: None,
218                input: None,
219            })),
220            pushdown_hint: None,
221        });
222        let (scan_entry, scan_stats) = ProfileEntry::new("NodeScan", "n:*".to_string());
223        let (filter_entry, filter_stats) = ProfileEntry::new("Filter", "true".to_string());
224        // Child dwarfs parent: child=500, parent=100 -> self should saturate at 0.
225        scan_stats.lock().time_ns = 500;
226        filter_stats.lock().time_ns = 100;
227        filter_stats.lock().rows_out = 3;
228
229        let mut iter = vec![scan_entry, filter_entry].into_iter();
230        let root = build_profile_tree(&plan, &mut iter);
231        assert_eq!(self_time_ns(&root), 0);
232
233        let result = profile_result(&root, 1.23);
234        assert_eq!(result.columns, vec!["profile".to_string()]);
235        let text = match &result.rows[0][0] {
236            grafeo_common::types::Value::String(s) => s.to_string(),
237            other => panic!("expected String, got {other:?}"),
238        };
239        assert!(text.contains("Filter"));
240        assert!(text.contains("NodeScan"));
241        assert!(text.contains("Total time: 1.23ms"));
242    }
243}
grafeo_engine/query/profile.rs

grafeo_engine/query/
profile.rs
