Skip to content

Audit physical operators for elapsed_compute double-counting of child compute time (follow-up to #24271) #24459

Open

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 (datafusion/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

Activity

  1. goutamadwant commented on Aug 19, 2026

    @goutamadwant
    Contributor

    take

  2. goutamadwant commented on Aug 19, 2026

    @goutamadwant
    Contributor

    @ulrichurriola-parada-ops I audited NestedLoopJoinExec and confirmed that both build-side and probe-side child polling were included in its timers, including the spill and replay paths. I prepared a focused fix with four ablation-verified regressions. This addresses the NestedLoopJoinExec slice of #24459; the broader operator audit remains open.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bugSomething isn't working

Type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions