Add planning-effort counters and prepare-stage timer to profile notes (#16)

Extends the profile-gated instrumentation (#15) with per-query
planning-effort counters and a `prepare` stage timer.

- `prepare` timer fills the gap between lowering and the published
  snapshot (order-by resolution, row-count evaluation, target config),
  the only previously uninstrumented stage around the graph-row call.
- Counters: node_legal_universe_sources, edge_source_consults,
  edge_source_misses, secondary_index_followups.

Counters use a crate-local thread-local the planner increments (always)
and the GQL layer snapshots when profiling; values ride the existing
GqlExecutionExplain.notes line, so no public struct or connector changes
and the shared read substrate is untouched.

profile=false is unchanged: timer mark() returns None and counter values
are neither snapshotted nor surfaced. Measured fire count is 3-8 per query
(~22-57 ns, ~0.001-0.005% of read latency).

Author: heunghingwan

src/engine/query.rs

@@ -44,9 +44,14 @@ struct GqlQueryInstrumentation {
     enabled: bool,
     bind_ns: u64,
     lower_ns: u64,
+    prepare_ns: u64,
     snapshot_ns: u64,
     graph_row_ns: u64,
     projection_ns: u64,
+    edge_source_consults: u64,
+    edge_source_misses: u64,
+    node_legal_universe_sources: u64,
+    secondary_index_followups: u64,
 }
 
 impl GqlQueryInstrumentation {
@@ -55,9 +60,14 @@ impl GqlQueryInstrumentation {
             enabled,
             bind_ns: 0,
             lower_ns: 0,
+            prepare_ns: 0,
             snapshot_ns: 0,
             graph_row_ns: 0,
             projection_ns: 0,
+            edge_source_consults: 0,
+            edge_source_misses: 0,
+            node_legal_universe_sources: 0,
+            secondary_index_followups: 0,
         }
     }
 
@@ -68,14 +78,21 @@ impl GqlQueryInstrumentation {
 
     fn note(&self) -> String {
         format!(
-            "stage timing (nanoseconds): bind={b} lower={l} snapshot={s} \
-             graph_row_plan_and_execute={g} projection={p}; graph_row covers normalize, \
-             cost-based planning, index probe, and execution inside the shared read view",
+            "stage timing (nanoseconds): bind={b} lower={l} prepare={pr} snapshot={s} \
+             graph_row_plan_and_execute={g} projection={p}; planning counters: \
+             node_legal_universe_sources={n} edge_source_consults={ec} edge_source_misses={em} \
+             secondary_index_followups={sf}; graph_row covers normalize, cost-based planning, \
+             index probe, and execution inside the shared read view",
             b = self.bind_ns,
             l = self.lower_ns,
+            pr = self.prepare_ns,
             s = self.snapshot_ns,
             g = self.graph_row_ns,
             p = self.projection_ns,
+            n = self.node_legal_universe_sources,
+            ec = self.edge_source_consults,
+            em = self.edge_source_misses,
+            sf = self.secondary_index_followups,
         )
     }
 }
@@ -155,10 +172,14 @@ impl DatabaseEngine {
         if matches!(&lowered.native_target, GqlNativeTarget::GraphPipeline { .. }) {
             return self.execute_gql_pipeline_target(lowered, started_at, options);
         }
+        let prepare_start = instr.mark();
         let resolved_order_by = resolve_order_by_return_aliases(&lowered)?;
         validate_gql_row_independent_order_keys(&resolved_order_by, &lowered, params)?;
         let row_counts = evaluate_gql_row_counts(&lowered, params, options)?;
         configure_gql_graph_row_target(&mut lowered, &resolved_order_by, &row_counts, options)?;
+        if let Some(t) = prepare_start {
+            instr.prepare_ns = t.elapsed().as_nanos() as u64;
+        }
         let warnings = lowered.warnings.clone();
 
         if row_counts.limit == Some(0) {
@@ -220,10 +241,21 @@ impl DatabaseEngine {
         let mut warnings = warnings;
 
         let graph_row_start = instr.mark();
+        if instr.enabled {
+            reset_graph_row_planning_probe();
+        }
         let graph_rows = execute_gql_graph_row_target(&published.view, &lowered)?;
+        let secondary_index_followups = graph_rows.followups.len();
         if let Some(t) = graph_row_start {
             instr.graph_row_ns = t.elapsed().as_nanos() as u64;
         }
+        if instr.enabled {
+            let probe = snapshot_graph_row_planning_probe();
+            instr.edge_source_consults = probe.edge_source_consults;
+            instr.edge_source_misses = probe.edge_source_misses;
+            instr.node_legal_universe_sources = probe.node_legal_universe_sources;
+            instr.secondary_index_followups = secondary_index_followups as u64;
+        }
         for followup in graph_rows.followups {
             self.runtime.enqueue_secondary_index_read_followup(followup);
         }

src/engine/query_plan.rs

@@ -169,6 +169,26 @@ impl GraphRowEdgeSourceCostMemo {
 
 const GRAPH_ROW_EDGE_INTERSECTION_TINY_SET: u64 = 64;
 
+#[derive(Clone, Copy, Default, Debug)]
+pub(crate) struct GraphRowPlanningProbeCounters {
+    pub(crate) edge_source_consults: u64,
+    pub(crate) edge_source_misses: u64,
+    pub(crate) node_legal_universe_sources: u64,
+}
+
+thread_local! {
+    static GRAPH_ROW_PLANNING_PROBE: std::cell::RefCell<GraphRowPlanningProbeCounters> =
+        std::cell::RefCell::new(GraphRowPlanningProbeCounters::default());
+}
+
+pub(crate) fn reset_graph_row_planning_probe() {
+    GRAPH_ROW_PLANNING_PROBE.with(|c| *c.borrow_mut() = GraphRowPlanningProbeCounters::default());
+}
+
+pub(crate) fn snapshot_graph_row_planning_probe() -> GraphRowPlanningProbeCounters {
+    GRAPH_ROW_PLANNING_PROBE.with(|c| *c.borrow())
+}
+
 #[derive(Clone, Debug)]
 struct GraphRowPhysicalSegment {
     segment_index: usize,
@@ -6011,13 +6031,24 @@ impl ReadView {
         build_explain: bool,
         memo: &'memo mut GraphRowEdgeSourceCostMemo,
     ) -> Result<&'memo GraphRowEdgeSourcePlanCost, EngineError> {
-        let Some(state_index) = GraphRowEdgeSourceCostMemo::bound_state_index(from_bound, to_bound)
-        else {
-            return Err(EngineError::InvalidOperation(
-                "graph row bound edge-source cost requested without a bound endpoint".into(),
-            ));
+        let state_index = match GraphRowEdgeSourceCostMemo::bound_state_index(from_bound, to_bound)
+        {
+            Some(idx) => idx,
+            None => {
+                return Err(EngineError::InvalidOperation(
+                    "graph row bound edge-source cost requested without a bound endpoint".into(),
+                ));
+            }
         };
-        if memo.bound_costs[edge_index][state_index].is_none() {
+        let is_miss = memo.bound_costs[edge_index][state_index].is_none();
+        GRAPH_ROW_PLANNING_PROBE.with(|c| {
+            let mut c = c.borrow_mut();
+            c.edge_source_consults += 1;
+            if is_miss {
+                c.edge_source_misses += 1;
+            }
+        });
+        if is_miss {
             let cost = self.graph_row_edge_source_plan_cost_with_endpoints(
                 query,
                 edge,
@@ -8884,6 +8915,10 @@ impl ReadView {
         }
 
         let legal_universe_sources = self.legal_universe_sources(query)?;
+        GRAPH_ROW_PLANNING_PROBE.with(|c| {
+            c.borrow_mut().node_legal_universe_sources +=
+                legal_universe_sources.len() as u64;
+        });
         let legal_universe_fallback =
             Self::cheapest_node_legal_universe_source(&legal_universe_sources);
         let cap_context = QueryCapContext {

src/engine/tests/gql_execution.rs

@@ -79,6 +79,78 @@ fn gql_query_profile_stage_timing_note_in_explain_plan() {
     );
 }
 
+#[test]
+fn gql_query_profile_planning_counters_in_explain_note() {
+    let (_dir, engine) = query_test_engine();
+    insert_query_node(&engine, "Person", "ada", &[], 1.0);
+
+    let profiled = engine
+        .execute_gql(
+            "MATCH (n:Person) WHERE elementKey(n) = 'ada' RETURN id(n)",
+            &GqlParams::new(),
+            &GqlExecutionOptions {
+                profile: true,
+                include_plan: true,
+                ..gql_opts()
+            },
+        )
+        .unwrap();
+    let note = profiled
+        .plan
+        .as_ref()
+        .and_then(|p| {
+            p.notes
+                .iter()
+                .find(|n| n.contains("planning counters"))
+                .cloned()
+        })
+        .expect("profile+include_plan should attach a planning-counters note");
+
+    assert!(
+        note.contains("prepare="),
+        "note should carry the prepare stage timer"
+    );
+    for key in [
+        "node_legal_universe_sources=",
+        "edge_source_consults=",
+        "edge_source_misses=",
+        "secondary_index_followups=",
+    ] {
+        assert!(note.contains(key), "note should carry counter {key:?}");
+    }
+
+    let universe = note
+        .split("node_legal_universe_sources=")
+        .nth(1)
+        .and_then(|rest| rest.trim_start().split(|c: char| !c.is_ascii_digit()).next())
+        .and_then(|s| s.parse::<u64>().ok())
+        .expect("node_legal_universe_sources should be a number");
+    assert!(
+        universe >= 1,
+        "a single-node graph-row query must enumerate >=1 universe source, got {universe}"
+    );
+
+    let plain = engine
+        .execute_gql(
+            "MATCH (n:Person) WHERE elementKey(n) = 'ada' RETURN id(n)",
+            &GqlParams::new(),
+            &GqlExecutionOptions {
+                include_plan: true,
+                ..gql_opts()
+            },
+        )
+        .unwrap();
+    let plain_plan = plain.plan.as_ref().unwrap();
+    assert!(
+        !plain_plan
+            .notes
+            .iter()
+            .any(|n| n.contains("planning counters")),
+        "profile=false must not attach planning counters, got: {:?}",
+        plain_plan.notes
+    );
+}
+
 fn execute_gql_with_params(
     engine: &DatabaseEngine,
     source: &str,