Skip to content

feat(datafusion): trace query planning and execution - #9286

Open
amunra wants to merge 3 commits into
lance-format:mainfrom
rerun-io:upstream/datafusion-tracing
Open

amunra wants to merge 3 commits into
lance-format:mainfrom
rerun-io:upstream/datafusion-tracing

Conversation

@amunra

@amunra amunra commented Sep 16, 2026

Copy link
Copy Markdown

Adds tracing spans around the three DataFusion entry points in lance-datafusion that sit between a caller's request and the operators that do the work: filter optimization, plan execution setup, and plan analysis.

What is missing

execute_plan, analyze_plan_with_context and Planner::optimize_expr open no span of their own. The time spent simplifying and coercing a filter expression, building the session context and constructing the execution stream is attributed to whatever span the caller happens to have open, and analyze_plan's re-parenting of operator spans through TracedExec hangs them off whatever span the caller has open rather than a query-specific one.

What this does

  • Planner::optimize_expr is wrapped in a filter_optimize span at trace level.
  • execute_plan is wrapped in an execute_plan span at debug level. execute_plan is synchronous and returns a stream, so the span covers session-context creation, coalescing of a multi-partition plan and plan.execute() (stream construction), and closes before the caller polls the stream. Spans opened by operators while the stream is polled are not children of it.
  • analyze_plan_with_context is wrapped in a span named analyze_plan at debug level. This function is async, drives the stream to completion inside the call, and already wraps the plan in TracedExec::new(plan, Span::current()) so that AnalyzeExec's per-partition tasks report under the caller's span; the new span gives that parent a name, so the whole analysis, including the operators' own spans, sits under analyze_plan. The attribute sits on analyze_plan_with_context, which holds the body, rather than on the thin analyze_plan wrapper, so callers of either entry point are covered; the span is named after the public entry point.

All three spans use skip_all: the plan, the filter expression and the execution options are not recorded as span fields, so enabling the spans adds a fixed per-call cost and never formats a plan tree.

Why this design

#[instrument] attributes on the existing functions leave the signatures untouched and let the span levels be tuned independently: filter optimization is per-query and cheap, so it is trace; execution setup and analysis are the natural top-level units of a query trace, so they are debug. Instrumenting the stream returned by execute_plan (so that polling is covered too) is deliberately out of scope here and is a separate decision.

Testing

The spans have no observable behaviour to assert, so there are no new tests. cargo test -p lance-datafusion and cargo clippy --all --tests --benches -- -D warnings pass.

Compatibility

No API, format or dependency changes; lance-datafusion already depends on tracing.


Tracking: Ported from rerun-io#71.

Wrap `Planner::optimize_expr` in a `filter_optimize` tracing span at
trace level so the cost of simplifying and coercing a filter expression
shows up in a trace alongside the scan it belongs to. The span uses
`skip_all`, so the expression itself is not recorded.
Wrap `execute_plan` and `analyze_plan_with_context` in debug-level
tracing spans.

`execute_plan` is synchronous and returns a stream, so its span covers
session-context creation, coalescing of a multi-partition plan and
`plan.execute()` (stream construction), and closes before the caller
polls the stream. Spans opened by operators while the stream is polled
are not children of it.

`analyze_plan_with_context` is async and drives the stream to completion
inside the call, and already re-parents the operators' spans under
`Span::current()` via `TracedExec`; the new span gives that parent a
name. It is attached to `analyze_plan_with_context`, which holds the
body, rather than to the thin `analyze_plan` wrapper, so callers of
either entry point are covered; it is named `analyze_plan` so the span
name matches the public entry point.

Both spans use `skip_all`, so the plan and options are not recorded as
fields.
@github-actions github-actions Bot added the enhancement New feature or request label Sep 16, 2026
@amunra
amunra marked this pull request as ready for review September 16, 2026 14:52
lance-gatekeeper[bot]

This comment was marked as outdated.

@lance-gatekeeper lance-gatekeeper Bot added the K-changes Latest Gatekeeper recommendation requests changes. label Sep 16, 2026
Cover the three spans this PR adds.

`Planner::optimize_expr` opens `filter_optimize` at trace level and
`execute_plan` opens `execute_plan` at debug level, both asserted with
`tracing-mock`, the harness `lance-io` already uses. It matches a
strictly ordered queue against every notification it is shown, so each
test filters the subscriber down to the single span it asserts on.

`analyze_plan_with_context` opens `analyze_plan` at debug level and runs
the plan underneath it. `TracedExec` re-parents both the plan's `execute`
and every poll of the stream `execute` returns, so the test covers both,
using a small recording `Layer` read back after the subscriber is
uninstalled. An ordered queue would instead have to spell out each enter
and exit of the analyze span, pinning down when `AnalyzeExec` spawns its
input task; it would also report a lost parent as an out-of-order enter,
and a panic inside a tracing callback aborts the whole test binary.

`execute_plan` gets no parent assertion: it returns before the stream is
polled, so operator spans opened during polling are not its children.
@github-actions github-actions Bot added the A-deps Dependency updates label Sep 17, 2026
@lance-gatekeeper lance-gatekeeper Bot removed the K-changes Latest Gatekeeper recommendation requests changes. label Sep 17, 2026

@lance-gatekeeper lance-gatekeeper Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Gate recommendation: approve.

The prior coverage finding is fixed: this revision verifies all three span names and levels, plus analyze_plan parenting for both plan execution and stream polling. The instrumentation remains narrowly scoped to tracing with no API or format changes.

@lance-gatekeeper lance-gatekeeper Bot added the K-approved Latest Gatekeeper recommendation permits acceptance. label Sep 17, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

A-deps Dependency updates enhancement New feature or request K-approved Latest Gatekeeper recommendation permits acceptance.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants