Skip to content

fix: scope HashJoinExec build_time to hash-table construction only - #24271

Open
ulrichurriola-parada-ops wants to merge 1 commit into
apache:mainfrom
ulrichurriola-parada-ops:fix/hashjoin-elapsed-time
Open

ulrichurriola-parada-ops wants to merge 1 commit into
apache:mainfrom
ulrichurriola-parada-ops:fix/hashjoin-elapsed-time

Conversation

@ulrichurriola-parada-ops

@ulrichurriola-parada-ops ulrichurriola-parada-ops commented Aug 11, 2026 •

Copy link
Copy Markdown

Rationale for this change

HashJoinExec's elapsed_compute metric (as reported by EXPLAIN ANALYZE and ExecutionPlanMetricsSet) includes time spent executing the entire build-side subtree, not just the join's own work. Any tool that sums elapsed_compute across a physical plan to estimate total CPU time (e.g. to build a cost/telemetry model) will double-count that subtree's compute: once under the child operator(s) that did the work, and again under HashJoinExec.

What changes are included in this PR?

build_time was previously timed around the entire collect_left_input future (via left_fut.get_shared(cx) in collect_build_side). That future both drains the build-side child's stream and builds the hash table, so the child's own compute got billed to build_time whenever the driving partition executed both phases inline.

  • Scoped the build_time timer inside collect_left_input to start only after the build-side stream has been fully folded, covering just the synchronous bounds/hash-map construction.
  • Removed the now-redundant wrapping timer in collect_build_side.

Are these changes tested?

Covered by the existing hash_join test suite (correctness of join output and other metrics is unaffected). No new test was added to assert the exact build_time/elapsed_compute value, since there isn't currently a way to attribute deterministic wall-clock cost to a specific subtree in a unit test.

Are there any user-facing changes?

elapsed_compute reported for HashJoinExec (e.g. via EXPLAIN ANALYZE) will be smaller and more accurate, reflecting only the join's own compute rather than including its build-side subtree. No public API changes.

build_time previously wrapped the whole collect_left_input future,
including the build-side child's own stream-draining work, so its
compute got double-counted into this join's elapsed_compute. Time only
the post-fold hash-map construction instead.
@github-actions github-actions Bot added the physical-plan Changes to the physical-plan crate label Aug 11, 2026
@ulrichurriola-parada-ops
ulrichurriola-parada-ops marked this pull request as ready for review August 11, 2026 14:48

@Rich-T-kid Rich-T-kid 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.

Im a bit confused by this PR, where is _build_timer actually used?

@ulrichurriola-parada-ops

Copy link
Copy Markdown
Author

Im a bit confused by this PR, where is _build_timer actually used?

The _build_timer is not "used" but:

  • Its instantiation starts the timer (see Time.timer impl in datafusion/physical-expr-common/src/metrics/value.rs, l.214)
  • Its deletion (Drop in ScopedTimerGuard, datafusion/physical-expr-common/src/metrics/value.rs l.359) stops the timer and add elapsed time to the inner object: the metrics.build_time

Note: a similar use exists in the codebase in datafusion/physical-plan/src/joins/nested_loop_join.rs, l1271

Thank you for the review

@Rich-T-kid Rich-T-kid 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.

Ok this makes sense to me, but I think we should first double check that

HashJoinExec's elapsed_compute metric (as reported by EXPLAIN ANALYZE and ExecutionPlanMetricsSet) includes time spent executing the entire build-side subtree, not just the join's own work.

isn't intentional, I can see why we may want to include the build-side elapse compute as part of the hashJoin elapsed_compute.

I can see why it can cause errors if you were to sum all compute time but it may make more sense to view it as tree's where each nodes elapsed_compute is the sum of its children and its self

@Rich-T-kid

Copy link
Copy Markdown
Contributor

@ulrichurriola-parada-ops thank your for the explanation it helped out alot!

@ulrichurriola-parada-ops

Copy link
Copy Markdown
Author

Ok this makes sense to me, but I think we should first double check that

HashJoinExec's elapsed_compute metric (as reported by EXPLAIN ANALYZE and ExecutionPlanMetricsSet) includes time spent executing the entire build-side subtree, not just the join's own work.

isn't intentional, I can see why we may want to include the build-side elapse compute as part of the hashJoin elapsed_compute.

I can see why it can cause errors if you were to sum all compute time but it may make more sense to view it as tree's where each nodes elapsed_compute is the sum of its children and its self

@Rich-T-kid thank you for your response.

Other types of nodes do not include the subtree times and only record time when their sub nodes are ready:

  • FilterExec in datafusion/physical-plan/src/filter.rs:1265, inside the ready!(self.input.poll_next_unpin(cx)),
  • ProjectionExec in datafusion/physical-plan/src/projection.rs:647 that calls batch_project (which handles the timer),
  • LimitExec (stream_limit) in datafusion/physical-plan/src/limit.rs:652 calls stream_limit method with the timer inside it,
  • WindowAggExec in datafusion/physical-plan/src/windows/window_agg_exec.rs:598 with the timer inside the compute_aggregates method
  • AggregateExec, in datafusion/physical-plan/src/aggregates/grouped_hash_stream.rs345 (AggregateStream) and datafusion/physical-plan/src/aggregates/grouped_hash_stream.rs647 (GroupedHashAggregateStream)

UnionExec in datafusion/physical-plan/src/union.rs does not record poll_next timing at all and only takes into account the time spent in the execute method.

Considering those examples, recording a node own time and not its children in the elapsed_time (and thus in the build_time) feels like a common design to me.

Finally, including children's time also makes duration analysis harder — you'd need to parse the execution plan to tell which time belongs to a node itself versus what's already rolled up from its children.

@Rich-T-kid Rich-T-kid 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.

make sense to me. are there any other operators that incorrectly account for their children's compute time?

@ulrichurriola-parada-ops

Copy link
Copy Markdown
Author

make sense to me. are there any other operators that incorrectly account for their children's compute time?

I haven't had a chance to audit the other operators for the same issue, so I can't say for sure yet. Given that, would you agree to roll the fix out progressively rather than blocking on a full audit, starting with this PR ?
I can open a follow-up issue to track checking the other operators for the same compute-time accounting bug.

@Rich-T-kid

Copy link
Copy Markdown
Contributor

make sense to me. are there any other operators that incorrectly account for their children's compute time?

I haven't had a chance to audit the other operators for the same issue, so I can't say for sure yet. Given that, would you agree to roll the fix out progressively rather than blocking on a full audit, starting with this PR ? I can open a follow-up issue to track checking the other operators for the same compute-time accounting bug.

@ulrichurriola-parada-ops I think it makes sense to create an issue explainging your findings and then create focused PR's. I'd be happy to review them feel free to ping me

@ulrichurriola-parada-ops

Copy link
Copy Markdown
Author

make sense to me. are there any other operators that incorrectly account for their children's compute time?

I haven't had a chance to audit the other operators for the same issue, so I can't say for sure yet. Given that, would you agree to roll the fix out progressively rather than blocking on a full audit, starting with this PR ? I can open a follow-up issue to track checking the other operators for the same compute-time accounting bug.

@ulrichurriola-parada-ops I think it makes sense to create an issue explainging your findings and then create focused PR's. I'd be happy to review them feel free to ping me

I just created the issue: #24459
Thank you

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

Labels

physical-plan Changes to the physical-plan crate

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants