fix: avoid double-counting build_time in HashJoinExec elapsed_compute - #24142
Conversation
BuildProbeJoinMetrics derives Clone and previously ran its elapsed_compute update from a Drop impl on itself. HashJoinExec::execute() clones this struct into the build-side future (collect_left_input) while the original is kept by HashJoinStream, so there are always two live instances for a CollectLeft/Partitioned join, and Drop fired once per instance. Since build_time/join_time are Arc<AtomicUsize>-backed and shared between clones, the clone dropped at build-completion time re-added whatever build_time had already accumulated (via ScopedTimerGuard flushing on every Pending poll) into elapsed_compute. The original then added the same build_time again at the end, plus join_time - inflating elapsed_compute by up to build_time on any hash join whose build side yields control before completing. Move the elapsed_compute update into a new ElapsedComputeFinalizer, held behind an Arc on BuildProbeJoinMetrics. Cloning the outer struct now only bumps the Arc's refcount instead of creating a second independent Drop, so the update runs exactly once, when the last clone is dropped, using the fully-accumulated final values. Added a regression test that reproduces the clone/drop sequence directly and asserts elapsed_compute == build_time + join_time exactly.
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #24142 +/- ##
========================================
Coverage 81.04% 81.05%
========================================
Files 1105 1106 +1
Lines 380163 380591 +428
Branches 380163 380591 +428
========================================
+ Hits 308111 308495 +384
- Misses 53834 53874 +40
- Partials 18218 18222 +4 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
kosiew
left a comment
There was a problem hiding this comment.
Thanks for working on this. The change looks good to me. Moving elapsed_compute finalization behind a shared Arc addresses the double-counting issue cleanly, and the regression test does a good job of covering the ownership behavior.
I left one non-blocking suggestion for an additional execution-level regression test that could make this even more robust.
| } | ||
|
|
||
| #[test] | ||
| fn build_probe_join_metrics_elapsed_compute_not_double_counted_on_clone() { |
There was a problem hiding this comment.
Nice regression test. One additional test that might be worth considering is an execution-level HashJoinExec test where the build stream yields before completing. This unit test covers the shared-finalizer ownership behavior well, while an execution-level test would also exercise the HashJoinExec::execute clone and future wiring that originally exposed the issue. Not blocking for this PR.
There was a problem hiding this comment.
Thank you for the review,I'll make a follow-up for the additional test.
Rationale for this change
HashJoinExec'selapsed_computemetric (visible viaEXPLAIN ANALYZE,.metrics(), and any tooling built on top of them) overstates the actual compute time for the join, sometimes substantially (observed a +47% higher thanbuild_time + join_timecombined, even thoughelapsed_computeis documented/expected to equal exactly that sum). This misleads anyone using the metric to diagnose slow joins or to attribute CPU time within a query plan.What changes are included in this PR?
BuildProbeJoinMetricsderivesCloneand previously updatedelapsed_computefrom its ownDropimpl.HashJoinExec::execute()clones this struct into the build-side future (collect_left_input) while the original is kept byHashJoinStream, so two instances exist for the lifetime of a join, andDropfired once per instance — double-countingbuild_timewhenever the build side yields control (e.g. returnsPending) at least once before completing, which is the common case for anything other than an already-materialized, single-batch build side.This PR moves the
elapsed_computeupdate into a newElapsedComputeFinalizer, held behind anArconBuildProbeJoinMetrics. Cloning the outer struct now only bumps theArc's reference count instead of creating a second independentDrop, so the update runs exactly once — when the last clone is dropped — using the fully-accumulated final values ofbuild_timeandjoin_time.Are these changes tested?
Yes. Added
build_probe_join_metrics_elapsed_compute_not_double_counted_on_clone, which reproduces the clone/drop sequence directly (without needing a full hash join) and assertselapsed_compute == build_time + join_timeexactly.Ran the full existing
joins::test module (cargo test -p datafusion-physical-plan --lib joins::): 1023 passed, 0 failed, no regressions.Are there any user-facing changes?
HashJoinExec'selapsed_computemetric will report lower (correct) values than before for any join whose build side isn't already fully materialized in a single poll — most visible inEXPLAIN ANALYZEoutput and any plan-visualization tooling built on DataFusion's metrics. No public API changes;BuildProbeJoinMetricsis a private (pub(crate)) type.