You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@doris.apache.org by yi...@apache.org on 2022/04/02 02:35:41 UTC
[incubator-doris] branch master updated: [improvement](storage) Add more detailed timer on SegmentIter in profile (#8768)
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/incubator-doris.git
The following commit(s) were added to refs/heads/master by this push:
new c31c6ae [improvement](storage) Add more detailed timer on SegmentIter in profile (#8768)
c31c6ae is described below
commit c31c6ae91a2f51d8eba5943180adfb3eb691fe30
Author: ZenoYang <co...@qq.com>
AuthorDate: Sat Apr 2 10:35:28 2022 +0800
[improvement](storage) Add more detailed timer on SegmentIter in profile (#8768)
* [improvement](storage) Add more detailed timer on SegmentIter in profile
* add OutputColumnTime
---
be/src/exec/olap_scan_node.cpp | 4 ++
be/src/exec/olap_scan_node.h | 4 ++
be/src/exec/olap_scanner.cpp | 4 ++
be/src/olap/olap_common.h | 4 ++
be/src/olap/rowset/segment_v2/segment_iterator.cpp | 55 +++++++++++++---------
be/src/olap/rowset/segment_v2/segment_iterator.h | 1 +
be/src/vec/exec/volap_scanner.cpp | 37 ++++++++-------
docs/en/administrator-guide/running-profile.md | 4 ++
docs/zh-CN/administrator-guide/running-profile.md | 4 ++
9 files changed, 77 insertions(+), 40 deletions(-)
diff --git a/be/src/exec/olap_scan_node.cpp b/be/src/exec/olap_scan_node.cpp
index 02f8c72..366cda5 100644
--- a/be/src/exec/olap_scan_node.cpp
+++ b/be/src/exec/olap_scan_node.cpp
@@ -126,6 +126,10 @@ void OlapScanNode::_init_counter(RuntimeState* state) {
_rows_vec_cond_counter = ADD_COUNTER(_segment_profile, "RowsVectorPredFiltered", TUnit::UNIT);
_vec_cond_timer = ADD_TIMER(_segment_profile, "VectorPredEvalTime");
+ _short_cond_timer = ADD_TIMER(_segment_profile, "ShortPredEvalTime");
+ _pred_col_read_timer = ADD_TIMER(_segment_profile, "PredColumnReadTime");
+ _lazy_read_timer = ADD_TIMER(_segment_profile, "LazyReadTime");
+ _output_col_timer = ADD_TIMER(_segment_profile, "OutputColumnTime");
_stats_filtered_counter = ADD_COUNTER(_segment_profile, "RowsStatsFiltered", TUnit::UNIT);
_bf_filtered_counter = ADD_COUNTER(_segment_profile, "RowsBloomFilterFiltered", TUnit::UNIT);
diff --git a/be/src/exec/olap_scan_node.h b/be/src/exec/olap_scan_node.h
index 44a5cd2..8ebe610 100644
--- a/be/src/exec/olap_scan_node.h
+++ b/be/src/exec/olap_scan_node.h
@@ -289,6 +289,10 @@ protected:
RuntimeProfile::Counter* _rows_vec_cond_counter = nullptr;
RuntimeProfile::Counter* _vec_cond_timer = nullptr;
+ RuntimeProfile::Counter* _short_cond_timer = nullptr;
+ RuntimeProfile::Counter* _pred_col_read_timer = nullptr;
+ RuntimeProfile::Counter* _lazy_read_timer = nullptr;
+ RuntimeProfile::Counter* _output_col_timer = nullptr;
RuntimeProfile::Counter* _stats_filtered_counter = nullptr;
RuntimeProfile::Counter* _bf_filtered_counter = nullptr;
diff --git a/be/src/exec/olap_scanner.cpp b/be/src/exec/olap_scanner.cpp
index fcacd22..c769a0d 100644
--- a/be/src/exec/olap_scanner.cpp
+++ b/be/src/exec/olap_scanner.cpp
@@ -529,6 +529,10 @@ void OlapScanner::update_counter() {
_raw_rows_read += _tablet_reader->mutable_stats()->raw_rows_read;
// COUNTER_UPDATE(_parent->_filtered_rows_counter, stats.num_rows_filtered);
COUNTER_UPDATE(_parent->_vec_cond_timer, stats.vec_cond_ns);
+ COUNTER_UPDATE(_parent->_short_cond_timer, stats.short_cond_ns);
+ COUNTER_UPDATE(_parent->_pred_col_read_timer, stats.pred_col_read_ns);
+ COUNTER_UPDATE(_parent->_lazy_read_timer, stats.lazy_read_ns);
+ COUNTER_UPDATE(_parent->_output_col_timer, stats.output_col_ns);
COUNTER_UPDATE(_parent->_rows_vec_cond_counter, stats.rows_vec_cond_filtered);
COUNTER_UPDATE(_parent->_stats_filtered_counter, stats.rows_stats_filtered);
diff --git a/be/src/olap/olap_common.h b/be/src/olap/olap_common.h
index b06334c..02a4c41 100644
--- a/be/src/olap/olap_common.h
+++ b/be/src/olap/olap_common.h
@@ -263,6 +263,10 @@ struct OlapReaderStatistics {
int64_t rows_vec_cond_filtered = 0;
int64_t rows_vec_del_cond_filtered = 0;
int64_t vec_cond_ns = 0;
+ int64_t short_cond_ns = 0;
+ int64_t pred_col_read_ns = 0;
+ int64_t lazy_read_ns = 0;
+ int64_t output_col_ns = 0;
int64_t rows_key_range_filtered = 0;
int64_t rows_stats_filtered = 0;
diff --git a/be/src/olap/rowset/segment_v2/segment_iterator.cpp b/be/src/olap/rowset/segment_v2/segment_iterator.cpp
index 1802d14..ed0429c 100644
--- a/be/src/olap/rowset/segment_v2/segment_iterator.cpp
+++ b/be/src/olap/rowset/segment_v2/segment_iterator.cpp
@@ -499,29 +499,32 @@ Status SegmentIterator::next_batch(RowBlockV2* block) {
// phase 1: read rows selected by various index (indicated by _row_bitmap) into block
// when using lazy-materialization-read, only columns with predicates are read
- do {
- uint32_t range_from;
- uint32_t range_to;
- bool has_next_range =
- _range_iter->next_range(nrows_read_limit - nrows_read, &range_from, &range_to);
- if (!has_next_range) {
- break;
- }
- if (_cur_rowid == 0 || _cur_rowid != range_from) {
- _cur_rowid = range_from;
- RETURN_IF_ERROR(_seek_columns(read_columns, _cur_rowid));
- }
- size_t rows_to_read = range_to - range_from;
- RETURN_IF_ERROR(_read_columns(read_columns, block, nrows_read, rows_to_read));
- _cur_rowid += rows_to_read;
- if (_lazy_materialization_read) {
- for (uint32_t rid = range_from; rid < range_to; rid++) {
- _block_rowids[nrows_read++] = rid;
+ {
+ SCOPED_RAW_TIMER(&_opts.stats->pred_col_read_ns);
+ do {
+ uint32_t range_from;
+ uint32_t range_to;
+ bool has_next_range =
+ _range_iter->next_range(nrows_read_limit - nrows_read, &range_from, &range_to);
+ if (!has_next_range) {
+ break;
}
- } else {
- nrows_read += rows_to_read;
- }
- } while (nrows_read < nrows_read_limit);
+ if (_cur_rowid == 0 || _cur_rowid != range_from) {
+ _cur_rowid = range_from;
+ RETURN_IF_ERROR(_seek_columns(read_columns, _cur_rowid));
+ }
+ size_t rows_to_read = range_to - range_from;
+ RETURN_IF_ERROR(_read_columns(read_columns, block, nrows_read, rows_to_read));
+ _cur_rowid += rows_to_read;
+ if (_lazy_materialization_read) {
+ for (uint32_t rid = range_from; rid < range_to; rid++) {
+ _block_rowids[nrows_read++] = rid;
+ }
+ } else {
+ nrows_read += rows_to_read;
+ }
+ } while (nrows_read < nrows_read_limit);
+ }
block->set_num_rows(nrows_read);
block->set_selected_size(nrows_read);
@@ -559,6 +562,7 @@ Status SegmentIterator::next_batch(RowBlockV2* block) {
// phase 3: read non-predicate columns of rows that have passed predicates
if (_lazy_materialization_read) {
+ SCOPED_RAW_TIMER(&_opts.stats->lazy_read_ns);
uint16_t i = 0;
const uint16_t* sv = block->selection_vector();
const uint16_t sv_size = block->selected_size();
@@ -758,6 +762,7 @@ void SegmentIterator::_init_current_block(
}
void SegmentIterator::_output_non_pred_columns(vectorized::Block* block, bool is_block_mem_reuse) {
+ SCOPED_RAW_TIMER(&_opts.stats->output_col_ns);
for (auto cid : _non_predicate_columns) {
block->replace_by_position(_schema_block_id_map[cid],
std::move(_current_return_columns[cid]));
@@ -766,6 +771,7 @@ void SegmentIterator::_output_non_pred_columns(vectorized::Block* block, bool is
Status SegmentIterator::_read_columns_by_index(uint32_t nrows_read_limit, uint32_t& nrows_read,
bool set_block_rowid) {
+ SCOPED_RAW_TIMER(&_opts.stats->pred_col_read_ns);
do {
uint32_t range_from;
uint32_t range_to;
@@ -795,6 +801,7 @@ Status SegmentIterator::_read_columns_by_index(uint32_t nrows_read_limit, uint32
void SegmentIterator::_evaluate_vectorization_predicate(uint16_t* sel_rowid_idx,
uint16_t& selected_size) {
+ SCOPED_RAW_TIMER(&_opts.stats->vec_cond_ns);
if (_vec_pred_column_ids.empty()) {
for (uint32_t i = 0; i < selected_size; ++i) {
sel_rowid_idx[i] = i;
@@ -835,6 +842,7 @@ void SegmentIterator::_evaluate_vectorization_predicate(uint16_t* sel_rowid_idx,
void SegmentIterator::_evaluate_short_circuit_predicate(uint16_t* vec_sel_rowid_idx,
uint16_t* selected_size_ptr) {
+ SCOPED_RAW_TIMER(&_opts.stats->short_cond_ns);
if (_short_cir_pred_column_ids.empty()) {
return;
}
@@ -861,6 +869,7 @@ void SegmentIterator::_read_columns_by_rowids(std::vector<ColumnId>& read_column
std::vector<rowid_t>& rowid_vector,
uint16_t* sel_rowid_idx, size_t select_size,
vectorized::MutableColumns* mutable_columns) {
+ SCOPED_RAW_TIMER(&_opts.stats->lazy_read_ns);
size_t start_idx = 0;
while (start_idx < select_size) {
size_t end_idx = start_idx + 1;
@@ -970,7 +979,7 @@ Status SegmentIterator::next_batch(vectorized::Block* block) {
}
}
- // shink char_type suffix zero data
+ // shrink char_type suffix zero data
block->shrink_char_type_column_suffix_zero(_char_type_idx);
return Status::OK();
diff --git a/be/src/olap/rowset/segment_v2/segment_iterator.h b/be/src/olap/rowset/segment_v2/segment_iterator.h
index 8ef97a8..07ee964 100644
--- a/be/src/olap/rowset/segment_v2/segment_iterator.h
+++ b/be/src/olap/rowset/segment_v2/segment_iterator.h
@@ -106,6 +106,7 @@ private:
Status _output_column_by_sel_idx(vectorized::Block* block, const Container& column_ids,
uint16_t* sel_rowid_idx, uint16_t select_size,
bool is_block_mem_reuse) {
+ SCOPED_RAW_TIMER(&_opts.stats->output_col_ns);
for (auto cid : column_ids) {
int block_cid = _schema_block_id_map[cid];
RETURN_IF_ERROR(block->copy_column_data_to_block(
diff --git a/be/src/vec/exec/volap_scanner.cpp b/be/src/vec/exec/volap_scanner.cpp
index b01bd60..3850a8a 100644
--- a/be/src/vec/exec/volap_scanner.cpp
+++ b/be/src/vec/exec/volap_scanner.cpp
@@ -51,23 +51,26 @@ Status VOlapScanner::get_block(RuntimeState* state, vectorized::Block* block, bo
}
}
- do {
- // Read one block from block reader
- auto res = _tablet_reader->next_block_with_aggregation(block, nullptr, nullptr, eof);
- if (res != OLAP_SUCCESS) {
- std::stringstream ss;
- ss << "Internal Error: read storage fail. res=" << res
- << ", tablet=" << _tablet->full_name()
- << ", backend=" << BackendOptions::get_localhost();
- return Status::InternalError(ss.str());
- }
- _num_rows_read += block->rows();
- _update_realtime_counter();
-
- RETURN_IF_ERROR(
- VExprContext::filter_block(_vconjunct_ctx, block, _tuple_desc->slots().size()));
- } while (block->rows() == 0 && !(*eof) && raw_rows_read() < raw_rows_threshold &&
- block->allocated_bytes() < raw_bytes_threshold);
+ {
+ SCOPED_TIMER(_parent->_scan_timer);
+ do {
+ // Read one block from block reader
+ auto res = _tablet_reader->next_block_with_aggregation(block, nullptr, nullptr, eof);
+ if (res != OLAP_SUCCESS) {
+ std::stringstream ss;
+ ss << "Internal Error: read storage fail. res=" << res
+ << ", tablet=" << _tablet->full_name()
+ << ", backend=" << BackendOptions::get_localhost();
+ return Status::InternalError(ss.str());
+ }
+ _num_rows_read += block->rows();
+ _update_realtime_counter();
+
+ RETURN_IF_ERROR(
+ VExprContext::filter_block(_vconjunct_ctx, block, _tuple_desc->slots().size()));
+ } while (block->rows() == 0 && !(*eof) && raw_rows_read() < raw_rows_threshold &&
+ block->allocated_bytes() < raw_bytes_threshold);
+ }
// NOTE:
// There is no need to check raw_bytes_threshold since block->rows() == 0 is checked first.
// But checking raw_bytes_threshold is still added here for consistency with raw_rows_threshold
diff --git a/docs/en/administrator-guide/running-profile.md b/docs/en/administrator-guide/running-profile.md
index 03e6ebd..8dff6f4 100644
--- a/docs/en/administrator-guide/running-profile.md
+++ b/docs/en/administrator-guide/running-profile.md
@@ -237,6 +237,10 @@ OLAP_SCAN_NODE (id=0):(Active: 1.2ms,% non-child: 0.00%)
- TotalPagesNum: 30 # Only in V2, the total number of pages read.
- UncompressedBytesRead: 0.00 # V1 is the decompressed size of the read data file (if the file does not need to be decompressed, the file size is directly counted). In V2, only the decompressed size of the Page that missed PageCache is counted (if the Page does not need to be decompressed, the Page size is directly counted)
- VectorPredEvalTime: 0ns # Time-consuming of vectorized condition filtering operation.
+ - ShortPredEvalTime: 0ns # Time-consuming of short-circuiting predicate condition filtering operations.
+ - PredColumnReadTime: 0ns # Time-consuming of predicate column read.
+ - LazyReadTime: 0ns # Time-consuming of non-predicate column read.
+ - OutputColumnTime: 0ns # Time-consuming of materialize columns.
```
The predicate push down and index usage can be inferred from the related indicators of the number of data rows in the profile. The following only describes the profile in the reading process of segment V2 format data. In segment V1 format, the meaning of these indicators is slightly different.
diff --git a/docs/zh-CN/administrator-guide/running-profile.md b/docs/zh-CN/administrator-guide/running-profile.md
index 8ee51b1..9277ab4 100644
--- a/docs/zh-CN/administrator-guide/running-profile.md
+++ b/docs/zh-CN/administrator-guide/running-profile.md
@@ -236,6 +236,10 @@ OLAP_SCAN_NODE (id=0):(Active: 1.2ms, % non-child: 0.00%)
- TotalPagesNum: 30 # 仅 V2 中，读取的总 Page 数量。
- UncompressedBytesRead: 0.00 # V1 中为读取的数据文件解压后的大小（如果文件无需解压，则直接统计文件大小）。V2 中，仅统计未命中 PageCache 的 Page 解压后的大小（如果Page无需解压，直接统计Page大小）
- VectorPredEvalTime: 0ns # 向量化条件过滤操作的耗时。
+ - ShortPredEvalTime: 0ns # 短路谓词过滤操作的耗时。
+ - PredColumnReadTime: 0ns # 谓词列读取的耗时。
+ - LazyReadTime: 0ns # 非谓词列读取的耗时。
+ - OutputColumnTime: 0ns # 物化列的耗时。
```
通过 Profile 中数据行数相关指标可以推断谓词条件下推和索引使用情况。以下仅针对 Segment V2 格式数据读取流程中的 Profile 进行说明。Segment V1 格式中，这些指标的含义略有不同。
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org