database/doris
2
0
Fork 0
Code Issues Pull Requests Actions 3 Packages Projects Releases Wiki Activity

[Improvement](profile)Add init and finalize external scan node time in profile (#21749)

Browse Source 
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
```
This commit is contained in:
Jibing-Li
2023-07-20 20:29:18 +08:00
committed by GitHub
parent 0e8432526e
commit e4ac52b2aa
4 changed files with 169 additions and 7 deletions
Download Patch File Download Diff File Expand all files Collapse all files

123
fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java
View File

@ -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";

13
fe/fe-core/src/main/java/org/apache/doris/common/util/RuntimeProfile.java
View File

@ -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();

27
fe/fe-core/src/main/java/org/apache/doris/planner/external/FileQueryScanNode.java vendored
View File

@ -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));
}

13
fe/fe-core/src/main/java/org/apache/doris/planner/external/HiveScanNode.java vendored
View File

@ -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) {