This is an automated email from the ASF dual-hosted git repository.
yiguolei 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 6221a673341 [fix](spill) Record the spill read deserialize timer
(#67041)
6221a673341 is described below
commit 6221a6733412e8a4f63b2843eff97bd5316ce7f6
Author: Xiangyi Zhu <[email protected]>
AuthorDate: Mon Aug 24 14:21:23 2026 +0800
[fix](spill) Record the spill read deserialize timer (#67041)
### What problem does this PR solve?
Issue Number: close #67040
Problem Summary:
`SpillReadDeserializeBlockTime` is always `0` in query profiles — the
time spent deserializing spilled blocks has never been recorded.
The counter is registered by `SpillReadCounters::init` under the shared
constant `profile::SPILL_READ_DESERIALIZE_BLOCK_TIME`, whose value is
`"SpillReadDeserializeBlockTime"`:
```cpp
// be/src/exec/operator/spill_counters.h
spill_read_deserialize_block_timer =
ADD_TIMER_WITH_LEVEL(profile,
profile::SPILL_READ_DESERIALIZE_BLOCK_TIME, 1);
```
But `SpillFileReader` looked it up with a hand-written 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.
**Why existing tests did not catch it:** `spill_file_test.cpp` and
`spill_repartitioner_test.cpp` registered the counters by hand and
copied the same misspelling, so the reader's lookup resolved in tests
while returning null in a real query.
Changes:
1. `SpillFileReader` now resolves every read counter through the
`profile::` name constants instead of string literals, and `DCHECK`s
that each one resolves, so a future rename fails loudly instead of
silently dropping a counter.
2. The unit tests reuse `SpillWriteCounters::init` /
`SpillReadCounters::init` rather than re-listing the names, so the
registered names and units cannot drift from production again.
3. `spillable_operator_test_helper` registered `SpillReadFileTime` and
`SpillReadDeserializeBlockTime` as `TUnit::UNIT` instead of timers. That
was harmless while the timer resolved to null, but trips the
`DCHECK_EQ(counter->type(), TUnit::TIME_NS)` inside `ScopedTimer` once
it resolves, so it is corrected by the same reuse.
### Release note
Fix `SpillReadDeserializeBlockTime` always being 0 in query profiles.
### Check List (For Author)
- Test
- [x] Unit Test
Added `SpillFileTest.ReadDeserializeTimerIsRecorded`, which 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 | 27 ++++---
.../operator/spillable_operator_test_helper.cpp | 37 ++++-----
be/test/vec/spill/spill_file_test.cpp | 90 +++++++++++++++++-----
be/test/vec/spill/spill_repartitioner_test.cpp | 35 ++++-----
4 files changed, 120 insertions(+), 69 deletions(-)
diff --git a/be/src/exec/spill/spill_file_reader.cpp
b/be/src/exec/spill/spill_file_reader.cpp
index 7c6107e4a3e..736064d720b 100644
--- a/be/src/exec/spill/spill_file_reader.cpp
+++ b/be/src/exec/spill/spill_file_reader.cpp
@@ -30,6 +30,7 @@
#include "io/fs/local_file_system.h"
#include "runtime/exec_env.h"
#include "runtime/query_context.h"
+#include "runtime/runtime_profile_counter_names.h"
#include "runtime/runtime_state.h"
#include "util/debug_points.h"
#include "util/slice.h"
@@ -43,16 +44,24 @@ SpillFileReader::SpillFileReader(RuntimeState* state,
RuntimeProfile* profile,
: _spill_dir(std::move(spill_dir)),
_part_count(part_count),
_resource_ctx(state->get_query_ctx()->resource_ctx()) {
- // Internalize counter setup
- RuntimeProfile* custom_profile = profile->get_child("CustomCounters");
+ // Internalize counter setup. The counters themselves are registered by
the owning
+ // operator (SpillReadCounters::init), so look them up by the shared name
constants:
+ // a literal that drifts from the constant silently yields a null counter,
which
+ // turns every SCOPED_TIMER/COUNTER_UPDATE on it into a no-op.
+ RuntimeProfile* custom_profile =
profile->get_child(profile::CUSTOM_COUNTERS);
DCHECK(custom_profile != nullptr);
- _read_file_timer = custom_profile->get_counter("SpillReadFileTime");
- _deserialize_timer =
custom_profile->get_counter("SpillReadDerializeBlockTime");
- _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");
- _read_rows_count = custom_profile->get_counter("SpillReadRows");
- _read_file_count = custom_profile->get_counter("SpillReadFileCount");
+ auto get_counter = [&](const char* name) {
+ auto* counter = custom_profile->get_counter(name);
+ DCHECK(counter != nullptr) << "spill read counter is not registered: "
<< name;
+ return counter;
+ };
+ _read_file_timer = get_counter(profile::SPILL_READ_FILE_TIME);
+ _deserialize_timer =
get_counter(profile::SPILL_READ_DESERIALIZE_BLOCK_TIME);
+ _read_block_count = get_counter(profile::SPILL_READ_BLOCK_COUNT);
+ _read_block_data_size = get_counter(profile::SPILL_READ_BLOCK_BYTES);
+ _read_file_size = get_counter(profile::SPILL_READ_FILE_BYTES);
+ _read_rows_count = get_counter(profile::SPILL_READ_ROWS);
+ _read_file_count = get_counter(profile::SPILL_READ_FILE_COUNT);
}
Status SpillFileReader::open() {
diff --git a/be/test/exec/operator/spillable_operator_test_helper.cpp
b/be/test/exec/operator/spillable_operator_test_helper.cpp
index dd39a8aa6b3..72bbc0bca43 100644
--- a/be/test/exec/operator/spillable_operator_test_helper.cpp
+++ b/be/test/exec/operator/spillable_operator_test_helper.cpp
@@ -28,6 +28,7 @@
#include <memory>
#include <vector>
+#include "exec/operator/spill_counters.h"
#include "io/fs/local_file_system.h"
#include "testutil/creators.h"
@@ -42,26 +43,22 @@ void SpillableOperatorTestHelper::SetUp() {
ADD_COUNTER_WITH_LEVEL(common_profile.get(), "MemoryUsage", TUnit::BYTES,
1);
ADD_TIMER_WITH_LEVEL(common_profile.get(), "ExecTime", 1);
- ADD_TIMER_WITH_LEVEL(custom_profile.get(), "SpillTotalTime", 1);
- ADD_TIMER_WITH_LEVEL(custom_profile.get(), "SpillWriteTime", 1);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(),
"SpillWriteTaskWaitInQueueCount", TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillWriteTaskCount",
TUnit::UNIT, 1);
- ADD_TIMER_WITH_LEVEL(custom_profile.get(),
"SpillWriteTaskWaitInQueueTime", 1);
- ADD_TIMER_WITH_LEVEL(custom_profile.get(), "SpillWriteFileTime", 1);
- ADD_TIMER_WITH_LEVEL(custom_profile.get(), "SpillWriteSerializeBlockTime",
1);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillWriteBlockCount",
TUnit::UNIT, 1);
- 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);
- 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);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillReadRows", TUnit::UNIT,
1);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillReadFileCount",
TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillWriteFileTotalCount",
TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(custom_profile.get(), "SpillWriteFileCurrentBytes",
TUnit::UNIT, 1);
+
+ // Reuse the production initializers so both the names and the TUnit of
every spill
+ // counter match what SpillFileReader/SpillFileWriter expect. Registering
a timer as
+ // TUnit::UNIT by hand trips the DCHECK inside ScopedTimer.
+ SpillWriteCounters write_counters;
+ write_counters.init(custom_profile.get());
+ SpillReadCounters read_counters;
+ read_counters.init(custom_profile.get());
+
+ // Source-only extras, see
PipelineXSpillLocalState::init_spill_{write,read}_counters.
+ ADD_TIMER_WITH_LEVEL(custom_profile.get(), profile::SPILL_TOTAL_TIME, 1);
+ ADD_COUNTER_WITH_LEVEL(custom_profile.get(),
profile::SPILL_WRITE_FILE_BYTES, TUnit::BYTES, 1);
+ ADD_COUNTER_WITH_LEVEL(custom_profile.get(),
profile::SPILL_WRITE_FILE_TOTAL_COUNT, TUnit::UNIT,
+ 1);
+ ADD_COUNTER_WITH_LEVEL(custom_profile.get(),
profile::SPILL_WRITE_FILE_CURRENT_BYTES,
+ TUnit::BYTES, 1);
operator_profile->add_child(custom_profile.get(), true);
operator_profile->add_child(common_profile.get(), true);
diff --git a/be/test/vec/spill/spill_file_test.cpp
b/be/test/vec/spill/spill_file_test.cpp
index 9df4bf626f3..c4d4f140635 100644
--- a/be/test/vec/spill/spill_file_test.cpp
+++ b/be/test/vec/spill/spill_file_test.cpp
@@ -32,6 +32,7 @@
#include "core/block/block.h"
#include "core/data_type/data_type_number.h"
#include "core/data_type/data_type_string.h"
+#include "exec/operator/spill_counters.h"
#include "exec/pipeline/pipeline_fragment_context.h"
#include "exec/spill/spill_file_manager.h"
#include "exec/spill/spill_file_reader.h"
@@ -62,27 +63,24 @@ protected:
_common_profile->AddHighWaterMarkCounter("MemoryUsage", TUnit::BYTES,
"", 1);
ADD_TIMER_WITH_LEVEL(_common_profile.get(), "ExecTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillTotalTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillWriteTime", 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteTaskWaitInQueueCount", TUnit::UNIT,
+ // Register exactly what PipelineXSpillLocalState registers in
production, by
+ // reusing the same initializers. Hand-copying the counter names here
is what let
+ // a misspelled lookup in SpillFileReader
("SpillReadDerializeBlockTime") go
+ // unnoticed: the test registered the same misspelling, so the lookup
"worked"
+ // here while silently returning null in a real query.
+ SpillWriteCounters write_counters;
+ write_counters.init(_custom_profile.get());
+ SpillReadCounters read_counters;
+ read_counters.init(_custom_profile.get());
+
+ // Source-only extras, see
PipelineXSpillLocalState::init_spill_{write,read}_counters.
+ ADD_TIMER_WITH_LEVEL(_custom_profile.get(), profile::SPILL_TOTAL_TIME,
1);
+ ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
profile::SPILL_WRITE_FILE_BYTES, TUnit::BYTES,
1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillWriteTaskCount",
TUnit::UNIT, 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteTaskWaitInQueueTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillWriteFileTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteSerializeBlockTime", 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillWriteBlockCount",
TUnit::UNIT, 1);
- 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_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillReadFileTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillReadDerializeBlockTime", 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);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadRows",
TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadFileCount",
TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteFileTotalCount", TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteFileCurrentBytes", TUnit::UNIT, 1);
+ ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
profile::SPILL_WRITE_FILE_TOTAL_COUNT,
+ TUnit::UNIT, 1);
+ ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
profile::SPILL_WRITE_FILE_CURRENT_BYTES,
+ TUnit::BYTES, 1);
_profile->add_child(_custom_profile.get(), true);
_profile->add_child(_common_profile.get(), true);
@@ -1541,6 +1539,58 @@ 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 by SpillReadCounters::init under the canonical
name and
+ // must still be untouched before any read happens.
+ auto* deserialize_timer =
+
_custom_profile->get_counter(profile::SPILL_READ_DESERIALIZE_BLOCK_TIME);
+ ASSERT_TRUE(deserialize_timer != nullptr)
+ << "counter name drifted from " <<
profile::SPILL_READ_DESERIALIZE_BLOCK_TIME;
+ 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 01da4719cad..f6fa6de73e3 100644
--- a/be/test/vec/spill/spill_repartitioner_test.cpp
+++ b/be/test/vec/spill/spill_repartitioner_test.cpp
@@ -25,6 +25,7 @@
#include "core/block/block.h"
#include "core/data_type/data_type_number.h"
+#include "exec/operator/spill_counters.h"
#include "exec/partitioner/partitioner.h"
#include "exec/spill/spill_file.h"
#include "exec/spill/spill_file_manager.h"
@@ -54,27 +55,21 @@ protected:
_common_profile->AddHighWaterMarkCounter("MemoryUsage", TUnit::BYTES,
"", 1);
ADD_TIMER_WITH_LEVEL(_common_profile.get(), "ExecTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillTotalTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillWriteTime", 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteTaskWaitInQueueCount", TUnit::UNIT,
+ // Reuse the production initializers so the registered names cannot
drift from
+ // what SpillFileReader/SpillFileWriter look up.
+ SpillWriteCounters write_counters;
+ write_counters.init(_custom_profile.get());
+ SpillReadCounters read_counters;
+ read_counters.init(_custom_profile.get());
+
+ // Source-only extras, see
PipelineXSpillLocalState::init_spill_{write,read}_counters.
+ ADD_TIMER_WITH_LEVEL(_custom_profile.get(), profile::SPILL_TOTAL_TIME,
1);
+ ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
profile::SPILL_WRITE_FILE_BYTES, TUnit::BYTES,
1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillWriteTaskCount",
TUnit::UNIT, 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteTaskWaitInQueueTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillWriteFileTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteSerializeBlockTime", 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillWriteBlockCount",
TUnit::UNIT, 1);
- 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_TIMER_WITH_LEVEL(_custom_profile.get(), "SpillReadFileTime", 1);
- ADD_TIMER_WITH_LEVEL(_custom_profile.get(),
"SpillReadDerializeBlockTime", 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);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadRows",
TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(), "SpillReadFileCount",
TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteFileTotalCount", TUnit::UNIT, 1);
- ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
"SpillWriteFileCurrentBytes", TUnit::UNIT, 1);
+ ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
profile::SPILL_WRITE_FILE_TOTAL_COUNT,
+ TUnit::UNIT, 1);
+ ADD_COUNTER_WITH_LEVEL(_custom_profile.get(),
profile::SPILL_WRITE_FILE_CURRENT_BYTES,
+ TUnit::BYTES, 1);
_profile->add_child(_custom_profile.get(), true);
_profile->add_child(_common_profile.get(), true);
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
