From 4d0bd4ddfff995ea3baedbc18d9fe72c78603e37 Mon Sep 17 00:00:00 2001 From: HappenLee Date: Fri, 27 Dec 2024 17:27:36 +0800 Subject: [PATCH] [Profile](scan) Add profile to detail the scan --- be/src/olap/olap_common.h | 8 ++++++++ be/src/olap/rowset/beta_rowset_reader.cpp | 17 ++++++++++++----- be/src/olap/rowset/segment_v2/segment.cpp | 5 ++++- be/src/vec/exec/scan/new_olap_scan_node.cpp | 11 +++++++++++ be/src/vec/exec/scan/new_olap_scan_node.h | 7 +++++++ be/src/vec/exec/scan/new_olap_scanner.cpp | 10 ++++++++++ be/src/vec/olap/block_reader.h | 1 + 7 files changed, 53 insertions(+), 6 deletions(-) diff --git a/be/src/olap/olap_common.h b/be/src/olap/olap_common.h index 811e77590f98b8..dba6e0ce0f57a8 100644 --- a/be/src/olap/olap_common.h +++ b/be/src/olap/olap_common.h @@ -278,6 +278,8 @@ struct OlapReaderStatistics { int64_t decompress_ns = 0; int64_t uncompressed_bytes_read = 0; + int64_t tablet_read_timer = 0; + // total read bytes in memory int64_t bytes_read = 0; @@ -365,6 +367,12 @@ struct OlapReaderStatistics { int64_t inverted_index_searcher_cache_hit = 0; int64_t inverted_index_searcher_cache_miss = 0; + int64_t rowset_reader_get_segment_iterators_timer_ns = 0; + int64_t rowset_reader_create_iterators_timer_ns = 0; + int64_t rowset_reader_init_iterators_timer_ns = 0; + int64_t rowset_reader_load_segments_timer_ns = 0; + int64_t segment_load_index_timer_ns = 0; + int64_t output_index_result_column_timer = 0; // number of segment filtered by column stat when creating seg iterator int64_t filtered_segment_number = 0; diff --git a/be/src/olap/rowset/beta_rowset_reader.cpp b/be/src/olap/rowset/beta_rowset_reader.cpp index d1f0419987f3db..7b152af9547168 100644 --- a/be/src/olap/rowset/beta_rowset_reader.cpp +++ b/be/src/olap/rowset/beta_rowset_reader.cpp @@ -77,7 +77,6 @@ bool BetaRowsetReader::update_profile(RuntimeProfile* profile) { Status BetaRowsetReader::get_segment_iterators(RowsetReaderContext* read_context, std::vector* out_iters, bool use_cache) { - RETURN_IF_ERROR(_rowset->load()); _read_context = read_context; // The segment iterator is created with its own statistics, // and the member variable '_stats' is initialized by '_stats(&owned_stats)'. @@ -92,6 +91,9 @@ Status BetaRowsetReader::get_segment_iterators(RowsetReaderContext* read_context _stats = _read_context->stats; } + SCOPED_RAW_TIMER(&_stats->rowset_reader_get_segment_iterators_timer_ns); + RETURN_IF_ERROR(_rowset->load()); + // convert RowsetReaderContext to StorageReadOptions _read_options.block_row_max = read_context->batch_size; _read_options.stats = _stats; @@ -218,8 +220,11 @@ Status BetaRowsetReader::get_segment_iterators(RowsetReaderContext* read_context // load segments bool should_use_cache = use_cache || _read_context->reader_type == ReaderType::READER_QUERY; - RETURN_IF_ERROR(SegmentLoader::instance()->load_segments(_rowset, &_segment_cache_handle, - should_use_cache)); + { + SCOPED_RAW_TIMER(&_stats->rowset_reader_load_segments_timer_ns); + RETURN_IF_ERROR(SegmentLoader::instance()->load_segments(_rowset, &_segment_cache_handle, + should_use_cache)); + } // create iterator for each segment auto& segments = _segment_cache_handle.get_segments(); @@ -229,6 +234,7 @@ Status BetaRowsetReader::get_segment_iterators(RowsetReaderContext* read_context seg_end = segments.size(); } + SCOPED_RAW_TIMER(&_stats->rowset_reader_create_iterators_timer_ns); for (int i = seg_start; i < seg_end; i++) { auto& seg_ptr = segments[i]; std::unique_ptr iter; @@ -261,6 +267,7 @@ Status BetaRowsetReader::_init_iterator() { std::vector iterators; RETURN_IF_ERROR(get_segment_iterators(_read_context, &iterators)); + SCOPED_RAW_TIMER(&_stats->rowset_reader_init_iterators_timer_ns); if (_read_context->merged_rows == nullptr) { _read_context->merged_rows = &_merged_rows; } @@ -296,8 +303,8 @@ Status BetaRowsetReader::_init_iterator() { } Status BetaRowsetReader::next_block(vectorized::Block* block) { - SCOPED_RAW_TIMER(&_stats->block_fetch_ns); RETURN_IF_ERROR(_init_iterator_once()); + SCOPED_RAW_TIMER(&_stats->block_fetch_ns); if (_empty) { return Status::Error("BetaRowsetReader is empty"); } @@ -316,8 +323,8 @@ Status BetaRowsetReader::next_block(vectorized::Block* block) { } Status BetaRowsetReader::next_block_view(vectorized::BlockView* block_view) { - SCOPED_RAW_TIMER(&_stats->block_fetch_ns); RETURN_IF_ERROR(_init_iterator_once()); + SCOPED_RAW_TIMER(&_stats->block_fetch_ns); do { auto s = _iterator->next_block_view(block_view); if (!s.ok()) { diff --git a/be/src/olap/rowset/segment_v2/segment.cpp b/be/src/olap/rowset/segment_v2/segment.cpp index 90ab6b45cf6710..bd7fd2169d304d 100644 --- a/be/src/olap/rowset/segment_v2/segment.cpp +++ b/be/src/olap/rowset/segment_v2/segment.cpp @@ -166,7 +166,10 @@ Status Segment::new_iterator(SchemaSPtr schema, const StorageReadOptions& read_o } } - RETURN_IF_ERROR(load_index()); + { + SCOPED_RAW_TIMER(&read_options.stats->segment_load_index_timer_ns); + RETURN_IF_ERROR(load_index()); + } if (read_options.delete_condition_predicates->num_of_column_predicate() == 0 && read_options.push_down_agg_type_opt != TPushAggOp::NONE && read_options.push_down_agg_type_opt != TPushAggOp::COUNT_ON_INDEX) { diff --git a/be/src/vec/exec/scan/new_olap_scan_node.cpp b/be/src/vec/exec/scan/new_olap_scan_node.cpp index 98a2371fa688e7..46b063bb6273af 100644 --- a/be/src/vec/exec/scan/new_olap_scan_node.cpp +++ b/be/src/vec/exec/scan/new_olap_scan_node.cpp @@ -104,6 +104,7 @@ Status NewOlapScanNode::_init_profile() { _block_load_timer = ADD_TIMER(_segment_profile, "BlockLoadTime"); _block_load_counter = ADD_COUNTER(_segment_profile, "BlocksLoad", TUnit::UNIT); _block_fetch_timer = ADD_TIMER(_scanner_profile, "BlockFetchTime"); + _tablet_read_timer = ADD_TIMER(_scanner_profile, "TabletReadTime"); _delete_bitmap_get_agg_timer = ADD_TIMER(_scanner_profile, "DeleteBitmapGetAggTime"); _raw_rows_counter = ADD_COUNTER(_segment_profile, "RawRowsRead", TUnit::UNIT); _block_convert_timer = ADD_TIMER(_scanner_profile, "BlockConvertTime"); @@ -186,6 +187,16 @@ Status NewOlapScanNode::_init_profile() { _inverted_index_searcher_cache_miss_counter = ADD_COUNTER(_segment_profile, "InvertedIndexSearcherCacheMiss", TUnit::UNIT); + _rowset_reader_get_segment_iterators_timer = + ADD_TIMER(_scanner_profile, "RowsetReaderGetSegmentIteratorsTimer"); + _rowset_reader_create_iterators_timer = + ADD_TIMER(_scanner_profile, "RowsetReaderCreateIteratorsTimer"); + _rowset_reader_init_iterators_timer = + ADD_TIMER(_scanner_profile, "RowsetReaderInitIteratorsTimer"); + _rowset_reader_load_segments_timer = + ADD_TIMER(_scanner_profile, "RowsetReaderLoadSegmentsTimer"); + _segment_load_index_timer = ADD_TIMER(_scanner_profile, "SegmentLoadIndexTimer"); + _output_index_result_column_timer = ADD_TIMER(_segment_profile, "OutputIndexResultColumnTimer"); _filtered_segment_counter = ADD_COUNTER(_segment_profile, "NumSegmentFiltered", TUnit::UNIT); diff --git a/be/src/vec/exec/scan/new_olap_scan_node.h b/be/src/vec/exec/scan/new_olap_scan_node.h index a8e0f6dde7eb97..3ae7c0a9c409cb 100644 --- a/be/src/vec/exec/scan/new_olap_scan_node.h +++ b/be/src/vec/exec/scan/new_olap_scan_node.h @@ -142,6 +142,7 @@ class NewOlapScanNode : public VScanNode { RuntimeProfile::Counter* _output_col_timer = nullptr; std::map _filter_info; + RuntimeProfile::Counter* _tablet_read_timer = nullptr; RuntimeProfile::Counter* _stats_filtered_counter = nullptr; RuntimeProfile::Counter* _stats_rp_filtered_counter = nullptr; RuntimeProfile::Counter* _bf_filtered_counter = nullptr; @@ -199,6 +200,12 @@ class NewOlapScanNode : public VScanNode { RuntimeProfile::Counter* _inverted_index_searcher_cache_hit_counter = nullptr; RuntimeProfile::Counter* _inverted_index_searcher_cache_miss_counter = nullptr; + RuntimeProfile::Counter* _rowset_reader_get_segment_iterators_timer = nullptr; + RuntimeProfile::Counter* _rowset_reader_create_iterators_timer = nullptr; + RuntimeProfile::Counter* _rowset_reader_init_iterators_timer = nullptr; + RuntimeProfile::Counter* _rowset_reader_load_segments_timer = nullptr; + RuntimeProfile::Counter* _segment_load_index_timer = nullptr; + RuntimeProfile::Counter* _output_index_result_column_timer = nullptr; // number of created olap scanners diff --git a/be/src/vec/exec/scan/new_olap_scanner.cpp b/be/src/vec/exec/scan/new_olap_scanner.cpp index 085baa0b619f43..fc52389a1ea055 100644 --- a/be/src/vec/exec/scan/new_olap_scanner.cpp +++ b/be/src/vec/exec/scan/new_olap_scanner.cpp @@ -518,6 +518,7 @@ void NewOlapScanner::_collect_profile_before_close() { COUNTER_UPDATE(olap_parent->_decompressor_timer, stats.decompress_ns); COUNTER_UPDATE(olap_parent->_read_uncompressed_counter, stats.uncompressed_bytes_read); + COUNTER_UPDATE(olap_parent->_tablet_read_timer, stats.tablet_read_timer); COUNTER_UPDATE(olap_parent->_block_load_timer, stats.block_load_ns); COUNTER_UPDATE(olap_parent->_block_load_counter, stats.blocks_load); COUNTER_UPDATE(olap_parent->_block_fetch_timer, stats.block_fetch_ns); @@ -601,6 +602,15 @@ void NewOlapScanner::_collect_profile_before_close() { COUNTER_UPDATE(olap_parent->_inverted_index_searcher_cache_miss_counter, stats.inverted_index_searcher_cache_miss); + COUNTER_UPDATE(olap_parent->_rowset_reader_get_segment_iterators_timer, + stats.rowset_reader_get_segment_iterators_timer_ns); + COUNTER_UPDATE(olap_parent->_rowset_reader_create_iterators_timer, + stats.rowset_reader_create_iterators_timer_ns); + COUNTER_UPDATE(olap_parent->_rowset_reader_init_iterators_timer, + stats.rowset_reader_init_iterators_timer_ns); + COUNTER_UPDATE(olap_parent->_rowset_reader_load_segments_timer, + stats.rowset_reader_load_segments_timer_ns); + COUNTER_UPDATE(olap_parent->_segment_load_index_timer, stats.segment_load_index_timer_ns); if (config::enable_file_cache) { io::FileCacheProfileReporter cache_profile(olap_parent->_segment_profile.get()); cache_profile.update(&stats.file_cache_stats); diff --git a/be/src/vec/olap/block_reader.h b/be/src/vec/olap/block_reader.h index 05b26f0c52c978..c12b5ae232f21c 100644 --- a/be/src/vec/olap/block_reader.h +++ b/be/src/vec/olap/block_reader.h @@ -48,6 +48,7 @@ class BlockReader final : public TabletReader { Status init(const ReaderParams& read_params) override; Status next_block_with_aggregation(Block* block, bool* eof) override { + SCOPED_RAW_TIMER(&_stats.tablet_read_timer); auto res = (this->*_next_block_func)(block, eof); if (UNLIKELY(!res.ok() && !res.is())) { _tablet->report_error(res);