Audit physical operators for elapsed_compute double-counting of child compute time (follow-up to #24271)
- Dominant language
- Rust
- Stars
- 9.3k
- Forks
- 2.4k
- Avg merge
- 3d 7h
- Merged PRs (30d)
- 344
Description
### Describe the bug
#24271 fixed `HashJoinExec` reporting `build_time` (and therefore `elapsed_compute`) that included the entire build-side subtree's compute time, not just the join's own hash-table-construction work. The root cause was a timer wrapped around a future/fold that both drained the child's stream and did the operator's own work, so the child's compute got billed twice when metrics are summed across a plan (once under the child, once under the parent).
During review of #24271, the following operators were checked and confirmed to record only their own compute time (not their children's):
- FilterExec (`datafusion/physical-plan/src/filter.rs:1265`)
- ProjectionExec (`datafusion/physical-plan/src/projection.rs:647`)
- LimitExec / stream_limit (`datafusion/physical-plan/src/limit.rs:652`)
- WindowAggExec (`datafusion/physical-plan/src/windows/window_agg_exec.rs:598`)
- AggregateExec (`datafusion/physical-plan/src/aggregates/grouped_hash_stream.rs:345,647`)
- UnionExec (doesn't time `poll_next` at all)
That audit was not exhaustive. In particular, `NestedLoopJoinExec` (d`atafusion/physical-plan/src/joins/nested_loop_join.rs:1271`) uses a timer/`ScopedTimerGuard` pattern similar to the one that was buggy in `HashJoinExec`, and has not yet been verified. Other operators with a build/materialization phase (e.g. sort, sort-merge join, grouped aggregates with spilling) may have the same class of bug and should be checked too.
This issue tracks a systematic audit of ExecutionPlan implementations' metrics-recording code for this pattern, so each confirmed occurrence can be fixed in its own focused PR.
### To Reproduce
For each operator implementing ExecutionPlan, inspect where its `elapsed_compute` (or any per-operator timer, e.g. `build_time`) is started/stopped relative to polling/draining its child(ren):
1. Locate the timer (`metrics.elapsed_compute.timer() `/ `ScopedTimerGuard`) in the operator's `poll_next`/stream implementation or build-side setup.
2. Check whether the timer spans a call that also drives the child executor's stream (e.g. `child.poll_next_unpin(cx),`) versus spanning only the operator's own synchronous work.
3. If the timer spans child-driving work, running `EXPLAIN ANALYZE `on a query exercising that operator will show its `elapsed_compute` including (roughly) the full wall-clock time of its child subtree, not just its own processing — confirmable by comparing it against the child's own reported `elapsed_compute`.
### Expected behavior
Every operator's `elapsed_compute` (and related per-operator metrics like `build_time`) should reflect only that operator's own work, consistent with the pattern already confirmed for `FilterExec`, `ProjectionExec`, `LimitExec`, `WindowAggExec`, `AggregateExec`, and `UnionExec`. This makes it safe to sum `elapsed_compute` across a physical plan (e.g. for cost/telemetry models) without double-counting subtree compute or having to parse the execution plan to tell which time belongs to a node itself versus what's already rolled up from its children.
### Additional context
- Original fix: #24271 (`HashJoinExec`'s `build_time`)
- Discussion establishing the design convention (own-time-only, not rolled-up-with-children) and the decision to track further operators here rather than block #24271 on a full audit: see review thread on #24271.
- Suggested first candidate to check: `NestedLoopJoinExec` (`datafusion/physical-plan/src/joins/nested_loop_join.rs:1271`), flagged during the #24271 review as using an analogous timer pattern.
- Each confirmed bug found via this audit should be split into its own focused PR referencing this issue, per agreement with @Rich-T-kid in the #24271 review.
Contributor guide
Assessment
This issue has not been assessed yet.