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 573102acb3bfc8..9e24a222cd50d0 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.thrift.TUnit; import com.google.common.collect.ImmutableList; +import com.google.common.collect.ImmutableMap; import com.google.common.collect.Maps; import java.util.Map; @@ -52,6 +53,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"; @@ -63,7 +70,26 @@ public class SummaryProfile { TOTAL_INSTANCES_NUM, INSTANCES_NUM_PER_BE, PARALLEL_FRAGMENT_EXEC_INSTANCE, TRACE_ID); public static final ImmutableList 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 EXECUTION_SUMMARY_KEYS_IDENTATION; + + { + 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; @@ -78,6 +104,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 @@ -120,10 +155,16 @@ private void updateSummaryProfile(Map infos) { 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)); @@ -148,6 +189,42 @@ public void setCreateSingleNodeFinishTime() { 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(); } @@ -286,6 +363,48 @@ private String getPrettyQueryDistributedFinishTime() { 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 084b69f1352685..fea16c2f75b83a 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 @@ 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 void prettyPrint(StringBuilder builder, String prefix) { 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 void addInfoString(String key, String value) { 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 f31a31dfc0b577..397784b661ca34 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 FileQueryScanNode(PlanNodeId id, TupleDescriptor desc, String planNodeNam @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 void init(Analyzer analyzer) throws UserException { */ @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. @@ -199,8 +211,14 @@ public void finalizeForNereids() throws UserException { // 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() @@ -230,7 +248,13 @@ private void setColumnPositionMapping() @Override public void createScanRangeLocations() throws UserException { long start = System.currentTimeMillis(); + if (ConnectContext.get().getExecutor() != null) { + ConnectContext.get().getExecutor().getSummaryProfile().setGetSplitsStartTime(); + } List inputSplits = getSplits(); + if (ConnectContext.get().getExecutor() != null) { + ConnectContext.get().getExecutor().getSummaryProfile().setGetSplitsFinishTime(); + } this.inputSplitsNum = inputSplits.size(); if (inputSplits.isEmpty()) { return; @@ -337,6 +361,9 @@ public void createScanRangeLocations() throws UserException { 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 710fed10ddcec4..bd6f0f17b1efef 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 @@ -145,7 +145,12 @@ protected List getPartitions() throws AnalysisException { ListPartitionItem listPartitionItem = (ListPartitionItem) idToPartitionItem.get(id); partitionValuesList.add(listPartitionItem.getItems().get(0).getPartitionValuesAsStringList()); } - return cache.getAllPartitions(hmsTable.getDbName(), hmsTable.getName(), partitionValuesList); + List 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. @@ -154,6 +159,9 @@ protected List getPartitions() throws AnalysisException { 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); } } @@ -186,6 +194,9 @@ private void getFileSplitByPartitions(HiveMetaStoreCache cache, List