This is an automated email from the ASF dual-hosted git repository.
yiguolei pushed a commit to branch branch-4.1
in repository https://gitbox.apache.org/repos/asf/doris.git
The following commit(s) were added to refs/heads/branch-4.1 by this push:
new 972d0c8b0ae branch-4.1: [fix](spill) Record the spill read deserialize
timer #67041 (#67059)
972d0c8b0ae is described below
commit 972d0c8b0aee52779394d2cb25fe6980d8b387ce
Author: Xiangyi Zhu <[email protected]>
AuthorDate: Tue Aug 25 10:40:29 2026 +0800
branch-4.1: [fix](spill) Record the spill read deserialize timer #67041
(#67059)
### What problem does this PR solve?
Issue Number: close #67040
Related PR: #67041
Problem Summary:
Cherry-picked from #67041. The automatic pick failed with conflicts in
the three test files, so this is a manual backport.
`SpillReadDeserializeBlockTime` is always `0` in query profiles on
branch-4.1 — the time spent deserializing spilled blocks is never
recorded.
`PipelineXSpillLocalState` registers the counter as
`"SpillReadDeserializeBlockTime"` (`be/src/exec/operator/operator.h`),
but `SpillFileReader` looked it up with a literal that is missing an
`s`:
```cpp
// be/src/exec/spill/spill_file_reader.cpp
_deserialize_timer =
custom_profile->get_counter("SpillReadDerializeBlockTime");
// ^^^ Derialize
```
`get_counter()` returns `nullptr` for the unknown name and `ScopedTimer`
returns early on a null counter, so `SCOPED_TIMER(_deserialize_timer)`
in `SpillFileReader::read()` silently measures nothing.
**Difference from the master PR:** #67041 resolves every spill read
counter through the shared `profile::` name constants, but
`be/src/runtime/runtime_profile_counter_names.h` does not exist on
branch-4.1. This backport therefore keeps the minimal spelling fix
rather than porting the constant refactor — that is also what caused the
automatic cherry-pick conflict.
Changes:
1. `SpillFileReader` looks the counter up under the name the operator
actually registers.
2. `spill_file_test.cpp` and `spill_repartitioner_test.cpp` registered
the same misspelling by hand, which is why the gap went unnoticed: the
reader's lookup matched in tests while returning null in a real query.
They now register the canonical name.
3. `spillable_operator_test_helper` registered `SpillReadFileTime` and
`SpillReadDeserializeBlockTime` as `TUnit::UNIT`. That stayed harmless
only while the deserialize lookup resolved to null; once it resolves,
`SCOPED_TIMER`'s `DCHECK_EQ(counter->type(), TUnit::TIME_NS)` would
fire, so both are registered as timers.
### Release note
Fix `SpillReadDeserializeBlockTime` always being 0 in query profiles.
### Check List (For Author)
- Test
- [x] Unit Test
Ported `SpillFileTest.ReadDeserializeTimerIsRecorded` from #67041. It
fails before
this change: with the test registering the canonical name, the reader's
misspelled
lookup yields a null counter and the timer stays at 0 after a real read.
The test
also asserts the misspelled name is absent, so it cannot be
reintroduced.
- Behavior changed:
- [x] No.
Profile-only fix. The counter already existed and was already reported;
it was
simply never updated. No counter is added, removed, or renamed.
- Does this need documentation?
- [x] No.
---
be/src/exec/spill/spill_file_reader.cpp | 2 +-
.../operator/spillable_operator_test_helper.cpp | 7 ++-
be/test/vec/spill/spill_file_test.cpp | 52 +++++++++++++++++++++-
be/test/vec/spill/spill_repartitioner_test.cpp | 2 +-
4 files changed, 58 insertions(+), 5 deletions(-)
diff --git a/be/src/exec/spill/spill_file_reader.cpp
b/be/src/exec/spill/spill_file_reader.cpp
index 50609d93f42..a0c00266e52 100644
--- a/be/src/exec/spill/spill_file_reader.cpp
+++ b/be/src/exec/spill/spill_file_reader.cpp
@@ -48,7 +48,7 @@ SpillFileReader::SpillFileReader(RuntimeState* state,
RuntimeProfile* profile,
RuntimeProfile* custom_profile = profile->get_child("CustomCounters");
DCHECK(custom_profile != nullptr);
_read_file_timer = custom_profile->get_counter("SpillReadFileTime");
- _deserialize_timer =
custom_profile->get_counter("SpillReadDerializeBlockTime");
+ _deserialize_timer =
custom_profile->get_counter("SpillReadDeserializeBlockTime");
_read_block_count = custom_profile->get_counter("SpillReadBlockCount");
_read_block_data_size = custom_profile->get_counter("SpillReadBlockBytes");
_read_file_size = custom_profile->get_counter("SpillReadFileBytes");
diff --git a/be/test/exec/operator/spillable_operator_test_helper.cpp
b/be/test/exec/operator/spillable_operator_test_helper.cpp
index fb87b156545..57d7eaa438c 100644
--- a/be/test/exec/operator/spillable_operator_test_helper.cpp
+++ b/be/test/exec/operator/spillable_operator_test_helper.cpp
@@ -52,8 +52,11 @@ void SpillableOperatorTestHelper::SetUp() {
ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillWriteBlockBytes",
TUnit::BYTES, 1);
ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillWriteFileBytes",
TUnit::BYTES, 1);
ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillWriteRows",
TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillReadFileTime",
TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(),
"SpillReadDeserializeBlockTime", TUnit::UNIT, 1);
+ // Both are consumed through SCOPED_TIMER in SpillFileReader, which
DCHECKs the counter
+ // is TUnit::TIME_NS. Registering them as plain UNIT counters only stayed
harmless while
+ // the deserialize lookup was misspelled and resolved to null.
+ ADD_TIMER_WITH_LEVEL(custom_profile.get(), "SpillReadFileTime", 1);
+ ADD_TIMER_WITH_LEVEL(custom_profile.get(),
"SpillReadDeserializeBlockTime", 1);
ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillReadBlockCount",
TUnit::UNIT, 1);
ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillReadBlockBytes",
TUnit::UNIT, 1);
ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillReadFileBytes",
TUnit::UNIT, 1);
diff --git a/be/test/vec/spill/spill_file_test.cpp
b/be/test/vec/spill/spill_file_test.cpp
index 11b16df1712..286a056c3cf 100644
--- a/be/test/vec/spill/spill_file_test.cpp
+++ b/be/test/vec/spill/spill_file_test.cpp
@@ -73,7 +73,7 @@ protected:
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillWriteFileBytes",
TUnit::BYTES, 1);
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillWriteRows",
TUnit::UNIT, 1);
ADD_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillReadFileTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillReadDerializeBlockTime", 1);
+ ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillReadDeserializeBlockTime", 1);
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadBlockCount",
TUnit::UNIT, 1);
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadBlockBytes",
TUnit::UNIT, 1);
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadFileBytes",
TUnit::UNIT, 1);
@@ -1451,6 +1451,56 @@ TEST_F(SpillFileTest, ReadCounters) {
ASSERT_GT(read_file_size->value(), 0);
}
+// Regression test: SpillFileReader used to look up the deserialize timer
under a
+// misspelled name ("SpillReadDerializeBlockTime"), so get_counter() returned
null and
+// SCOPED_TIMER silently recorded nothing. The counter stayed at 0 in every
profile.
+TEST_F(SpillFileTest, ReadDeserializeTimerIsRecorded) {
+ SpillFileSPtr spill_file;
+ auto st = ExecEnv::GetInstance()->spill_file_mgr()->create_spill_file(
+ "test_query/read_deserialize_timer", spill_file);
+ ASSERT_TRUE(st.ok());
+
+ {
+ SpillFileWriterSPtr writer;
+ st = spill_file->create_writer(_runtime_state.get(), _profile.get(),
writer);
+ ASSERT_TRUE(st.ok());
+
+ auto block = _create_int_block({1, 2, 3, 4, 5});
+ st = writer->write_block(_runtime_state.get(), block);
+ ASSERT_TRUE(st.ok());
+
+ st = writer->close();
+ ASSERT_TRUE(st.ok());
+ }
+
+ // The timer is registered under the canonical name and must still be
untouched
+ // before any read happens.
+ auto* deserialize_timer =
_custom_profile->get_counter("SpillReadDeserializeBlockTime");
+ ASSERT_TRUE(deserialize_timer != nullptr);
+ ASSERT_EQ(deserialize_timer->value(), 0);
+
+ auto reader = spill_file->create_reader(_runtime_state.get(),
_profile.get());
+ st = reader->open();
+ ASSERT_TRUE(st.ok());
+
+ Block block;
+ bool eos = false;
+ st = reader->read(&block, &eos);
+ ASSERT_TRUE(st.ok());
+ ASSERT_EQ(block.rows(), 5);
+
+ st = reader->close();
+ ASSERT_TRUE(st.ok());
+
+ // Deserializing a real block must land on the canonical counter. This is
0 whenever
+ // the reader's lookup name does not match what the operator registered.
+ ASSERT_GT(deserialize_timer->value(), 0);
+
+ // The misspelled name must not exist: if it reappears, some caller
registered it and
+ // the two spellings will drift apart again.
+ ASSERT_TRUE(_custom_profile->get_counter("SpillReadDerializeBlockTime") ==
nullptr);
+}
+
// ═══════════════════════════════════════════════════════════════════════
// SpillDataDir tests
// ═══════════════════════════════════════════════════════════════════════
diff --git a/be/test/vec/spill/spill_repartitioner_test.cpp
b/be/test/vec/spill/spill_repartitioner_test.cpp
index 53ffcf9f0ac..b630c0d8920 100644
--- a/be/test/vec/spill/spill_repartitioner_test.cpp
+++ b/be/test/vec/spill/spill_repartitioner_test.cpp
@@ -67,7 +67,7 @@ protected:
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillWriteFileBytes",
TUnit::BYTES, 1);
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillWriteRows",
TUnit::UNIT, 1);
ADD_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillReadFileTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillReadDerializeBlockTime", 1);
+ ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillReadDeserializeBlockTime", 1);
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadBlockCount",
TUnit::UNIT, 1);
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadBlockBytes",
TUnit::UNIT, 1);
ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadFileBytes",
TUnit::UNIT, 1);
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
