Skip to content

Commit

Permalink
[Improvement](profile)Add init and finalize external scan node time i…
Browse files Browse the repository at this point in the history 
…n profile. apache#21749
  • Loading branch information
@Jibing-Li @morningman
Jibing-Li authored and morningman committed Jul 13, 2023
1 parent dd2b998 commit 4bc415c
Show file tree
Hide file tree
Showing 4 changed files with 169 additions and 7 deletions.
123 changes: 121 additions & 2 deletions fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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";
Expand All @@ -63,7 +70,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.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;
Expand All @@ -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
Expand Down Expand Up @@ -120,10 +155,16 @@ private void updateSummaryProfile(Map<String, String> 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));
Expand All @@ -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();
}
Expand Down Expand Up @@ -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";
Expand Down
13 changes: 9 additions & 4 deletions fe/fe-core/src/main/java/org/apache/doris/common/util/RuntimeProfile.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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();
Expand Down
27 changes: 27 additions & 0 deletions fe/fe-core/src/main/java/org/apache/doris/planner/external/FileQueryScanNode.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -102,16 +102,28 @@ 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();
}
}

/**
* Init ExternalFileScanNode, ONLY used for Nereids. Should NOT use this function in anywhere else.
*/
@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.
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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<Split> inputSplits = getSplits();
if (ConnectContext.get().getExecutor() != null) {
ConnectContext.get().getExecutor().getSummaryProfile().setGetSplitsFinishTime();
}
this.inputSplitsNum = inputSplits.size();
if (inputSplits.isEmpty()) {
return;
Expand Down Expand Up @@ -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));
}
Expand Down
13 changes: 12 additions & 1 deletion fe/fe-core/src/main/java/org/apache/doris/planner/external/HiveScanNode.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -145,7 +145,12 @@ protected List<HivePartition> 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<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.
Expand All @@ -154,6 +159,9 @@ protected List<HivePartition> 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);
}
}
Expand Down Expand Up @@ -186,6 +194,9 @@ private void getFileSplitByPartitions(HiveMetaStoreCache cache, List<HivePartiti
} 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) {
Expand Down

0 comments on commit 4bc415c

Please sign in to comment.