zhuxiangyi opened a new issue, #67040: URL: https://github.com/apache/doris/issues/67040
### Search before asking - [X] I had searched in the [issues](https://github.com/apache/doris/issues?q=is%3Aissue) and found no similar issues. ### Version master, commit 5202d06dd8 ### What's Wrong? `SpillReadDeserializeBlockTime` is always `0` in query profiles. The time spent deserializing spilled blocks has never been recorded for any spill-enabled query. The counter is registered by `SpillReadCounters::init` under the shared name 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); ``` ```cpp // be/src/runtime/runtime_profile_counter_names.h:116 inline constexpr char SPILL_READ_DESERIALIZE_BLOCK_TIME[] = "SpillReadDeserializeBlockTime"; ``` But `SpillFileReader` resolves it with a hand-written literal that is missing an `s`: ```cpp // be/src/exec/spill/spill_file_reader.cpp:50 _deserialize_timer = custom_profile->get_counter("SpillReadDerializeBlockTime"); // ^^^ "Derialize" ``` `get_counter()` returns `nullptr` for the unknown name, and `ScopedTimer` returns early when the counter is null: ```cpp // be/src/runtime/runtime_profile.h:855 ScopedTimer(RuntimeProfile::Counter* counter, const Bool* is_cancelled = nullptr) : _counter(counter), _is_cancelled(is_cancelled) { if (counter == nullptr) { return; } ``` So `SCOPED_TIMER(_deserialize_timer)` in `SpillFileReader::read()` silently measures nothing, and the counter stays at its initial `0`. The same misspelling is also present in two unit tests (`be/test/vec/spill/spill_file_test.cpp`, `be/test/vec/spill/spill_repartitioner_test.cpp`), which register the counters by hand. That is why the gap went unnoticed: the reader's lookup matches in those tests while returning null in a real query. Only this one name is affected — the other 15 `get_counter()` literals under `be/src/exec/spill/` match their constants. ### What You Expected? `SpillReadDeserializeBlockTime` should report the actual time spent in `Block::deserialize()` when reading spilled data back, so that deserialization cost is visible when diagnosing slow spill-enabled queries. ### How to Reproduce? Run any query that spills and reads the data back, then inspect the profile: ```sql set enable_spill = true; set enable_force_spill = true; set enable_profile = true; select l_orderkey, count(*) from lineitem group by l_orderkey; ``` In the resulting profile, under the aggregation source operator's `CustomCounters`, `SpillReadDeserializeBlockTime` reads `0ns` while sibling counters such as `SpillReadFileTime`, `SpillReadBlockCount` and `SpillReadRows` are populated. ### Anything Else? The fix is a one-name change, but it is worth resolving the counters through the shared `profile::` constants rather than repeating string literals, so the same drift cannot recur silently. ### Are you willing to submit PR? - [X] Yes I am willing to submit a PR! ### Code of Conduct - [X] I agree to follow this project's [Code of Conduct](https://www.apache.org/foundation/policies/conduct) -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
