Repository navigation
[fix](be) Correct the external row fetch InitReaderAvgTime and GetBlockAvgTime - #69583
Open
morningman wants to merge 1 commit into
Open
morningman wants to merge 1 commit into
morningman wants to merge 1 commit into
Conversation
…ckAvgTime ### What problem does this PR solve? Issue Number: None Related PR: apache#67005 Problem Summary: The second phase of TopN lazy materialization on an external table (RowIdStorageReader::read_batch_external_row) reads each scan range of a request block with its own reader and reports two profile values per request block: InitReaderAvgTime and GetBlockAvgTime, the mean reader-init and block-read time over those ranges. MaterializationOperator lists them per backend in the query profile. Both are wrong on master: - InitReaderAvgTime assigns each range's init time instead of adding it, so it reports the last range's time divided by the number of ranges: ranges that took 10, 20 and 60 ms give 20 ms instead of 30 ms. - GetBlockAvgTime is filled with the init-time average, so the block-read time never reaches the profile. - The averages are accumulated in the caller's variables, which read_by_rowids() zeroes once per RPC and passes to every request block. When an RPC fetches two lazily materialized external tables, the second block's sums start from the first block's averages. branch-4.1/4.2 fixed the first two in apache#67005 (a Lance profile PR) by summing the init times and reporting the get-block average, but kept the shared accumulators, so a second request block reports inflated averages there: 46ms and 466ms instead of 30ms and 300ms in the unit test below once the first block left 50 and 500 ms. The summary now lives in RowIdStorageReader::add_external_fetch_avg_time_profile(). It sums both times over the block's ranges from zero, overwrites the caller's variables with the averages and reports each average under its own key. The "Query stats" log line at the end of read_by_rowids() therefore prints the averages of the RPC's last external request block, the same block whose scan range count it already prints. ### Release note None ### Check List (For Author) - Test: Unit Test - BE UT RowIdStorageReaderTest.ExternalFetchProfileAveragesInitAndGetBlockTimes: three ranges (10/100, 20/200, 60/600 ms) with the caller's variables preset to 50/500 ms by a previous request block give 30ms and 300ms. - Behavior changed: No - Does this need documentation: No Co-authored-by: zhangstar333 <zhangsida@selectdb.com> Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Contributor
|
Thank you for your contribution to Apache Doris. Please clearly describe your PR:
|
Contributor
Author
|
run buildall |
Contributor
Author
|
/review |
![github-actions[bot]](https://avatars.githubusercontent.com/in/15368?s=60&v=4){kind=small}
Contributor
There was a problem hiding this comment.
No actionable new findings in the three-file PR at ec36f8f. The external row-fetch profile now reports independent reader-init and block-read means for each request block, without carrying an earlier block's values into the next. No existing inline findings require carry-forward, and no additional user focus was supplied.
Critical checkpoint conclusions:
- Goal and proof: fresh sums, overwritten outputs and distinct profile values address all three reported defects. The added three-range unit case checks 30ms/300ms from preset 50ms/500ms outputs; assessed statically.
- Scope and clarity: a small private helper, a forward declaration and a focused unit test; comments explain the averaging and overwrite semantics with examples.
- Concurrency and locks: scanner workers write distinct pre-sized statistics entries; the completion mutex/CV publishes their writes before aggregation. Error statuses bypass profiling. No new lock or blocking operation is introduced.
- Lifecycle and static initialization: the helper borrows live per-call objects after worker completion and retains nothing; no new owner, cycle, callback or global initialization.
- Configuration: no configuration changes.
- Compatibility: existing profile keys, millisecond representation and wire/storage formats remain compatible. No new libc API, library or toolchain requirement is introduced; no artifact ABI audit was performed.
- Thrift/protobuf definitions: no changes.
- Parallel paths: both FileScanner and FileScannerV2 populate the common millisecond statistics consumed by this helper; internal-table reading is unaffected.
- Preconditions and comments: the nonempty assertion follows from the request's nonempty row-ID gate and unconditional range grouping; missing mappings return an error before profiling.
- Test coverage: the deterministic unit case covers multiple ranges, distinct init/read values, prior-block output contamination and both profile strings. Scanner/RPC integration and scheduler cancellation stress were inspected in source, not executed.
- Test expectations and build integration: numeric/string expectations are correct; existing BE-UT flags permit private access and its CMake glob includes the test. No expected-result files changed; the test includes no source .cpp requiring unity exclusion.
- Observability: both repaired values reach each response block's protobuf profile and materialization consumer under the intended keys. The RPC log consistently shows its last external block's averages and range count.
- Transactions and persistence: no commit, visibility-version, delete-bitmap, edit-log or persistence behavior changes.
- Data writes and atomicity: no writes or result-scatter changes; the patch changes post-read profiling.
- FE-BE variables: no new transmitted variables or sending paths.
- Performance and memory: one linear pass over existing range statistics, constant auxiliary space and no added per-range allocation or I/O; no actionable regression found.
- Other checks: header hygiene, exception/status propagation, nullable/COW scope and profile serialization were reviewed without an additional issue.
Review scope and convergence: all changed lines and relevant upstream/downstream paths received main-agent and complete-reviewer static coverage, with a separate risk review for range cardinality and worker publication. The unchanged scheduler shutdown behavior was considered and yielded no defect introduced by this patch; this is not a full scheduler teardown audit. No builds, tests, runtime stress runs or artifact checks were executed under the review-only contract. No unresolved PR candidates or static coverage gaps remain. Converged after 2 rounds, including final confirmation of this frozen payload.
Review converged after 2 round(s).
Contributor
TPC-H: Total hot run time: 28384 ms |
Contributor
TPC-DS: Total hot run time: 150610 ms |
Contributor
ClickBench: Total hot run time: 24.32 s |
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.
What problem does this PR solve?
Issue Number: None
Related PR: #67005
Problem Summary:
In short. This ports the profile fix that branch-4.1/4.2 made in #67005 to master: the second phase of TopN lazy materialization on external tables reported a wrong
InitReaderAvgTimeand put the init time intoGetBlockAvgTime. It also stops one request block's averages from leaking into the next one of the same RPC, which the 4.x fix still does.Original author: @zhangstar333
Background. When a TopN query lazily materializes an external table, the second phase sends the row IDs to the backends that own the rows. On each backend,
RowIdStorageReader::read_batch_external_rowreads one request block (one table) by grouping its row IDs per scan range and reading each range with its own reader. It then reports two values per request block:InitReaderAvgTimeandGetBlockAvgTime, the mean reader-init and block-read time over those ranges.MaterializationOperatorlists them per backend in the query profile, one value per RPC response block.The problem, and what it cost. Both values are wrong on master:
InitReaderAvgTimeassigns each range's init time instead of adding it, so it is the last range's init time divided by the number of ranges.GetBlockAvgTimeis filled with the init-time average, so the block-read time never reaches the profile.read_by_rowids()zeroes once per RPC and passes to every request block. A query that lazily materializes two external tables sends two request blocks in one RPC, and the second block's sums start from the first block's averages.So the profile of a slow lazily materialized external read cannot tell whether opening the readers or reading the rows took the time. Only the profile and one log line are affected; the fetched rows are not. #67005 (a Lance profile PR in 4.x) fixed the first two points; branch-4.1 and branch-4.2 still have the third.
How this PR fixes it. The summary moves into
RowIdStorageReader::add_external_fetch_avg_time_profile(). It sums both times over the block's ranges starting from zero, overwrites the caller's variables with the averages, and reports each average under its own key. TheQuery statslog line at the end ofread_by_rowids()prints those variables, so it now shows the averages of the RPC's last external request block, the same block whose scan range count it already prints.Results.
InitReaderAvgTime / GetBlockAvgTimefor a request block with three ranges that took 10/100, 20/200 and 60/600 ms (init/read), first as the only external block of the RPC, then as the second one after a block that left 50/500 ms in the shared variables:Release note
None
Check List (For Author)
RowIdStorageReaderTest.ExternalFetchProfileAveragesInitAndGetBlockTimes: the three ranges above, with the caller's variables preset to 50/500 ms as a previous request block would leave them, give 30ms and 300ms. It fails with master's assignment (20ms), withGetBlockAvgTimereporting the init average (30ms), and with the 4.x accumulation (46ms / 466ms). The otherRowIdStorageReaderTestandSubmitExternalScanTasksTestcases still pass.Check List (For Reviewer who merge this PR)