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/doris.git
The following commit(s) were added to refs/heads/master by this push:
new e4ac52b2aa [Improvement](profile)Add init and finalize external scan
node time in profile (#21749)
e4ac52b2aa is described below
commit e4ac52b2aab17fc61c2a63f40566da5a221ea0b5
Author: Jibing-Li <64681310+jibing...@users.noreply.github.com>
AuthorDate: Thu Jul 20 20:29:18 2023 +0800
[Improvement](profile)Add init and finalize external scan node time in
profile (#21749)
Add more profile information for external table plan time. Including init
and finalize scan node time, getSplits time, create scan range time, get all
partitions time and get all files for all partitions time. Also modified the
Indentation to make it easier to read.
This is an example output of the new profile summary.
```
Execution Summary:
- Analysis Time: 3ms
- Plan Time: 26s885ms
- JoinReorder Time: N/A
- CreateSingleNode Time: N/A
- QueryDistributed Time: N/A
- Init Scan Node Time: 1ms
- Finalize Scan Node Time: 26s868ms
- Get Splits Time: 26s554ms
- Get PARTITIONS Time: 20s189ms
- Get PARTITION FILES Time: 6s289ms
- Create Scan Range Time: 314ms
- Schedule Time: 1s67ms
- Fetch Result Time: 56ms
- Write Result Time: 0ms
- Wait and Fetch Result Time: 57ms
```
---
.../doris/common/profile/SummaryProfile.java | 123 ++++++++++++++++++++-
.../apache/doris/common/util/RuntimeProfile.java | 13 ++-
.../doris/planner/external/FileQueryScanNode.java | 27 +++++
.../doris/planner/external/HiveScanNode.java | 13 ++-
4 files changed, 169 insertions(+), 7 deletions(-)
diff --git
a/fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java
b/fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java
index 1646120254..1cd2c171e2 100644
---
a/fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java
+++
b/fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java
@@ -22,6 +22,7 @@ import org.apache.doris.common.util.TimeUtils;
import org.apache.doris.thrift.TUnit;
import com.google.common.collect.ImmutableList;
+import com.google.common.collect.ImmutableMap;
import com.google.common.collect.Maps;
import java.util.Map;
@@ -55,6 +56,12 @@ public class SummaryProfile {
public static final String JOIN_REORDER_TIME = "JoinReorder Time";
public static final String CREATE_SINGLE_NODE_TIME = "CreateSingleNode
Time";
public static final String QUERY_DISTRIBUTED_TIME = "QueryDistributed
Time";
+ public static final String INIT_SCAN_NODE_TIME = "Init Scan Node Time";
+ public static final String FINALIZE_SCAN_NODE_TIME = "Finalize Scan Node
Time";
+ public static final String GET_SPLITS_TIME = "Get Splits Time";
+ public static final String GET_PARTITIONS_TIME = "Get PARTITIONS Time";
+ public static final String GET_PARTITION_FILES_TIME = "Get PARTITION FILES
Time";
+ public static final String CREATE_SCAN_RANGE_TIME = "Create Scan Range
Time";
public static final String PLAN_TIME = "Plan Time";
public static final String SCHEDULE_TIME = "Schedule Time";
public static final String FETCH_RESULT_TIME = "Fetch Result Time";
@@ -66,7 +73,26 @@ public class SummaryProfile {
IS_CACHED, TOTAL_INSTANCES_NUM, INSTANCES_NUM_PER_BE,
PARALLEL_FRAGMENT_EXEC_INSTANCE, TRACE_ID);
public static final ImmutableList<String> EXECUTION_SUMMARY_KEYS =
ImmutableList.of(ANALYSIS_TIME, PLAN_TIME,
- SCHEDULE_TIME, FETCH_RESULT_TIME, WRITE_RESULT_TIME,
WAIT_FETCH_RESULT_TIME);
+ JOIN_REORDER_TIME, CREATE_SINGLE_NODE_TIME, QUERY_DISTRIBUTED_TIME,
+ INIT_SCAN_NODE_TIME, FINALIZE_SCAN_NODE_TIME, GET_SPLITS_TIME,
GET_PARTITIONS_TIME,
+ GET_PARTITION_FILES_TIME, CREATE_SCAN_RANGE_TIME, SCHEDULE_TIME,
FETCH_RESULT_TIME,
+ WRITE_RESULT_TIME, WAIT_FETCH_RESULT_TIME);
+
+ public static ImmutableMap<String, Integer>
EXECUTION_SUMMARY_KEYS_IDENTATION = ImmutableMap.of();
+
+ {
+ ImmutableMap.Builder builder = new ImmutableMap.Builder();
+ builder.put(JOIN_REORDER_TIME, 1);
+ builder.put(CREATE_SINGLE_NODE_TIME, 1);
+ builder.put(QUERY_DISTRIBUTED_TIME, 1);
+ builder.put(INIT_SCAN_NODE_TIME, 1);
+ builder.put(FINALIZE_SCAN_NODE_TIME, 1);
+ builder.put(GET_SPLITS_TIME, 2);
+ builder.put(GET_PARTITIONS_TIME, 3);
+ builder.put(GET_PARTITION_FILES_TIME, 3);
+ builder.put(CREATE_SCAN_RANGE_TIME, 2);
+ EXECUTION_SUMMARY_KEYS_IDENTATION = builder.build();
+ }
private RuntimeProfile summaryProfile;
private RuntimeProfile executionSummaryProfile;
@@ -81,6 +107,15 @@ public class SummaryProfile {
private long queryCreateSingleNodeFinishTime = -1;
// Create distribute plan end time
private long queryDistributedFinishTime = -1;
+ private long initScanNodeStartTime = -1;
+ private long initScanNodeFinishTime = -1;
+ private long finalizeScanNodeStartTime = -1;
+ private long finalizeScanNodeFinishTime = -1;
+ private long getSplitsStartTime = -1;
+ private long getPartitionsFinishTime = -1;
+ private long getPartitionFilesFinishTime = -1;
+ private long getSplitsFinishTime = -1;
+ private long createScanRangeFinishTime = -1;
// Plan end time
private long queryPlanFinishTime = -1;
// Fragment schedule and send end time
@@ -123,10 +158,16 @@ public class SummaryProfile {
private void updateExecutionSummaryProfile() {
executionSummaryProfile.addInfoString(ANALYSIS_TIME,
getPrettyQueryAnalysisFinishTime());
+ executionSummaryProfile.addInfoString(PLAN_TIME,
getPrettyQueryPlanFinishTime());
executionSummaryProfile.addInfoString(JOIN_REORDER_TIME,
getPrettyQueryJoinReorderFinishTime());
executionSummaryProfile.addInfoString(CREATE_SINGLE_NODE_TIME,
getPrettyCreateSingleNodeFinishTime());
executionSummaryProfile.addInfoString(QUERY_DISTRIBUTED_TIME,
getPrettyQueryDistributedFinishTime());
- executionSummaryProfile.addInfoString(PLAN_TIME,
getPrettyQueryPlanFinishTime());
+ executionSummaryProfile.addInfoString(INIT_SCAN_NODE_TIME,
getPrettyInitScanNodeTime());
+ executionSummaryProfile.addInfoString(FINALIZE_SCAN_NODE_TIME,
getPrettyFinalizeScanNodeTime());
+ executionSummaryProfile.addInfoString(GET_SPLITS_TIME,
getPrettyGetSplitsTime());
+ executionSummaryProfile.addInfoString(GET_PARTITIONS_TIME,
getPrettyGetPartitionsTime());
+ executionSummaryProfile.addInfoString(GET_PARTITION_FILES_TIME,
getPrettyGetPartitionFilesTime());
+ executionSummaryProfile.addInfoString(CREATE_SCAN_RANGE_TIME,
getPrettyCreateScanRangeTime());
executionSummaryProfile.addInfoString(SCHEDULE_TIME,
getPrettyQueryScheduleFinishTime());
executionSummaryProfile.addInfoString(FETCH_RESULT_TIME,
RuntimeProfile.printCounter(queryFetchResultConsumeTime,
TUnit.TIME_MS));
@@ -151,6 +192,42 @@ public class SummaryProfile {
this.queryCreateSingleNodeFinishTime = TimeUtils.getStartTimeMs();
}
+ public void setInitScanNodeStartTime() {
+ this.initScanNodeStartTime = TimeUtils.getStartTimeMs();
+ }
+
+ public void setInitScanNodeFinishTime() {
+ this.initScanNodeFinishTime = TimeUtils.getStartTimeMs();
+ }
+
+ public void setFinalizeScanNodeStartTime() {
+ this.finalizeScanNodeStartTime = TimeUtils.getStartTimeMs();
+ }
+
+ public void setFinalizeScanNodeFinishTime() {
+ this.finalizeScanNodeFinishTime = TimeUtils.getStartTimeMs();
+ }
+
+ public void setGetSplitsStartTime() {
+ this.getSplitsStartTime = TimeUtils.getStartTimeMs();
+ }
+
+ public void setGetPartitionsFinishTime() {
+ this.getPartitionsFinishTime = TimeUtils.getStartTimeMs();
+ }
+
+ public void setGetPartitionFilesFinishTime() {
+ this.getPartitionFilesFinishTime = TimeUtils.getStartTimeMs();
+ }
+
+ public void setGetSplitsFinishTime() {
+ this.getSplitsFinishTime = TimeUtils.getStartTimeMs();
+ }
+
+ public void setCreateScanRangeFinishTime() {
+ this.createScanRangeFinishTime = TimeUtils.getStartTimeMs();
+ }
+
public void setQueryDistributedFinishTime() {
this.queryDistributedFinishTime = TimeUtils.getStartTimeMs();
}
@@ -304,6 +381,48 @@ public class SummaryProfile {
return RuntimeProfile.printCounter(queryDistributedFinishTime -
queryCreateSingleNodeFinishTime, TUnit.TIME_MS);
}
+ private String getPrettyInitScanNodeTime() {
+ if (initScanNodeStartTime == -1 || initScanNodeFinishTime == -1) {
+ return "N/A";
+ }
+ return RuntimeProfile.printCounter(initScanNodeFinishTime -
initScanNodeStartTime, TUnit.TIME_MS);
+ }
+
+ private String getPrettyFinalizeScanNodeTime() {
+ if (finalizeScanNodeFinishTime == -1 || finalizeScanNodeStartTime ==
-1) {
+ return "N/A";
+ }
+ return RuntimeProfile.printCounter(finalizeScanNodeFinishTime -
finalizeScanNodeStartTime, TUnit.TIME_MS);
+ }
+
+ private String getPrettyGetSplitsTime() {
+ if (getSplitsFinishTime == -1 || getSplitsStartTime == -1) {
+ return "N/A";
+ }
+ return RuntimeProfile.printCounter(getSplitsFinishTime -
getSplitsStartTime, TUnit.TIME_MS);
+ }
+
+ private String getPrettyGetPartitionsTime() {
+ if (getSplitsStartTime == -1 || getPartitionsFinishTime == -1) {
+ return "N/A";
+ }
+ return RuntimeProfile.printCounter(getPartitionsFinishTime -
getSplitsStartTime, TUnit.TIME_MS);
+ }
+
+ private String getPrettyGetPartitionFilesTime() {
+ if (getPartitionsFinishTime == -1 || getPartitionFilesFinishTime ==
-1) {
+ return "N/A";
+ }
+ return RuntimeProfile.printCounter(getPartitionFilesFinishTime -
getPartitionsFinishTime, TUnit.TIME_MS);
+ }
+
+ private String getPrettyCreateScanRangeTime() {
+ if (getSplitsFinishTime == -1 || createScanRangeFinishTime == -1) {
+ return "N/A";
+ }
+ return RuntimeProfile.printCounter(createScanRangeFinishTime -
getSplitsFinishTime, TUnit.TIME_MS);
+ }
+
private String getPrettyQueryPlanFinishTime() {
if (queryAnalysisFinishTime == -1 || queryPlanFinishTime == -1) {
return "N/A";
diff --git
a/fe/fe-core/src/main/java/org/apache/doris/common/util/RuntimeProfile.java
b/fe/fe-core/src/main/java/org/apache/doris/common/util/RuntimeProfile.java
index 084b69f135..fea16c2f75 100644
--- a/fe/fe-core/src/main/java/org/apache/doris/common/util/RuntimeProfile.java
+++ b/fe/fe-core/src/main/java/org/apache/doris/common/util/RuntimeProfile.java
@@ -19,6 +19,7 @@ package org.apache.doris.common.util;
import org.apache.doris.common.Pair;
import org.apache.doris.common.Reference;
+import org.apache.doris.common.profile.SummaryProfile;
import org.apache.doris.thrift.TCounter;
import org.apache.doris.thrift.TRuntimeProfileNode;
import org.apache.doris.thrift.TRuntimeProfileTree;
@@ -268,7 +269,13 @@ public class RuntimeProfile {
infoStringsLock.readLock().lock();
try {
for (String key : this.infoStringsDisplayOrder) {
- builder.append(prefix).append(" - ").append(key).append(": ")
+ builder.append(prefix);
+ if
(SummaryProfile.EXECUTION_SUMMARY_KEYS_IDENTATION.containsKey(key)) {
+ for (int i = 0; i <
SummaryProfile.EXECUTION_SUMMARY_KEYS_IDENTATION.get(key); i++) {
+ builder.append(" ");
+ }
+ }
+ builder.append(" - ").append(key).append(": ")
.append(this.infoStrings.get(key)).append("\n");
}
} finally {
@@ -493,11 +500,9 @@ public class RuntimeProfile {
infoStringsLock.writeLock().lock();
try {
String target = this.infoStrings.get(key);
+ this.infoStrings.put(key, value);
if (target == null) {
- this.infoStrings.put(key, value);
this.infoStringsDisplayOrder.add(key);
- } else {
- this.infoStrings.put(key, value);
}
} finally {
infoStringsLock.writeLock().unlock();
diff --git
a/fe/fe-core/src/main/java/org/apache/doris/planner/external/FileQueryScanNode.java
b/fe/fe-core/src/main/java/org/apache/doris/planner/external/FileQueryScanNode.java
index 5b6238bf14..d6ec536d5f 100644
---
a/fe/fe-core/src/main/java/org/apache/doris/planner/external/FileQueryScanNode.java
+++
b/fe/fe-core/src/main/java/org/apache/doris/planner/external/FileQueryScanNode.java
@@ -102,8 +102,14 @@ public abstract class FileQueryScanNode extends
FileScanNode {
@Override
public void init(Analyzer analyzer) throws UserException {
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setInitScanNodeStartTime();
+ }
super.init(analyzer);
doInitialize();
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setInitScanNodeFinishTime();
+ }
}
/**
@@ -111,7 +117,13 @@ public abstract class FileQueryScanNode extends
FileScanNode {
*/
@Override
public void init() throws UserException {
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setInitScanNodeStartTime();
+ }
doInitialize();
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setInitScanNodeFinishTime();
+ }
}
// Init scan provider and schema related params.
@@ -194,8 +206,14 @@ public abstract class FileQueryScanNode extends
FileScanNode {
// Create scan range locations and the statistics.
protected void doFinalize() throws UserException {
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setFinalizeScanNodeStartTime();
+ }
createScanRangeLocations();
updateRequiredSlots();
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setFinalizeScanNodeFinishTime();
+ }
}
private void setColumnPositionMapping()
@@ -229,7 +247,13 @@ public abstract class FileQueryScanNode extends
FileScanNode {
@Override
public void createScanRangeLocations() throws UserException {
long start = System.currentTimeMillis();
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setGetSplitsStartTime();
+ }
List<Split> inputSplits = getSplits();
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setGetSplitsFinishTime();
+ }
this.inputSplitsNum = inputSplits.size();
if (inputSplits.isEmpty()) {
return;
@@ -312,6 +336,9 @@ public abstract class FileQueryScanNode extends
FileScanNode {
scanRangeLocations.add(curLocations);
this.totalFileSize += fileSplit.getLength();
}
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setCreateScanRangeFinishTime();
+ }
LOG.debug("create #{} ScanRangeLocations cost: {} ms",
scanRangeLocations.size(), (System.currentTimeMillis() -
start));
}
diff --git
a/fe/fe-core/src/main/java/org/apache/doris/planner/external/HiveScanNode.java
b/fe/fe-core/src/main/java/org/apache/doris/planner/external/HiveScanNode.java
index d629914775..1fe115a0b9 100644
---
a/fe/fe-core/src/main/java/org/apache/doris/planner/external/HiveScanNode.java
+++
b/fe/fe-core/src/main/java/org/apache/doris/planner/external/HiveScanNode.java
@@ -150,7 +150,12 @@ public class HiveScanNode extends FileQueryScanNode {
ListPartitionItem listPartitionItem = (ListPartitionItem)
idToPartitionItem.get(id);
partitionValuesList.add(listPartitionItem.getItems().get(0).getPartitionValuesAsStringList());
}
- return cache.getAllPartitions(hmsTable.getDbName(),
hmsTable.getName(), partitionValuesList);
+ List<HivePartition> allPartitions =
+ cache.getAllPartitions(hmsTable.getDbName(),
hmsTable.getName(), partitionValuesList);
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setGetPartitionsFinishTime();
+ }
+ return allPartitions;
} else {
// unpartitioned table, create a dummy partition to save location
and inputformat,
// so that we can unify the interface.
@@ -159,6 +164,9 @@ public class HiveScanNode extends FileQueryScanNode {
hmsTable.getRemoteTable().getSd().getLocation(), null);
this.totalPartitionNum = 1;
this.readPartitionNum = 1;
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setGetPartitionsFinishTime();
+ }
return Lists.newArrayList(dummyPartition);
}
}
@@ -191,6 +199,9 @@ public class HiveScanNode extends FileQueryScanNode {
} else {
fileCaches = cache.getFilesByPartitions(partitions,
useSelfSplitter);
}
+ if (ConnectContext.get().getExecutor() != null) {
+
ConnectContext.get().getExecutor().getSummaryProfile().setGetPartitionFilesFinishTime();
+ }
for (HiveMetaStoreCache.FileCacheValue fileCacheValue : fileCaches) {
// This if branch is to support old splitter, will remove later.
if (fileCacheValue.getSplits() != null) {
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscr...@doris.apache.org
For additional commands, e-mail: commits-h...@doris.apache.org
