fix: count Parquet decoding in the scan's elapsed_compute - #25486
Open
akashjainn wants to merge 1 commit into
Open
akashjainn wants to merge 1 commit into
akashjainn wants to merge 1 commit into
Conversation
The elapsed_compute timer added in apache#20767 covers projection and metrics copying but starts after reader.next() has returned, so decoding is not counted and a full scan reports a fraction of a millisecond of compute. Run one timer for the whole push decoder transition and pause it only while fetching byte ranges, which is I/O. Part of apache#18195
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #25486 +/- ##
=======================================
Coverage 82.36% 82.36%
=======================================
Files 1137 1137
Lines 432962 433027 +65
Branches 432962 433027 +65
=======================================
+ Hits 356610 356667 +57
- Misses 54825 54827 +2
- Partials 21527 21533 +6 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
jayzhan211
approved these changes
Sep 19, 2026
jayzhan211
left a comment
Contributor
There was a problem hiding this comment.
Thanks @akashjainn, make sense to me
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Which issue does this PR close?
DataSourceExecwithParquetsource #18195. This is the last unchecked item, "Fixelapsed_computebaseline metrics not counting issue".Rationale for this change
EXPLAIN ANALYZEreports anelapsed_computefor a Parquet scan that is far too small. For a single-partitionSELECT *over a 1M row file, the scan takes about 155 ms and reports about 0.1 ms of compute, so the metric is useless for telling whether a query is bound by the scan.#20767 added an
elapsed_computetimer inPushDecoderStreamState::transition, but it wrapscopy_arrow_reader_metricsandproject_batchonly. The decoding happens before the timer starts (intry_decodeat the time of that PR, inreader.next()today), so the metric went from a few nanoseconds to a fraction of a millisecond and is still missing where the time goes. The CSV fix in #18901 timesreader.next(), and this PR does the equivalent for Parquet.What changes are included in this PR?
PushDecoderStreamState::transitionnow runs one timer for the whole transition and pauses it only acrossget_byte_ranges(...).await. Everything else in the loop is CPU work: decoding inreader.next(), row group pruning and decoder rebuilds at row group boundaries,try_next_reader,push_rangesand the projection. That matches the guidance in the issue to count metadata handling and payload decoding.On the overhead concern raised on #20767: there is still one timer start per batch, as there is today. The only additional timer operations are a stop and a restart around each byte range fetch, which happens per row group rather than per batch.
The timer is created from a clone of the
Timemetric, which shares the underlying counter, so the guard does not borrowselfacross the&mut selfcalls in the loop. It records when it is dropped, which covers every return.What is the testing strategy for this PR?
New test
parquet_scan_elapsed_compute_includes_decodingindatafusion/core/tests/sql/explain_analyze.rs. It writes a 1M row Parquet file, scans it with one target partition so the scan runs on one thread, and asserts that the scan'selapsed_computeis at least a quarter of the wall time of the scan. The existing tests only assert thatelapsed_computeis greater than zero, which a timer that misses decoding still satisfies. This is also an answer to the question on #20767 of whether the metric can be tested: comparing against wall time measured in the same run avoids depending on machine speed.Measured locally in a debug build, three runs each, within 1% of each other:
elapsed_computeThe test fails on main and passes with this change, and it passed five consecutive runs. The threshold of a quarter leaves a wide margin on both sides, and because it compares against wall time measured in the same run it does not depend on machine speed.
Is the new number right? Two checks, done with a throwaway test that is not part of this PR, on the same 1M row file:
ParquetRecordBatchReaderBuilderat a batch size of 8192, with no DataFusion involved, took 145 to 148 ms over three runs. The scan'selapsed_computewith this change was 145 to 147 ms.InMemorystore wrapped in object_store'sThrottledStore, which sleeps on every get:elapsed_computeTripling the delay adds 200 ms of wall time and leaves
elapsed_computeunchanged. The step from 149 to 167 ms is CPU time and not a leak of I/O wait: wall time minus the injected delay is about 171 to 174 ms in those runs, so the work itself was slower once the thread had gone idle.The metric also scales with the work: 500k rows report 77 ms against 147 ms for 1M, a single
Int64column reports 38 ms, and a single string column 76 ms. In every caseelapsed_computestayed below the wall time, by 0.5 to 5 ms.Also run locally:
cargo fmt --all -- --check,cargo clippy --all-targets --all-features -- -D warningsfordatafusion-datasource-parquetand for thecore_integrationtest target,cargo test -p datafusion-datasource-parquet(267 passed), thesql::explain_analyzetests (30 passed) and theparquet_integrationtests (242 passed).Are there any user-facing changes?
elapsed_computefor Parquet scans inEXPLAIN ANALYZEbecomes much larger, because it now includes decoding. No API changes.