This is an automated email from the ASF dual-hosted git repository.
morningman pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/doris.git
The following commit(s) were added to refs/heads/master by this push:
new c560d936d6e [fix](be) Count the materialization push time once (#69579)
c560d936d6e is described below
commit c560d936d6e934b69bbf4fc38ae4f49abb745022
Author: Mingyu Chen (Rayner) <[email protected]>
AuthorDate: Mon Oct 26 07:01:51 2026 +0000
[fix](be) Count the materialization push time once (#69579)
### What problem does this PR solve?
Issue Number: None
Related PR: #68690
Problem Summary:
**In short.** This ports the materialization timing fix of branch-4.1
#68690 to master. `MaterializationOperator::push` timed itself with the
same `ExecTime` counter that the operator framework already uses around
every `push()`, so the operator's `ExecTime` counted each push twice,
including the synchronous row-fetch RPC wait. `push()` no longer opens
its own timer.
Original author: @Gabriel39
**Background.** `MaterializationOperator` is the second phase of TopN
lazy materialization: it collects row IDs from its child and fetches the
remaining columns from the backends that own the rows, waiting for the
fetch RPCs inside `push()`. It is a `StatefulOperatorX`, and
`StatefulOperatorX::get_block_impl` already wraps every `push()` and
`pull()` in `SCOPED_TIMER(local_state.exec_time_counter())`.
**The problem, and what it cost.** `MaterializationOperator::push`
opened a second `SCOPED_TIMER(local_state.exec_time_counter())`. Both
timers add their elapsed time to the same counter when they go out of
scope, so the time of every push was added twice. Since the row-fetch
RPC wait happens inside `push()`, the profile reported a materialization
`ExecTime` up to twice the real time, which points at the wrong operator
when a TopN lazy materialization query is slow. Only the profile is
affected; results and the fetch itself are not.
**How this PR fixes it.** `push()` drops its own timer and leaves the
`ExecTime` sample to the framework, with a comment explaining why.
`pull()` never had the nested timer. #68690 also adds Lance row-fetch
counters and a Lance query parallelism option; those belong to the Lance
work and are not part of this PR.
**Results.**
| | `ExecTime` of one push |
|---|---|
| Before | counted twice (framework timer + the nested one in `push()`)
|
| After | counted once, by the framework |
Co-authored-by: Gabriel <[email protected]>
---
be/src/exec/operator/materialization_opertor.cpp | 3 +-
.../operator/materialization_shared_state_test.cpp | 41 ++++++++++++++++++++++
2 files changed, 43 insertions(+), 1 deletion(-)
diff --git a/be/src/exec/operator/materialization_opertor.cpp
b/be/src/exec/operator/materialization_opertor.cpp
index f8871c533c5..2c1ef6956a5 100644
--- a/be/src/exec/operator/materialization_opertor.cpp
+++ b/be/src/exec/operator/materialization_opertor.cpp
@@ -606,7 +606,8 @@ Status MaterializationOperator::pull(RuntimeState* state,
Block* output_block, b
Status MaterializationOperator::push(RuntimeState* state, Block* in_block,
bool eos) const {
auto& local_state = get_local_state(state);
- SCOPED_TIMER(local_state.exec_time_counter());
+ // StatefulOperatorX::get_block_impl already times push() with this
counter.
+ // Nesting the same timer counts the synchronous row-fetch RPC wait twice.
if (!local_state._materialization_state.rpc_struct_inited) {
RETURN_IF_ERROR(local_state._materialization_state.init_multi_requests(
_materialization_node, state));
diff --git a/be/test/exec/operator/materialization_shared_state_test.cpp
b/be/test/exec/operator/materialization_shared_state_test.cpp
index fb3c31493a6..0da15f792e9 100644
--- a/be/test/exec/operator/materialization_shared_state_test.cpp
+++ b/be/test/exec/operator/materialization_shared_state_test.cpp
@@ -24,6 +24,7 @@
#include "exec/operator/materialization_opertor.h"
#include "exec/pipeline/dependency.h"
#include "runtime/runtime_profile.h"
+#include "testutil/mock/mock_runtime_state.h"
namespace doris {
@@ -36,6 +37,46 @@ void add_request_row(PRequestBlockDesc* request_block_desc,
uint32_t row_id, uin
} // namespace
+TEST(MaterializationOperatorTimingTest,
PushDoesNotDuplicateFrameworkExecTimer) {
+ ObjectPool pool;
+ MockRuntimeState state;
+ // Even an empty-block timing test needs a real tuple: OperatorXBase builds
+ // a RowDescriptor from the plan and requires non-empty, resolvable tuple
IDs.
+ TTupleDescriptor tuple;
+ tuple.__set_id(0);
+ TDescriptorTable thrift_desc;
+ thrift_desc.__set_tupleDescriptors({tuple});
+ DescriptorTbl* desc_tbl = nullptr;
+ ASSERT_TRUE(DescriptorTbl::create(&pool, thrift_desc, &desc_tbl).ok());
+ state.set_desc_tbl(desc_tbl);
+
+ TPlanNode node;
+ node.__set_node_id(0);
+ node.__set_node_type(TPlanNodeType::MATERIALIZATION_NODE);
+ node.__set_row_tuples({0});
+ node.__set_nullable_tuples({false});
+ MaterializationOperator op(&pool, node, 0, state.desc_tbl());
+ RuntimeProfile profile("materialization_timing");
+ auto local = MaterializationLocalState::create_unique(&state, &op);
+ LocalStateInfo info {.parent_profile = &profile,
+ .scan_ranges = {},
+ .shared_state = nullptr,
+ .shared_state_map = {},
+ .task_idx = 0};
+ ASSERT_TRUE(local->init(&state, info).ok());
+ local->_materialization_state.rpc_struct_inited = true;
+ auto* timer = local->exec_time_counter();
+ state.resize_op_id_to_local_state(-1);
+ state.emplace_local_state(0, std::move(local));
+ Block block;
+ const auto before = timer->value();
+ // The framework owns ExecTime. Direct push calls must not contribute a
second sample.
+ for (int i = 0; i < 100; ++i) {
+ ASSERT_TRUE(op.push(&state, &block, false).ok());
+ }
+ EXPECT_EQ(before, timer->value());
+}
+
class MaterializationSharedStateTest : public testing::Test {
protected:
void SetUp() override {
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
