parquet: Add finer metrics on operations covered by time_elapsed_opening
#12585
Conversation
As it does not measure evaluation of row group-level pushdown filters
github-actions
bot
added
documentation
progval
changed the title
time_elapsed_openingtime_elapsed_opening
progval
force-pushed
the
opener-metrics-pr
branch
from
ea09cf7
to
b9b7156
Compare
| @@ -43,14 +43,20 @@ pub struct ParquetFileMetrics { | |||
| pub pushdown_rows_pruned: Count, | |||
| /// Total rows passed predicates pushed into parquet scan | |||
| pub pushdown_rows_matched: Count, | |||
| /// Total time spent evaluating pushdown filters | |||
| pub pushdown_eval_time: Time, | |||
| /// Total time spent evaluating row-level pushdown filters | |||
There was a problem hiding this comment.
As an aside while I am reviewing this code, the description of what the metrics mean would be more useful if we could attach them to the Metric itself somehow 🤔
Something like:
let row_pushdown_eval_time = MetricBuilder::new(metrics)
.with_description("Total time spent evaluating row-level pushdown filters")
.with_new_label("filename", filename.to_string())
.subset_time("row_pushdown_eval_time", partition);Though then we would have to figure out how to expose that information in an explain plan 🤔
|
|
||
| if enable_bloom_filter && !row_groups.is_empty() { | ||
| let mut timer = file_metrics.bloom_filter_eval_time.timer(); |
There was a problem hiding this comment.
I note that the time calculation for page_index_eval_time below seems to be in the call to
access_plan = p.prune_plan_with_page_index(
access_plan,
&file_schema,
builder.parquet_schema(),
file_metadata.as_ref(),
&file_metrics,
);I wonder if we should move the timer into this function for consistency (or alternatively push the timer calculation into prune_by_bloom_filters and prune_by_statistics)
There was a problem hiding this comment.
Good point. I did the latter, because it's probably closer to what users expect.
| row_groups.prune_by_statistics( | ||
| &file_schema, | ||
| builder.parquet_schema(), | ||
| rg_metadata, | ||
| predicate, | ||
| &file_metrics, | ||
| ); | ||
| timer.stop(); |
There was a problem hiding this comment.
I don't think it is a problem, but technically speaking the stop() is unecessary (it happens automatically when timer goes out of scope and is Droped
There was a problem hiding this comment.
This one is needed, because it only goes out of scope after the Bloom Filter evaluation. The next timer.stop() is indeed redundant, but I kept it for consistency.
There was a problem hiding this comment.
Doesn't matter anymore, as I moved both calls to the callees.
|
Thanks again @progval |
…ning` (apache#12585) * Rename 'pushdown_eval_time' to 'row_pushdown_eval_time' As it does not measure evaluation of row group-level pushdown filters * Add statistics_eval_time and bloom_filter_eval_time metrics * Add metadata_load_time metric * Add docs * Move timers to the callees
Which issue does this PR close?
Closes #12584.
Rationale for this change
This allows both Datafusion developers and users to better measure the impact of their optimizations. For example, I am working on #12547 (caching the page index), and my patch makes these metrics go from:
to
which shows it reduced
metadata_load_timeandtime_elapsed_openingwith little impact to the others.What changes are included in this PR?
metadata_load_timestatistics_eval_timeandbloom_filter_eval_timepushdown_eval_timetorow_pushdown_eval_time, because statistics and eval time are pushdown filters tooAre these changes tested?
Not really. There is no unit tests, but it works in datafusion-cli and as a library
Are there any user-facing changes?
Renamed a metric, and added two others, visible in
EXPLAIN ANALYZE.