Add profile-gated GQL read-path stage timing to explain notes - #15
Merged
bhensley5 merged 1 commit intoJul 3, 2026
Merged
Conversation
When options.profile is set, record per-query elapsed time for the GQL read stages (bind, lower, published_snapshot, graph-row target, projection) and append one summary line to the explain payload's notes. The note only appears when include_plan is also set (it rides on the existing GqlExecutionExplain.notes Vec, so no public struct or connector changes). Scope is deliberately limited to the GQL layer: graph_row_plan_and_execute lumps normalize, cost-based planning, index probe, and execution because those live inside the shared read view and are intentionally not touched here. The native hot path (e.g. get_node) does not go through this code. profile=false is a no-op: the collector is disabled and mark() never calls Instant::now, so there is zero overhead in the default path.
Owner
|
Thanks for the contribution. This is a good scoped first step for GQL profiling visibility. Merging via squash. |
bhensley5
pushed a commit
that referenced
this pull request
Jul 3, 2026
…#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).
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
When
profile: true(withinclude_plan: true), this appends a singleline to the existing
GqlExecutionExplain.notesarray, breaking per-queryGQL read latency down by stage:
Why
GqlExecutionStats.elapsed_usis whole-query only. A coarse per-stagebreakdown that lives entirely in the GQL layer makes it cheap to confirm
where per-query time is — and isn't — spent (e.g. bind+lower and
published_snapshotshow up as negligible), which helps steer optimizationeffort without a separate profiling harness.
Design (deliberately limited scope)
notes: Vec<String>onGqlExecutionExplain; Rust/Node/Python parityis untouched.
read.rs,query_exec.rs,ReadView/SourceList). The native hot path (get_node, etc.) does notgo through this code, so its latency is unaffected.
graph_row_plan_and_executeis intentionally combined — normalize,cost-based planning, index probe and execution all happen inside the
shared read view and are out of scope here. The note labels this so the
value isn't misread as pure planning time.
LIMIT 0, not graph pipelines).Overhead
profile: false(the default) is a no-op: the collector is disabled andmark()never callsInstant::now, so the default path carries no extrawork. When profiling is on, the cost is a few
Instant::nowcalls per query.Tests
New
gql_query_profile_stage_timing_note_in_explain_planasserts the noteappears with
profile+include_planand is absent withoutprofile.cargo test --lib gql(357 tests) andcargo clippy --libare clean.This is intentionally a small, self-contained first step; deeper
instrumentation (e.g. splitting the
graph_rowbucket, or planning-workcounters) is left for separate follow-ups.