This is an automated email from the ASF dual-hosted git repository. kxiao pushed a commit to branch branch-2.0 in repository https://gitbox.apache.org/repos/asf/doris.git
commit 864cb9456638618967678c606c6a74335f3e300a Author: Jibing-Li <[email protected]> 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 52887f3ff3..51d027639d 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 { 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: [email protected] For additional commands, e-mail: [email protected]
