You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@doris.apache.org by ka...@apache.org on 2020/06/02 03:07:25 UTC
[incubator-doris] branch master updated: [Bug] Fix bug that
runningprofile show time problem in FE web page and add the runingprofile
doc (#3722)
This is an automated email from the ASF dual-hosted git repository.
kangkaisen 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 761a0cc [Bug] Fix bug that runningprofile show time problem in FE web page and add the runingprofile doc (#3722)
761a0cc is described below
commit 761a0ccd1228cba4492283239a8b5e072307fa59
Author: HappenLee <ha...@hotmail.com>
AuthorDate: Tue Jun 2 11:07:15 2020 +0800
[Bug] Fix bug that runningprofile show time problem in FE web page and add the runingprofile doc (#3722)
---
docs/en/administrator-guide/runing-profile.md | 147 ++++++++++++++++++++
docs/zh-CN/administrator-guide/running-profile.md | 151 +++++++++++++++++++++
.../org/apache/doris/common/util/DebugUtil.java | 2 +-
3 files changed, 299 insertions(+), 1 deletion(-)
diff --git a/docs/en/administrator-guide/runing-profile.md b/docs/en/administrator-guide/runing-profile.md
new file mode 100644
index 0000000..e411bf5
--- /dev/null
+++ b/docs/en/administrator-guide/runing-profile.md
@@ -0,0 +1,147 @@
+---
+{
+ "title": "Statistics of query execution",
+ "language": "en"
+}
+---
+
+<!--
+Licensed to the Apache Software Foundation (ASF) under one
+or more contributor license agreements. See the NOTICE file
+distributed with this work for additional information
+regarding copyright ownership. The ASF licenses this file
+to you under the Apache License, Version 2.0 (the
+"License"); you may not use this file except in compliance
+with the License. You may obtain a copy of the License at
+
+ http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing,
+software distributed under the License is distributed on an
+"AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+KIND, either express or implied. See the License for the
+specific language governing permissions and limitations
+under the License.
+-->
+
+# Statistics of query execution
+
+This document focuses on introducing the **RuningProfle** which recorded runtime status of Doris in query execution. Using these statistical information, we can understand the execution of frgment to become a expert of Doris's **debugging and tuning**.
+
+## Noun Interpretation
+
+* **FE**: Frontend, frontend node of Doris. Responsible for metadata management and request access.
+
+* **BE**: Backend, backend node of Doris. Responsible for query execution and data storage.
+
+* **Fragment**: FE will convert the execution of specific SQL statements into corresponding fragments and distribute them to BE for execution. BE will execute corresponding fragments and gather the result of RunningProfile to send back FE.
+
+## Basic concepts
+
+FE splits the query plan into fragments and distributes them to BE for task execution. BE records the statistics of **Running State** when executing fragment. BE print the outputs statistics of fragment execution into the log. FE can also collect these statistics recorded by each fragment and print the results on FE's web page.
+## Specific operation
+
+Turn on the report switch on FE through MySQL command
+
+```
+mysql> set is_report_success=true;
+```
+
+After executing the corresponding SQL statement, we can see the report information of the corresponding SQL statement on the FE web page like the picture below.
+
+
+The latest **100 statements** executed will be listed here. We can view detailed statistics of RunningProfile.
+```
+Query:
+ Summary:
+ Query ID: 9664061c57e84404-85ae111b8ba7e83a
+ Start Time: 2020-05-02 10:34:57
+ End Time: 2020-05-02 10:35:08
+ Total: 10s323ms
+ Query Type: Query
+ Query State: EOF
+ Doris Version: trunk
+ User: root
+ Default Db: default_cluster:test
+ Sql Statement: select max(Bid_Price) from quotes group by Symbol
+```
+Here is a detailed list of ```query ID, execution time, execution statement``` and other summary information. The next step is to print the details of each fragment collected from be.
+ ```
+ Fragment 0:
+ Instance 9664061c57e84404-85ae111b8ba7e83d (host=TNetworkAddress(hostname:10.144.192.47, port:9060)):(Active: 10s270ms, % non-child: 0.14%)
+ - MemoryLimit: 2.00 GB
+ - BytesReceived: 168.08 KB
+ - PeakUsedReservation: 0.00
+ - SendersBlockedTimer: 0ns
+ - DeserializeRowBatchTimer: 501.975us
+ - PeakMemoryUsage: 577.04 KB
+ - RowsProduced: 8.322K (8322)
+ EXCHANGE_NODE (id=4):(Active: 10s256ms, % non-child: 99.35%)
+ - ConvertRowBatchTime: 180.171us
+ - PeakMemoryUsage: 0.00
+ - RowsReturned: 8.322K (8322)
+ - 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**.
+
+## Profile statistic analysis
+
+There are many statistical information collected at BE. so we list the corresponding meanings of profile are below:
+
+#### Fragment
+ - AverageThreadTokens: Number of threads used to execute fragment, excluding the usage of thread pool
+ - PeakReservation: Peak memory used by buffer pool
+ - MemoryLimit: Memory limit at query
+ - PeakMemoryUsage: Peak memory usage
+ - RowsProduced: Number of rows that process
+ - BytesReceived: Size of bytes received by network
+ - DeserializeRowBatchTimer: Time consuming to receive data deserialization
+
+#### DataStreamSender
+ - BytesSent: Total bytes data sent
+ - IgnoreRows: Rows filtered
+ - OverallThroughput: Total throughput = BytesSent / Time
+ - SerializeBatchTime: Sending data serialization time
+ - UncompressedRowBatchSize: Size of rowbatch before sending data compression
+
+#### SORT_NODE
+ - InMemorySortTime: In memory sort time
+ - InitialRunsCreated: Number of initialize sort run
+ - MergeGetNext: Time cost of MergeSort from multiple sort_run to get the next batch (only show spilled disk)
+ - MergeGetNextBatch: Time cost MergeSort one sort_run to get the next batch (only show spilled disk)
+ - SortDataSize: Total sorted data
+ - TotalMergesPerformed: Number of external sort merges
+
+#### AGGREGATION_NODE：
+ - PartitionsCreated: Number of partition split by aggregate
+ - GetResultsTime: Time to get aggregate results from each partition
+ - HTResizeTime: Time spent in resizing hashtable
+ - HTResize: Number of times hashtable resizes
+ - HashBuckets: Number of buckets in hashtable
+ - HashBucketsWithDuplicate: Number of buckets with duplicatenode in hashtable
+ - HashCollisions: Number of hash conflicts generated
+ - HashDuplicateNodes: Number of duplicate nodes with the same buckets in hashtable
+ - HashFailedProbe: Number of failed probe operations
+ - HashFilledBuckets: Number of buckets filled data
+ - HashProbe: Number of hashtable probe
+ - HashTravelLength: The number of steps moved when hashtable queries
+
+#### OLAP_SCAN_NODE:
+ - BytesRead: Total data
+ - TotalReadThroughput：Throughput = BytesRead / Time
+ - TabletCount: Number of scanned tablets
+ - RowsPushedCondFiltered：Number of filters pushed down
+ - RawRowsRead: Number of rows read
+ - RowsReturned: Number of rows returned by the node
+ - RowsReturnedRate: Rate of rows returned
+ - PeakMemoryUsage: Peak memory usage of the node
+
+#### Buffer pool:
+ - AllocTime: Memory allocation time
+ - CumulativeAllocationBytes: Cumulative amount of memory allocated
+ - CumulativeAllocations: Cumulative number of memory allocations
+ - PeakReservation: Peak of reservation
+ - PeakUnpinnedBytes: Amount of memory data of unpin
+ - PeakUsedReservation: Peak usage of reservation
+ - ReservationLimit: Limit of reservation of bufferpool
diff --git a/docs/zh-CN/administrator-guide/running-profile.md b/docs/zh-CN/administrator-guide/running-profile.md
new file mode 100644
index 0000000..a662d30
--- /dev/null
+++ b/docs/zh-CN/administrator-guide/running-profile.md
@@ -0,0 +1,151 @@
+---
+{
+ "title": "查询执行的统计",
+ "language": "zh-CN"
+}
+---
+
+<!--
+Licensed to the Apache Software Foundation (ASF) under one
+or more contributor license agreements. See the NOTICE file
+distributed with this work for additional information
+regarding copyright ownership. The ASF licenses this file
+to you under the Apache License, Version 2.0 (the
+"License"); you may not use this file except in compliance
+with the License. You may obtain a copy of the License at
+
+ http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing,
+software distributed under the License is distributed on an
+"AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+KIND, either express or implied. See the License for the
+specific language governing permissions and limitations
+under the License.
+-->
+
+# 查询执行的统计
+
+本文档主要介绍Doris在查询执行的统计结果。利用这些统计的信息，可以更好的帮助我们了解Doris的执行情况，并有针对性的进行相应**Debug与调优工作**。
+
+
+## 名词解释
+
+* FE：Frontend，Doris 的前端节点。负责元数据管理和请求接入。
+* BE：Backend，Doris 的后端节点。负责查询执行和数据存储。
+* Fragment：FE会将具体的SQL语句的执行转化为对应的Fragment并下发到BE进行执行。BE上执行对应Fragment，并将结果汇聚返回给FE。
+
+## 基本原理
+
+FE将查询计划拆分成为Fragment下发到BE进行任务执行。BE在执行Fragment时记录了**运行状态时的统计值**，并将Fragment执行的统计信息输出到日志之中。 FE也可以通过开关将各个Fragment记录的这些统计值进行搜集，并在FE的Web页面上打印结果。
+
+## 操作流程
+
+通过Mysql命令，将FE上的Report的开关打开
+
+```
+mysql> set is_report_success=true;
+```
+
+之后执行对应的SQL语句之后，在FE的Web页面就可以看到对应SQL语句执行的Report信息：
+
+
+这里会列出最新执行完成的**100条语句**，我们可以通过Profile查看详细的统计信息。
+```
+Query:
+ Summary:
+ Query ID: 9664061c57e84404-85ae111b8ba7e83a
+ Start Time: 2020-05-02 10:34:57
+ End Time: 2020-05-02 10:35:08
+ Total: 10s323ms
+ Query Type: Query
+ Query State: EOF
+ Doris Version: trunk
+ User: root
+ Default Db: default_cluster:test
+ Sql Statement: select max(Bid_Price) from quotes group by Symbol
+```
+这里详尽的列出了**查询的ID，执行时间，执行语句**等等的总结信息。接下来内容是打印从BE收集到的各个Fragement的详细信息。
+ ```
+ Fragment 0:
+ Instance 9664061c57e84404-85ae111b8ba7e83d (host=TNetworkAddress(hostname:10.144.192.47, port:9060)):(Active: 10s270ms, % non-child: 0.14%)
+ - MemoryLimit: 2.00 GB
+ - BytesReceived: 168.08 KB
+ - PeakUsedReservation: 0.00
+ - SendersBlockedTimer: 0ns
+ - DeserializeRowBatchTimer: 501.975us
+ - PeakMemoryUsage: 577.04 KB
+ - RowsProduced: 8.322K (8322)
+ EXCHANGE_NODE (id=4):(Active: 10s256ms, % non-child: 99.35%)
+ - ConvertRowBatchTime: 180.171us
+ - PeakMemoryUsage: 0.00
+ - RowsReturned: 8.322K (8322)
+ - MemoryUsed: 0.00
+ - RowsReturnedRate: 811
+```
+这里列出了Fragment的ID；```hostname```指的是执行Fragment的BE节点；```Active：10s270ms```表示该节点的执行总时间；```non-child: 0.14%```表示执行节点自身的执行时间，不包含子节点的执行时间。后续依次打印子节点的统计信息，**这里可以通过缩进区分节点之间的父子关系**。
+## Profile参数解析
+BE端收集的统计信息较多，下面列出了各个参数的对应含义：
+
+#### Fragment
+ - AverageThreadTokens: 执行Fragment使用线程数目，不包含线程池的使用情况
+ - Buffer Pool PeakReservation: Buffer Pool使用的内存的峰值
+ - MemoryLimit: 查询时的内存限制
+ - PeakMemoryUsage: 内存使用的峰值
+ - RowsProduced: 处理列的行数
+ - BytesReceived: 通过网络接收的Bytes大小
+ - DeserializeRowBatchTimer: 反序列化的耗时
+#### BlockMgr:
+ - BlocksCreated: 落盘时创建的Blocks数目
+ - BlocksRecycled: 重用的Blocks数目
+ - BytesWritten: 总的落盘写数据量
+ - MaxBlockSize: 单个Block的大小
+ - TotalReadBlockTime: 读Block的总耗时
+#### DataStreamSender
+ - BytesSent: 发送的总数据量 = 接受者 * 发送数据量
+ - IgnoreRows: 过滤的行数
+ - OverallThroughput: 总的吞吐量 = BytesSent / 时间
+ - SerializeBatchTime: 发送数据序列化消耗的时间
+ - UncompressedRowBatchSize: 发送数据压缩前的RowBatch的大小
+
+ #### SORT_NODE
+ - InMemorySortTime: 内存之中的排序耗时
+ - InitialRunsCreated: 初始化排序的趟数（如果内存排序的话，该数为1）
+ - SortDataSize: 总的排序数据量
+ - MergeGetNext: MergeSort从多个sort_run获取下一个batch的耗时 (仅在落盘时计时）
+ - MergeGetNextBatch: MergeSort提取下一个sort_run的batch的耗时 (仅在落盘时计时）
+ - TotalMergesPerformed: 进行外排merge的次数
+
+#### AGGREGATION_NODE：
+ - PartitionsCreated: 聚合查询拆分成Partition的个数
+ - GetResultsTime: 从各个partition之中获取聚合结果的时间
+ - HTResizeTime: HashTable进行resize消耗的时间
+ - HTResize: HashTable进行resize的次数
+ - HashBuckets: HashTable中Buckets的个数
+ - HashBucketsWithDuplicate: HashTable有DuplicateNode的Buckets的个数
+ - HashCollisions: HashTable产生哈希冲突的次数
+ - HashDuplicateNodes: HashTable出现Buckets相同DuplicateNode的个数
+ - HashFailedProbe: HashTable Probe操作失败的次数
+ - HashFilledBuckets: HashTable填入数据的Buckets数目
+ - HashProbe: HashTable查询的次数
+ - HashTravelLength: HashTable查询时移动的步数
+
+#### OLAP_SCAN_NODE:
+ - RowsProduced: 生成结果的行数
+ - BytesRead: scan node 扫描数据的总量
+ - TotalReadThroughput：吞吐量
+ - TabletCount: tablet 的数目
+ - RowsPushedCondFiltered：下推的过滤器
+ - RawRowsRead: 实际读取的行数
+ - RowsReturned: 该节点返回的行数
+ - RowsReturnedRate: 返回行数的速率
+ - PeakMemoryUsage 内存使用的峰值
+
+#### Buffer pool:
+ - AllocTime: 内存分配耗时
+ - CumulativeAllocationBytes: 累计内存分配的量
+ - CumulativeAllocations: 累计的内存分配次数
+ - PeakReservation: Reservation的峰值
+ - PeakUnpinnedBytes: unpin的内存数据量
+ - PeakUsedReservation: Reservation的内存使用量
+ - ReservationLimit: BufferPool的Reservation的限制量
diff --git a/fe/src/main/java/org/apache/doris/common/util/DebugUtil.java b/fe/src/main/java/org/apache/doris/common/util/DebugUtil.java
index 31febdc..9348447 100644
--- a/fe/src/main/java/org/apache/doris/common/util/DebugUtil.java
+++ b/fe/src/main/java/org/apache/doris/common/util/DebugUtil.java
@@ -75,7 +75,7 @@ public class DebugUtil {
}
if (newValue >= MINUTE) {
builder.append(newValue / MINUTE).append("m");
- newValue %= newValue;
+ newValue %= MINUTE;
minute = true;
}
if (!hour && newValue >= SECOND) {
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org