Skip to content

Commit d628e4b

Browse files
HappenLeeCopilot
HappenLee
and
Copilot
authored
[improvement](be) Restructure OLAP scan profile timers into tree hierarchy (apache#62717)
 Problem Summary: The OLAP scanner profile timers were registered as a flat list, making it hard to understand parent-child timing relationships. This change: 1. Converts all relevant timers to use ADD_CHILD_TIMER so the profile renders as a tree reflecting actual call containment: - ReaderInitTime → TabletReaderInitTimer → (TabletReader* + BlockReader* sub-timers) - ScannerGetBlockTime → RowsetReaderGetSegmentIteratorsTimer → (DeleteBitmapGetAggTime, RowsetReaderCreateIteratorsTimer) - ScannerGetBlockTime → BlockFetchTime → SegmentIteratorInitTimer → (SegmentIterator* + Segment* sub-timers) 2. Fixes TabletReaderInitTimer inaccuracy: removes the SCOPED_RAW_TIMER wrapper in TabletReader::init() (which double-counted overhead) and instead computes the value as the sum of its sub-timers in olap_scanner.cpp. 3. Adds missing COUNTER_UPDATE for SegmentIteratorInitSegmentPrefetchersTimer which was tracked in stats but never reported to the profile. ### Release note Profile timers for OLAP scanner are now displayed as a tree hierarchy showing containment relationships between init and scan phases. ### Check List (For Author) - Test: Manual test (profile structure verified via code review) - No functional behavior changed, only profile display structure - Behavior changed: No - Does this need documentation: No --------- Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent 5c56cfd commit d628e4b

8 files changed

Lines changed: 92 additions & 46 deletions

File tree

‎be/src/exec/operator/olap_scan_operator.cpp‎

Lines changed: 49 additions & 39 deletions
Original file line numberDiff line numberDiff line change
@@ -135,8 +135,7 @@ Status OlapScanLocalState::_init_profile() {
135135
ADD_COUNTER(_segment_profile, "UncompressedBytesRead", TUnit::BYTES);
136136
_block_load_timer = ADD_TIMER(_segment_profile, "BlockLoadTime");
137137
_block_load_counter = ADD_COUNTER(_segment_profile, "BlocksLoad", TUnit::UNIT);
138-
_block_fetch_timer = ADD_TIMER(_scanner_profile, "BlockFetchTime");
139-
_delete_bitmap_get_agg_timer = ADD_TIMER(_scanner_profile, "DeleteBitmapGetAggTime");
138+
_block_fetch_timer = ADD_CHILD_TIMER(_scanner_profile, "BlockFetchTime", "ScannerGetBlockTime");
140139
if (config::is_cloud_mode()) {
141140
static const char* sync_rowset_timer_name = "SyncRowsetTime";
142141
_sync_rowset_timer = ADD_TIMER(_scanner_profile, sync_rowset_timer_name);
@@ -274,46 +273,57 @@ Status OlapScanLocalState::_init_profile() {
274273
_total_segment_counter = ADD_COUNTER(_segment_profile, "NumSegmentTotal", TUnit::UNIT);
275274
_tablet_counter = ADD_COUNTER(custom_profile(), "TabletNum", TUnit::UNIT);
276275
_key_range_counter = ADD_COUNTER(custom_profile(), "KeyRangesNum", TUnit::UNIT);
277-
_tablet_reader_init_timer = ADD_TIMER(_scanner_profile, "TabletReaderInitTimer");
278-
_tablet_reader_capture_rs_readers_timer =
279-
ADD_TIMER(_scanner_profile, "TabletReaderCaptureRsReadersTimer");
280-
_tablet_reader_init_return_columns_timer =
281-
ADD_TIMER(_scanner_profile, "TabletReaderInitReturnColumnsTimer");
282-
_tablet_reader_init_keys_param_timer =
283-
ADD_TIMER(_scanner_profile, "TabletReaderInitKeysParamTimer");
284-
_tablet_reader_init_orderby_keys_param_timer =
285-
ADD_TIMER(_scanner_profile, "TabletReaderInitOrderbyKeysParamTimer");
286-
_tablet_reader_init_conditions_param_timer =
287-
ADD_TIMER(_scanner_profile, "TabletReaderInitConditionsParamTimer");
288-
_tablet_reader_init_delete_condition_param_timer =
289-
ADD_TIMER(_scanner_profile, "TabletReaderInitDeleteConditionParamTimer");
290-
_block_reader_vcollect_iter_init_timer =
291-
ADD_TIMER(_scanner_profile, "BlockReaderVcollectIterInitTimer");
292-
_block_reader_rs_readers_init_timer =
293-
ADD_TIMER(_scanner_profile, "BlockReaderRsReadersInitTimer");
294-
_block_reader_build_heap_init_timer =
295-
ADD_TIMER(_scanner_profile, "BlockReaderBuildHeapInitTimer");
296-
297-
_rowset_reader_get_segment_iterators_timer =
298-
ADD_TIMER(_scanner_profile, "RowsetReaderGetSegmentIteratorsTimer");
276+
_tablet_reader_init_timer =
277+
ADD_CHILD_TIMER(_scanner_profile, "TabletReaderInitTimer", "ReaderInitTime");
278+
_tablet_reader_capture_rs_readers_timer = ADD_CHILD_TIMER(
279+
_scanner_profile, "TabletReaderCaptureRsReadersTimer", "TabletReaderInitTimer");
280+
_tablet_reader_init_return_columns_timer = ADD_CHILD_TIMER(
281+
_scanner_profile, "TabletReaderInitReturnColumnsTimer", "TabletReaderInitTimer");
282+
_tablet_reader_init_keys_param_timer = ADD_CHILD_TIMER(
283+
_scanner_profile, "TabletReaderInitKeysParamTimer", "TabletReaderInitTimer");
284+
_tablet_reader_init_orderby_keys_param_timer = ADD_CHILD_TIMER(
285+
_scanner_profile, "TabletReaderInitOrderbyKeysParamTimer", "TabletReaderInitTimer");
286+
_tablet_reader_init_conditions_param_timer = ADD_CHILD_TIMER(
287+
_scanner_profile, "TabletReaderInitConditionsParamTimer", "TabletReaderInitTimer");
288+
_tablet_reader_init_delete_condition_param_timer = ADD_CHILD_TIMER(
289+
_scanner_profile, "TabletReaderInitDeleteConditionParamTimer", "TabletReaderInitTimer");
290+
_block_reader_vcollect_iter_init_timer = ADD_CHILD_TIMER(
291+
_scanner_profile, "BlockReaderVcollectIterInitTimer", "TabletReaderInitTimer");
292+
_block_reader_rs_readers_init_timer = ADD_CHILD_TIMER(
293+
_scanner_profile, "BlockReaderRsReadersInitTimer", "TabletReaderInitTimer");
294+
_block_reader_build_heap_init_timer = ADD_CHILD_TIMER(
295+
_scanner_profile, "BlockReaderBuildHeapInitTimer", "TabletReaderInitTimer");
296+
297+
_rowset_reader_get_segment_iterators_timer = ADD_CHILD_TIMER(
298+
_scanner_profile, "RowsetReaderGetSegmentIteratorsTimer", "ScannerGetBlockTime");
299+
_delete_bitmap_get_agg_timer = ADD_CHILD_TIMER(_scanner_profile, "DeleteBitmapGetAggTime",
300+
"RowsetReaderGetSegmentIteratorsTimer");
299301
_rowset_reader_create_iterators_timer =
300-
ADD_TIMER(_scanner_profile, "RowsetReaderCreateIteratorsTimer");
301-
_rowset_reader_init_iterators_timer =
302-
ADD_TIMER(_scanner_profile, "RowsetReaderInitIteratorsTimer");
303-
_rowset_reader_load_segments_timer =
304-
ADD_TIMER(_scanner_profile, "RowsetReaderLoadSegmentsTimer");
305-
306-
_segment_iterator_init_timer = ADD_TIMER(_scanner_profile, "SegmentIteratorInitTimer");
302+
ADD_CHILD_TIMER(_scanner_profile, "RowsetReaderCreateIteratorsTimer",
303+
"RowsetReaderGetSegmentIteratorsTimer");
304+
_rowset_reader_init_iterators_timer = ADD_CHILD_TIMER(
305+
_scanner_profile, "RowsetReaderInitIteratorsTimer", "ScannerGetBlockTime");
306+
_rowset_reader_load_segments_timer = ADD_CHILD_TIMER(
307+
_scanner_profile, "RowsetReaderLoadSegmentsTimer", "ScannerGetBlockTime");
308+
309+
_segment_iterator_init_timer =
310+
ADD_CHILD_TIMER(_scanner_profile, "SegmentIteratorInitTimer", "BlockFetchTime");
307311
_segment_iterator_init_return_column_iterators_timer =
308-
ADD_TIMER(_scanner_profile, "SegmentIteratorInitReturnColumnIteratorsTimer");
309-
_segment_iterator_init_index_iterators_timer =
310-
ADD_TIMER(_scanner_profile, "SegmentIteratorInitIndexIteratorsTimer");
312+
ADD_CHILD_TIMER(_scanner_profile, "SegmentIteratorInitReturnColumnIteratorsTimer",
313+
"SegmentIteratorInitTimer");
314+
_segment_iterator_init_index_iterators_timer = ADD_CHILD_TIMER(
315+
_scanner_profile, "SegmentIteratorInitIndexIteratorsTimer", "SegmentIteratorInitTimer");
311316
_segment_iterator_init_segment_prefetchers_timer =
312-
ADD_TIMER(_scanner_profile, "SegmentIteratorInitSegmentPrefetchersTimer");
313-
314-
_segment_create_column_readers_timer =
315-
ADD_TIMER(_scanner_profile, "SegmentCreateColumnReadersTimer");
316-
_segment_load_index_timer = ADD_TIMER(_scanner_profile, "SegmentLoadIndexTimer");
317+
ADD_CHILD_TIMER(_scanner_profile, "SegmentIteratorInitSegmentPrefetchersTimer",
318+
"SegmentIteratorInitTimer");
319+
320+
// These two timers span both iterator init and later lazy segment init paths,
321+
// so their nearest stable ancestor is ScannerGetBlockTime instead of any
322+
// narrower SegmentIterator/BlockFetch subphase.
323+
_segment_create_column_readers_timer = ADD_CHILD_TIMER(
324+
_scanner_profile, "SegmentCreateColumnReadersTimer", "ScannerGetBlockTime");
325+
_segment_load_index_timer =
326+
ADD_CHILD_TIMER(_scanner_profile, "SegmentLoadIndexTimer", "ScannerGetBlockTime");
317327

318328
_index_filter_profile = std::make_unique<RuntimeProfile>("IndexFilter");
319329
_scanner_profile->add_child(_index_filter_profile.get(), true, nullptr);

‎be/src/exec/scan/olap_scanner.cpp‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -126,7 +126,7 @@ static std::string read_columns_to_string(TabletSchemaSPtr tablet_schema,
126126
return read_columns_string;
127127
}
128128

129-
Status OlapScanner::prepare() {
129+
Status OlapScanner::_prepare_impl() {
130130
auto* local_state = static_cast<OlapScanLocalState*>(_local_state);
131131
auto& tablet = _tablet_reader_params.tablet;
132132
auto& tablet_schema = _tablet_reader_params.tablet_schema;
@@ -881,6 +881,8 @@ void OlapScanner::_collect_profile_before_close() {
881881
stats.segment_iterator_init_return_column_iterators_timer_ns);
882882
COUNTER_UPDATE(local_state->_segment_iterator_init_index_iterators_timer,
883883
stats.segment_iterator_init_index_iterators_timer_ns);
884+
COUNTER_UPDATE(local_state->_segment_iterator_init_segment_prefetchers_timer,
885+
stats.segment_iterator_init_segment_prefetchers_timer_ns);
884886

885887
COUNTER_UPDATE(local_state->_segment_create_column_readers_timer,
886888
stats.segment_create_column_readers_timer_ns);

‎be/src/exec/scan/olap_scanner.h‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -69,7 +69,7 @@ class OlapScanner : public Scanner {
6969

7070
OlapScanner(ScanLocalStateBase* parent, Params&& params);
7171

72-
Status prepare() override;
72+
Status _prepare_impl() override;
7373

7474
Status _open_impl(RuntimeState* state) override;
7575

‎be/src/exec/scan/scanner.h‎

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -71,13 +71,15 @@ class Scanner {
7171
}
7272

7373
virtual Status init(RuntimeState* state, const VExprContextSPtrs& conjuncts);
74-
virtual Status prepare() {
75-
_has_prepared = true;
76-
return Status::OK();
74+
Status prepare() {
75+
SCOPED_RAW_TIMER(&_per_scanner_timer);
76+
SCOPED_RAW_TIMER(&_per_scanner_prepare_timer);
77+
return _prepare_impl();
7778
}
7879

7980
Status open(RuntimeState* state) {
8081
SCOPED_RAW_TIMER(&_per_scanner_timer);
82+
SCOPED_RAW_TIMER(&_per_scanner_open_timer);
8183
return _open_impl(state);
8284
}
8385

@@ -96,6 +98,11 @@ class Scanner {
9698
virtual std::string get_current_scan_range_name() { return "not implemented"; }
9799

98100
protected:
101+
virtual Status _prepare_impl() {
102+
_has_prepared = true;
103+
return Status::OK();
104+
}
105+
99106
virtual Status _open_impl(RuntimeState* state) {
100107
_block_avg_bytes = state->batch_size() * 8;
101108
return Status::OK();
@@ -153,6 +160,8 @@ class Scanner {
153160
start_wait_worker_timer();
154161
}
155162
int64_t get_time_cost_ns() const { return _per_scanner_timer; }
163+
int64_t get_prepare_time_cost_ns() const { return _per_scanner_prepare_timer; }
164+
int64_t get_open_time_cost_ns() const { return _per_scanner_open_timer; }
156165

157166
int64_t projection_time() const { return _projection_timer; }
158167
int64_t get_rows_read() const { return _num_rows_read; }
@@ -260,6 +269,8 @@ class Scanner {
260269

261270
ScannerCounter _counter;
262271
int64_t _per_scanner_timer = 0;
272+
int64_t _per_scanner_prepare_timer = 0;
273+
int64_t _per_scanner_open_timer = 0;
263274
int64_t _projection_timer = 0;
264275

265276
bool _should_stop = false;

‎be/src/exec/scan/scanner_context.cpp‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -490,10 +490,14 @@ void ScannerContext::stop_scanners(RuntimeState* state) {
490490
std::stringstream scanner_rows_read;
491491
std::stringstream scanner_wait_worker_time;
492492
std::stringstream scanner_projection;
493+
std::stringstream scanner_prepare_time;
494+
std::stringstream scanner_open_time;
493495
scanner_statistics << "[";
494496
scanner_rows_read << "[";
495497
scanner_wait_worker_time << "[";
496498
scanner_projection << "[";
499+
scanner_prepare_time << "[";
500+
scanner_open_time << "[";
497501
// Scanners can in 3 state
498502
// state 1: in scanner context, not scheduled
499503
// state 2: in scanner worker pool's queue, scheduled but not running
@@ -517,17 +521,28 @@ void ScannerContext::stop_scanners(RuntimeState* state) {
517521
<< PrettyPrinter::print(scanner->_scanner->get_scanner_wait_worker_timer(),
518522
TUnit::TIME_NS)
519523
<< ", ";
524+
scanner_prepare_time << PrettyPrinter::print(
525+
scanner->_scanner->get_prepare_time_cost_ns(),
526+
TUnit::TIME_NS)
527+
<< ", ";
528+
scanner_open_time << PrettyPrinter::print(scanner->_scanner->get_open_time_cost_ns(),
529+
TUnit::TIME_NS)
530+
<< ", ";
520531
// since there are all scanners, some scanners is running, so that could not call scanner
521532
// close here.
522533
}
523534
scanner_statistics << "]";
524535
scanner_rows_read << "]";
525536
scanner_wait_worker_time << "]";
526537
scanner_projection << "]";
538+
scanner_prepare_time << "]";
539+
scanner_open_time << "]";
527540
_scanner_profile->add_info_string("PerScannerRunningTime", scanner_statistics.str());
528541
_scanner_profile->add_info_string("PerScannerRowsRead", scanner_rows_read.str());
529542
_scanner_profile->add_info_string("PerScannerWaitTime", scanner_wait_worker_time.str());
530543
_scanner_profile->add_info_string("PerScannerProjectionTime", scanner_projection.str());
544+
_scanner_profile->add_info_string("PerScannerPrepareTime", scanner_prepare_time.str());
545+
_scanner_profile->add_info_string("PerScannerOpenTime", scanner_open_time.str());
531546
}
532547
}
533548

‎be/src/storage/iterator/block_reader.cpp‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -205,6 +205,7 @@ Status BlockReader::_init_agg_state(const ReaderParams& read_params) {
205205
}
206206

207207
Status BlockReader::init(const ReaderParams& read_params) {
208+
SCOPED_RAW_TIMER(&_stats.tablet_reader_init_timer_ns);
208209
RETURN_IF_ERROR(TabletReader::init(read_params));
209210

210211
auto return_column_size = read_params.origin_return_columns->size();

‎be/src/storage/segment/segment_loader.cpp‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -56,12 +56,17 @@ Status SegmentLoader::load_segment(const BetaRowsetSharedPtr& rowset, int64_t se
5656
SegmentCacheHandle* cache_handle, bool use_cache,
5757
bool need_load_pk_index_and_bf,
5858
OlapReaderStatistics* index_load_stats) {
59+
auto start = MonotonicMicros();
5960
SegmentCache::CacheKey cache_key(rowset->rowset_id(), segment_id);
6061
if (_segment_cache->lookup(cache_key, cache_handle)) {
6162
// Has to check the segment status here, because the segment in cache may has something wrong during
6263
// load index or create column reader.
6364
// Not merge this if logic with previous to make the logic more clear.
6465
if (cache_handle->pop_unhealthy_segment() == nullptr) {
66+
if (index_load_stats != nullptr) {
67+
index_load_stats->rowset_reader_load_segments_timer_ns +=
68+
(MonotonicMicros() - start) * 1000;
69+
}
6570
return Status::OK();
6671
}
6772
}
@@ -79,6 +84,10 @@ Status SegmentLoader::load_segment(const BetaRowsetSharedPtr& rowset, int64_t se
7984
} else {
8085
cache_handle->push_segment(std::move(segment));
8186
}
87+
if (index_load_stats != nullptr) {
88+
index_load_stats->rowset_reader_load_segments_timer_ns +=
89+
(MonotonicMicros() - start) * 1000;
90+
}
8291

8392
return Status::OK();
8493
}

‎be/src/storage/tablet/tablet_reader.cpp‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -67,8 +67,6 @@ void TabletReader::ReaderParams::check_validation() const {
6767
}
6868

6969
Status TabletReader::init(const ReaderParams& read_params) {
70-
SCOPED_RAW_TIMER(&_stats.tablet_reader_init_timer_ns);
71-
7270
Status res = _init_params(read_params);
7371
if (!res.ok()) {
7472
LOG(WARNING) << "fail to init reader when init params. res:" << res

0 commit comments

Comments
 (0)