ulrichurriola-parada-ops opened a new issue, #24459:
URL: https://github.com/apache/datafusion/issues/24459
### 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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
