ARROW-11052: [Rust] [DataFusion] Implement metrics for HashJoinExec #9035

andygrove · 2020-12-28T20:47:48Z

Implement metrics for HashJoinExec to help debug performance issues.

Example output:

[2020-12-28T20:46:28Z DEBUG datafusion::physical_plan::hash_join] Built build-side of hash join containing 3115341 rows in 9926 ms
[2020-12-28T20:46:36Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 388922 rows in 7994 ms
[2020-12-28T20:46:36Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 389294 rows in 7986 ms
[2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 389558 rows in 8326 ms
[2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 388841 rows in 8499 ms
[2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 390056 rows in 8643 ms
[2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18749999 rows and produced 144 output batches containing 389143 rows in 8711 ms
[2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 389605 rows in 8712 ms
[2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 389922 rows in 8877 ms

andygrove · 2020-12-28T20:48:25Z

@jorgecarleitao fyi

github-actions · 2020-12-28T20:55:32Z

https://issues.apache.org/jira/browse/ARROW-11052

Dandandan · 2020-12-28T21:04:39Z

rust/datafusion/src/physical_plan/hash_join.rs

+                }
+                other => {
+                    debug!(
+                        "Processed {} probe-side input batches containing {} rows and \


Maybe we can make this a bit less verbose? Processed {} rows probe-side and {} output rows in {} ms or something like that?

Dandandan · 2020-12-28T21:21:02Z

rust/datafusion/src/physical_plan/hash_join.rs

@@ -186,8 +190,18 @@ impl ExecutionPlan for HashJoinExec {
                        })
                        .await?;

+                    let num_rows: usize =
+                        left_data.1.iter().map(|batch| batch.num_rows()).sum();


Maybe we want to put this behind a flag so we don't do this in the macro so we don't compute the num_rows when not being logged?

Dandandan · 2020-12-28T21:40:50Z

rust/datafusion/src/physical_plan/hash_join.rs

+                    self.num_input_rows += batch.num_rows();
+                    match result {
+                        Ok(ref batch) => {
+                            self.join_time += start.elapsed().as_millis() as usize;


We could avoid rounding errors by using start.elapsed().as_secs_f64() store join_time var as f64 and format with 0 digits afterwards.

andygrove · 2020-12-30T17:04:31Z

I will rebase this and address feedback once #9048 is merged

alamb · 2020-12-31T13:18:28Z

The full set of Rust CI tests did not run on this PR :(

Can you please rebase this PR against apache/master to pick up the changes in #9056 so that they do?

I apologize for the inconvenience.

jorgecarleitao

LGTM @andygrove

jorgecarleitao · 2021-01-02T08:57:23Z

@Dandandan , Thanks a lot for the review. I am approving because even though I consider most of your comments relevant, I do not consider them blocking the merge.

For example, summing the number of rows of all batches is O(number_of_batches) and negligible when compared to the time it takes to execute the join, thus being too minor to block this.

Dandandan · 2021-01-02T09:20:31Z

I agree, feel free to address the remaining feedback or to merge it @andygrove👍

codecov-io · 2021-01-02T18:57:04Z

Codecov Report

Merging #9035 (36b0ebd) into master (4b7cdcb) will decrease coverage by 0.02%.
The diff coverage is 55.55%.

@@            Coverage Diff             @@
##           master    #9035      +/-   ##
==========================================
- Coverage   82.61%   82.59%   -0.03%     
==========================================
  Files         203      204       +1     
  Lines       50140    50169      +29     
==========================================
+ Hits        41422    41435      +13     
- Misses       8718     8734      +16

Impacted Files	Coverage Δ
rust/datafusion/src/physical_plan/hash_join.rs	`86.32% <55.55%> (-3.21%)`	⬇️
rust/arrow/src/csv/writer.rs	`78.82% <0.00%> (-0.56%)`	⬇️
rust/parquet/src/encodings/encoding.rs	`95.24% <0.00%> (-0.20%)`	⬇️
rust/arrow/src/util/serialization.rs	`100.00% <0.00%> (ø)`

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 4b7cdcb...36b0ebd. Read the comment docs.

Implement metrics for `HashJoinExec` to help debug performance issues. Example output: ``` [2020-12-28T20:46:28Z DEBUG datafusion::physical_plan::hash_join] Built build-side of hash join containing 3115341 rows in 9926 ms [2020-12-28T20:46:36Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 388922 rows in 7994 ms [2020-12-28T20:46:36Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 389294 rows in 7986 ms [2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 389558 rows in 8326 ms [2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 388841 rows in 8499 ms [2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 390056 rows in 8643 ms [2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18749999 rows and produced 144 output batches containing 389143 rows in 8711 ms [2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 389605 rows in 8712 ms [2020-12-28T20:46:37Z DEBUG datafusion::physical_plan::hash_join] Processed 144 probe-side input batches containing 18750000 rows and produced 144 output batches containing 389922 rows in 8877 ms ``` Closes apache#9035 from andygrove/join-metrics Authored-by: Andy Grove <andygrove73@gmail.com> Signed-off-by: Andy Grove <andygrove73@gmail.com>

andygrove requested a review from jorgecarleitao December 28, 2020 20:47

github-actions bot added Component: Rust - DataFusion Component: Rust labels Dec 28, 2020

Dandandan reviewed Dec 28, 2020

View reviewed changes

Dandandan mentioned this pull request Dec 28, 2020

ARROW-11021: [Rust] Update dependencies #9020

Closed

Dandandan reviewed Dec 28, 2020

View reviewed changes

andygrove mentioned this pull request Dec 28, 2020

ARROW-11053: [Rust] [DataFusion] Optimize joins with dynamic capacity for output batches #9036

Closed

jorgecarleitao approved these changes Jan 2, 2021

View reviewed changes

Add metrics to hash join

4b5154a

andygrove force-pushed the join-metrics branch from a6a5b58 to 4b5154a Compare January 2, 2021 18:40

clippy

36b0ebd

andygrove closed this in fc43489 Jan 2, 2021

asfimport mentioned this pull request Jan 2, 2021

[Rust] [DataFusion] Implement metrics in join operator #26968

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ARROW-11052: [Rust] [DataFusion] Implement metrics for HashJoinExec #9035

ARROW-11052: [Rust] [DataFusion] Implement metrics for HashJoinExec #9035

andygrove commented Dec 28, 2020 •

edited

andygrove commented Dec 28, 2020

github-actions bot commented Dec 28, 2020

Dandandan Dec 28, 2020

Dandandan Dec 28, 2020

Dandandan Dec 28, 2020

andygrove commented Dec 30, 2020

alamb commented Dec 31, 2020

jorgecarleitao left a comment

jorgecarleitao commented Jan 2, 2021

Dandandan commented Jan 2, 2021

codecov-io commented Jan 2, 2021 •

edited

ARROW-11052: [Rust] [DataFusion] Implement metrics for HashJoinExec #9035

ARROW-11052: [Rust] [DataFusion] Implement metrics for HashJoinExec #9035

Conversation

andygrove commented Dec 28, 2020 • edited

andygrove commented Dec 28, 2020

github-actions bot commented Dec 28, 2020

Dandandan Dec 28, 2020

Choose a reason for hiding this comment

Dandandan Dec 28, 2020

Choose a reason for hiding this comment

Dandandan Dec 28, 2020

Choose a reason for hiding this comment

andygrove commented Dec 30, 2020

alamb commented Dec 31, 2020

jorgecarleitao left a comment

Choose a reason for hiding this comment

jorgecarleitao commented Jan 2, 2021

Dandandan commented Jan 2, 2021

codecov-io commented Jan 2, 2021 • edited

Codecov Report

andygrove commented Dec 28, 2020 •

edited

codecov-io commented Jan 2, 2021 •

edited