You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@doris.apache.org by mo...@apache.org on 2020/11/16 13:53:46 UTC
[incubator-doris] branch master updated: [Doc] Running Profile
document add HASH_JOIN_NODE, etc. (#4878)
This is an automated email from the ASF dual-hosted git repository.
morningman 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 e706a6b [Doc] Running Profile document add HASH_JOIN_NODE, etc. (#4878)
e706a6b is described below
commit e706a6bca498986e40ead4f75431aa99ad81d68f
Author: Xinyi Zou <zo...@foxmail.com>
AuthorDate: Mon Nov 16 21:53:25 2020 +0800
[Doc] Running Profile document add HASH_JOIN_NODE, etc. (#4878)
- Running Profile document add `HASH_JOIN_NODE`, `CROSS_JOIN_NODE`, `UNION_NODE`, `ANALYTIC_EVAL_NODE`.
- `UNION_NODE` increase`MaterializeExprsEvaluateTime` profile.
---
be/src/exec/union_node.cpp | 15 +++++++++++
be/src/exec/union_node.h | 6 +++++
docs/en/administrator-guide/running-profile.md | 33 ++++++++++++++++++++++-
docs/zh-CN/administrator-guide/running-profile.md | 33 ++++++++++++++++++++++-
4 files changed, 85 insertions(+), 2 deletions(-)
diff --git a/be/src/exec/union_node.cpp b/be/src/exec/union_node.cpp
index a5b686c..1543fff 100644
--- a/be/src/exec/union_node.cpp
+++ b/be/src/exec/union_node.cpp
@@ -73,6 +73,7 @@ Status UnionNode::prepare(RuntimeState* state) {
RETURN_IF_ERROR(ExecNode::prepare(state));
_tuple_desc = state->desc_tbl().get_tuple_descriptor(_tuple_id);
DCHECK(_tuple_desc != nullptr);
+ _materialize_exprs_evaluate_timer = ADD_TIMER(_runtime_profile, "MaterializeExprsEvaluateTimer");
_codegend_union_materialize_batch_fns.resize(_child_expr_lists.size());
// Prepare const expr lists.
for (const vector<ExprContext*>& exprs : _const_expr_lists) {
@@ -180,6 +181,7 @@ Status UnionNode::get_next_materialized(RuntimeState* state, RowBatch* row_batch
}
DCHECK_EQ(_codegend_union_materialize_batch_fns.size(), _children.size());
if (_codegend_union_materialize_batch_fns[_child_idx] == nullptr) {
+ SCOPED_TIMER(_materialize_exprs_evaluate_timer);
materialize_batch(row_batch, &tuple_buf);
} else {
_codegend_union_materialize_batch_fns[_child_idx](this, row_batch, &tuple_buf);
@@ -298,5 +300,18 @@ Status UnionNode::close(RuntimeState* state) {
return ExecNode::close(state);
}
+void UnionNode::debug_string(int indentation_level, std::stringstream* out) const {
+ *out << string(indentation_level * 2, ' ');
+ *out << "_union(_first_materialized_child_idx=" << _first_materialized_child_idx
+ << " _row_descriptor=[" << row_desc().debug_string() << "] "
+ << " _child_expr_lists=[";
+ for (int i = 0; i < _child_expr_lists.size(); ++i) {
+ *out << Expr::debug_string(_child_expr_lists[i]) << ", ";
+ }
+ *out << "] \n";
+ ExecNode::debug_string(indentation_level, out);
+ *out << ")" << std::endl;
+}
+
}
diff --git a/be/src/exec/union_node.h b/be/src/exec/union_node.h
index daa4dc4..d05349f 100644
--- a/be/src/exec/union_node.h
+++ b/be/src/exec/union_node.h
@@ -50,6 +50,9 @@ public:
// virtual Status reset(RuntimeState* state);
virtual Status close(RuntimeState* state);
+protected:
+ void debug_string(int indentation_level, std::stringstream* out) const;
+
private:
/// Tuple id resolved in Prepare() to set tuple_desc_;
const int _tuple_id;
@@ -99,6 +102,9 @@ private:
/// to -1 if no child needs to be closed.
int _to_close_child_idx;
+ // Time spent to evaluates exprs and materializes the results
+ RuntimeProfile::Counter* _materialize_exprs_evaluate_timer = nullptr;
+
/// END: Members that must be Reset()
/////////////////////////////////////////
diff --git a/docs/en/administrator-guide/running-profile.md b/docs/en/administrator-guide/running-profile.md
index 77bd5d3..25a4a70 100644
--- a/docs/en/administrator-guide/running-profile.md
+++ b/docs/en/administrator-guide/running-profile.md
@@ -83,7 +83,11 @@ Here is a detailed list of ```query ID, execution time, execution statement```
- MemoryUsed: 0.00
- RowsReturnedRate: 811
```
-The fragment ID is listed here; ``` hostname ``` show the be node executing the fragment; ```active: 10s270ms```show the total execution time of the node; ```non child: 0.14%``` show the execution time of the node self except the execution time of the subchild node. Subsequently, the statistics of the child nodes will be printed in turn. **here you can distinguish the parent-child relationship by intent**.
+The fragment ID is listed here; ``` hostname ``` show the be node executing the fragment; ```active: 10s270ms```show the total execution time of the node; ```non child: 0.14%``` means the execution time of the execution node itself (not including the execution time of child nodes) as a percentage of the total time.
+
+`PeakMemoryUsage` indicates the peak memory usage of `EXCHANGE_NODE`; `RowsReturned` indicates the number of rows returned by `EXCHANGE_NODE`; `RowsReturnedRate`=`RowsReturned`/`ActiveTime`; the meaning of these three statistics in other `NODE` the same.
+
+Subsequently, the statistics of the child nodes will be printed in turn. **here you can distinguish the parent-child relationship by intent**.
## Profile statistic analysis
@@ -142,6 +146,33 @@ There are many statistical information collected at BE. so we list the correspo
- HashProbe: Number of hashtable probe
- HashTravelLength: The number of steps moved when hashtable queries
+#### `HASH_JOIN_NODE`
+ - ExecOption: The way to construct a HashTable for the right child (synchronous or asynchronous), the right child in Join may be a table or a subquery, the same is true for the left child
+ - BuildBuckets: The number of Buckets in HashTable
+ - BuildRows: the number of rows of HashTable
+ - BuildTime: Time-consuming to construct HashTable
+ - LoadFactor: Load factor of HashTable (ie the number of non-empty buckets)
+ - ProbeRows: Traverse the number of rows of the left child for Hash Probe
+ - ProbeTime: Time consuming to traverse the left child for Hash Probe, excluding the time consuming to call GetNext on the left child RowBatch
+ - PushDownComputeTime: The calculation time of the predicate pushdown condition
+ - PushDownTime: The total time consumed by the predicate push down. When Join, the right child who meets the requirements is converted to the left child's in query
+
+#### `CROSS_JOIN_NODE`
+ - ExecOption: The way to construct RowBatchList for the right child (synchronous or asynchronous)
+ - BuildRows: The number of rows of RowBatchList (ie the number of rows of the right child)
+ - BuildTime: Time-consuming to construct RowBatchList
+ - LeftChildRows: the number of rows of the left child
+ - LeftChildTime: The time it takes to traverse the left child and find the Cartesian product with the right child, not including the time it takes to call GetNext on the left child RowBatch
+
+#### `UNION_NODE`
+ - MaterializeExprsEvaluateTime: When the field types at both ends of the Union are inconsistent, the time spent to evaluates type conversion exprs and materializes the results
+
+#### `ANALYTIC_EVAL_NODE`
+ - EvaluationTime: Analysis function (window function) calculation total time
+ - GetNewBlockTime: It takes time to apply for a new block during initialization. Block saves the cache line window or the entire partition for analysis function calculation
+ - PinTime: the time it takes to apply for a new block later or reread the block written to the disk back to the memory
+ - UnpinTime: the time it takes to flush the data of the block to the disk when the memory pressure of the block that is not in use or the current operator is high
+
#### `OLAP_SCAN_NODE`
The `OLAP_SCAN_NODE` is responsible for specific data scanning tasks. One `OLAP_SCAN_NODE` will generate one or more `OlapScanner`. Each Scanner thread is responsible for scanning part of the data.
diff --git a/docs/zh-CN/administrator-guide/running-profile.md b/docs/zh-CN/administrator-guide/running-profile.md
index 3a220b8..fe13a72 100644
--- a/docs/zh-CN/administrator-guide/running-profile.md
+++ b/docs/zh-CN/administrator-guide/running-profile.md
@@ -83,7 +83,11 @@ Query:
- MemoryUsed: 0.00
- RowsReturnedRate: 811
```
-这里列出了Fragment的ID；```hostname```指的是执行Fragment的BE节点；```Active：10s270ms```表示该节点的执行总时间；```non-child: 0.14%```表示执行节点自身的执行时间，不包含子节点的执行时间。后续依次打印子节点的统计信息，**这里可以通过缩进区分节点之间的父子关系**。
+这里列出了Fragment的ID；```hostname```指的是执行Fragment的BE节点；```Active：10s270ms```表示该节点的执行总时间；```non-child: 0.14%```表示执行节点自身的执行时间（不包含子节点的执行时间）占总时间的百分比；
+
+`PeakMemoryUsage`表示`EXCHANGE_NODE`内存使用的峰值；`RowsReturned`表示`EXCHANGE_NODE`结果返回的行数；`RowsReturnedRate`=`RowsReturned`/`ActiveTime`；这三个统计信息在其他`NODE`中的含义相同。
+
+后续依次打印子节点的统计信息，**这里可以通过缩进区分节点之间的父子关系**。
## Profile参数解析
BE端收集的统计信息较多，下面列出了各个参数的对应含义：
@@ -141,6 +145,33 @@ BE端收集的统计信息较多，下面列出了各个参数的对应含义：
- HashProbe: HashTable查询的次数
- HashTravelLength: HashTable查询时移动的步数
+#### `HASH_JOIN_NODE`
+ - ExecOption: 对右孩子构造HashTable的方式（同步or异步），Join中右孩子可能是表或子查询，左孩子同理
+ - BuildBuckets: HashTable中Buckets的个数
+ - BuildRows: HashTable的行数
+ - BuildTime: 构造HashTable的耗时
+ - LoadFactor: HashTable的负载因子（即非空Buckets的数量）
+ - ProbeRows: 遍历左孩子进行Hash Probe的行数
+ - ProbeTime: 遍历左孩子进行Hash Probe的耗时，不包括对左孩子RowBatch调用GetNext的耗时
+ - PushDownComputeTime: 谓词下推条件计算耗时
+ - PushDownTime: 谓词下推的总耗时，Join时对满足要求的右孩子，转为左孩子的in查询
+
+#### `CROSS_JOIN_NODE`
+ - ExecOption: 对右孩子构造RowBatchList的方式（同步or异步）
+ - BuildRows: RowBatchList的行数（即右孩子的行数）
+ - BuildTime: 构造RowBatchList的耗时
+ - LeftChildRows: 左孩子的行数
+ - LeftChildTime: 遍历左孩子，和右孩子求笛卡尔积的耗时，不包括对左孩子RowBatch调用GetNext的耗时
+
+#### `UNION_NODE`
+ - MaterializeExprsEvaluateTime: Union两端字段类型不一致时，类型转换表达式计算及物化结果的耗时
+
+#### `ANALYTIC_EVAL_NODE`
+ - EvaluationTime: 分析函数（窗口函数）计算总耗时
+ - GetNewBlockTime: 初始化时申请一个新的Block的耗时，Block用来缓存Rows窗口或整个分区，用于分析函数计算
+ - PinTime: 后续申请新的Block或将写入磁盘的Block重新读取回内存的耗时
+ - UnpinTime: 对暂不需要使用的Block或当前操作符内存压力大时，将Block的数据刷入磁盘的耗时
+
#### `OLAP_SCAN_NODE`
`OLAP_SCAN_NODE` 节点负责具体的数据扫描任务。一个 `OLAP_SCAN_NODE` 会生成一个或多个 `OlapScanner` 。每个 Scanner 线程负责扫描部分数据。
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org