Skip to content

Commit

Permalink
show process time when execute explain plan in nereids
Browse files Browse the repository at this point in the history
  • Loading branch information
@924060929
924060929 committed Feb 23, 2024
1 parent 10a9689 commit 1a98c8e
Show file tree
Hide file tree
Showing 5 changed files with 89 additions and 18 deletions.
30 changes: 25 additions & 5 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 @@ -75,6 +75,7 @@ public class SummaryProfile {
public static final String GET_PARTITION_VERSION_COUNT = "Get Partition Version Count";
public static final String GET_PARTITION_VERSION_BY_HAS_DATA_COUNT = "Get Partition Version Count (hasData)";

public static final String PARSE_SQL_TIME = "Parse SQL Time";
public static final String NEREIDS_ANALYSIS_TIME = "Nereids Analysis Time";
public static final String NEREIDS_REWRITE_TIME = "Nereids Rewrite Time";
public static final String NEREIDS_OPTIMIZE_TIME = "Nereids Optimize Time";
Expand All @@ -87,7 +88,7 @@ public class SummaryProfile {
START_TIME, END_TIME, TOTAL_TIME, TASK_STATE, USER, DEFAULT_DB, SQL_STATEMENT);

public static final ImmutableList<String> EXECUTION_SUMMARY_KEYS = ImmutableList.of(
NEREIDS_ANALYSIS_TIME, NEREIDS_REWRITE_TIME, NEREIDS_OPTIMIZE_TIME, NEREIDS_TRANSLATE_TIME,
PARSE_SQL_TIME, NEREIDS_ANALYSIS_TIME, NEREIDS_REWRITE_TIME, NEREIDS_OPTIMIZE_TIME, NEREIDS_TRANSLATE_TIME,
WORKLOAD_GROUP, ANALYSIS_TIME,
PLAN_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,
Expand Down Expand Up @@ -120,6 +121,8 @@ public class SummaryProfile {
private RuntimeProfile summaryProfile;
private RuntimeProfile executionSummaryProfile;

private long parseSqlStartTime = -1;
private long parseSqlFinishTime = -1;
private long nereidsAnalysisFinishTime = -1;
private long nereidsRewriteFinishTime = -1;
private long nereidsOptimizeFinishTime = -1;
Expand Down Expand Up @@ -204,6 +207,8 @@ private void updateSummaryProfile(Map<String, String> infos) {
}

private void updateExecutionSummaryProfile() {
executionSummaryProfile.addInfoString(PARSE_SQL_TIME, getPrettyParseSqlTime());
executionSummaryProfile.addInfoString(NEREIDS_ANALYSIS_TIME, getPrettyNereidsAnalysisTime());
executionSummaryProfile.addInfoString(NEREIDS_ANALYSIS_TIME, getPrettyNereidsAnalysisTime());
executionSummaryProfile.addInfoString(NEREIDS_REWRITE_TIME, getPrettyNereidsRewriteTime());
executionSummaryProfile.addInfoString(NEREIDS_OPTIMIZE_TIME, getPrettyNereidsOptimizeTime());
Expand Down Expand Up @@ -234,6 +239,14 @@ private void updateExecutionSummaryProfile() {
}
}

public void setParseSqlStartTime(long parseSqlStartTime) {
this.parseSqlStartTime = parseSqlStartTime;
}

public void setParseSqlFinishTime(long parseSqlFinishTime) {
this.parseSqlFinishTime = parseSqlFinishTime;
}

public void setNereidsAnalysisTime() {
this.nereidsAnalysisFinishTime = TimeUtils.getStartTimeMs();
}
Expand Down Expand Up @@ -441,28 +454,35 @@ public Map<String, String> build() {
}
}

private String getPrettyNereidsAnalysisTime() {
public String getPrettyParseSqlTime() {
if (parseSqlStartTime == -1 || parseSqlFinishTime == -1) {
return "N/A";
}
return RuntimeProfile.printCounter(parseSqlFinishTime - parseSqlStartTime, TUnit.TIME_MS);
}

public String getPrettyNereidsAnalysisTime() {
if (nereidsAnalysisFinishTime == -1 || queryAnalysisFinishTime == -1) {
return "N/A";
}
return RuntimeProfile.printCounter(nereidsAnalysisFinishTime - queryBeginTime, TUnit.TIME_MS);
}

private String getPrettyNereidsRewriteTime() {
public String getPrettyNereidsRewriteTime() {
if (nereidsRewriteFinishTime == -1 || nereidsAnalysisFinishTime == -1) {
return "N/A";
}
return RuntimeProfile.printCounter(nereidsRewriteFinishTime - nereidsAnalysisFinishTime, TUnit.TIME_MS);
}

private String getPrettyNereidsOptimizeTime() {
public String getPrettyNereidsOptimizeTime() {
if (nereidsOptimizeFinishTime == -1 || nereidsRewriteFinishTime == -1) {
return "N/A";
}
return RuntimeProfile.printCounter(nereidsOptimizeFinishTime - nereidsRewriteFinishTime, TUnit.TIME_MS);
}

private String getPrettyNereidsTranslateTime() {
public String getPrettyNereidsTranslateTime() {
if (nereidsTranslateFinishTime == -1 || nereidsOptimizeFinishTime == -1) {
return "N/A";
}
Expand Down
23 changes: 23 additions & 0 deletions fe/fe-core/src/main/java/org/apache/doris/common/util/TimeUtils.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,10 +24,13 @@
import org.apache.doris.common.ErrorCode;
import org.apache.doris.common.ErrorReport;
import org.apache.doris.common.FeConstants;
import org.apache.doris.common.NereidsException;
import org.apache.doris.common.Pair;
import org.apache.doris.qe.ConnectContext;
import org.apache.doris.qe.VariableMgr;

import com.google.common.base.Preconditions;
import com.google.common.base.Throwables;
import com.google.common.collect.ImmutableMap;
import com.google.common.collect.Maps;
import org.apache.logging.log4j.LogManager;
Expand All @@ -47,6 +50,7 @@
import java.util.Date;
import java.util.Map;
import java.util.TimeZone;
import java.util.concurrent.Callable;
import java.util.function.Function;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
Expand Down Expand Up @@ -335,4 +339,23 @@ private static String formatDateStr(String dateStr) {
Integer.parseInt(parts[4]), Integer.parseInt(parts[5])) : "");
}

public static long timer(Runnable task) {
return timer(() -> {
task.run();
return null;
}).second;
}

public static <R> Pair<R, Long> timer(Callable<R> task) {
long startTime = System.currentTimeMillis();
try {
R result = task.call();
long finishTime = System.currentTimeMillis();
return Pair.of(result, finishTime - startTime);
} catch (Throwable t) {
Throwables.propagateIfInstanceOf(t, RuntimeException.class);
throw new NereidsException(t.getMessage(),
t instanceof Exception ? (Exception) t : new IllegalStateException(t.getMessage(), t));
}
}
}
48 changes: 36 additions & 12 deletions fe/fe-core/src/main/java/org/apache/doris/nereids/NereidsPlanner.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@
import org.apache.doris.catalog.MTMV;
import org.apache.doris.common.NereidsException;
import org.apache.doris.common.Pair;
import org.apache.doris.common.profile.SummaryProfile;
import org.apache.doris.nereids.CascadesContext.Lock;
import org.apache.doris.nereids.exceptions.AnalysisException;
import org.apache.doris.nereids.glue.LogicalPlanAdapter;
Expand Down Expand Up @@ -73,6 +74,7 @@
import java.util.Collections;
import java.util.List;
import java.util.Optional;
import java.util.function.Function;
import java.util.stream.Collectors;

/**
Expand Down Expand Up @@ -212,17 +214,17 @@ public Plan plan(LogicalPlan plan, PhysicalProperties requireProperties, Explain

// rule-based optimize
rewrite();
if (statementContext.getConnectContext().getExecutor() != null) {
statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsRewriteTime();
}

if (explainLevel == ExplainLevel.REWRITTEN_PLAN || explainLevel == ExplainLevel.ALL_PLAN) {
rewrittenPlan = cascadesContext.getRewritePlan();
if (explainLevel == ExplainLevel.REWRITTEN_PLAN) {
return rewrittenPlan;
}
}

if (statementContext.getConnectContext().getExecutor() != null) {
statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsRewriteTime();
}

optimize();
if (statementContext.getConnectContext().getExecutor() != null) {
statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsOptimizeTime();
Expand Down Expand Up @@ -422,19 +424,23 @@ public String getExplainString(ExplainOptions explainOptions) {
break;
case MEMO_PLAN:
plan = cascadesContext.getMemo().toString()
+ "\n\n========== OPTIMIZED PLAN ==========\n"
+ optimizedPlan.treeString()
+ "\n\n========== MATERIALIZATIONS ==========\n"
+ MaterializationContext.toString(cascadesContext.getMaterializationContexts());
+ "\n\n========== OPTIMIZED PLAN ==========\n"
+ optimizedPlan.treeString()
+ "\n\n========== MATERIALIZATIONS ==========\n"
+ MaterializationContext.toString(cascadesContext.getMaterializationContexts());
break;
case ALL_PLAN:
plan = "========== PARSED PLAN ==========\n"
plan = "========== PARSED PLAN "
+ getTimeMetricString(SummaryProfile::getPrettyParseSqlTime) + " ==========\n"
+ parsedPlan.treeString() + "\n\n"
+ "========== ANALYZED PLAN ==========\n"
+ "========== ANALYZED PLAN "
+ getTimeMetricString(SummaryProfile::getPrettyNereidsAnalysisTime) + " ==========\n"
+ analyzedPlan.treeString() + "\n\n"
+ "========== REWRITTEN PLAN ==========\n"
+ "========== REWRITTEN PLAN "
+ getTimeMetricString(SummaryProfile::getPrettyNereidsRewriteTime) + "==========\n"
+ rewrittenPlan.treeString() + "\n\n"
+ "========== OPTIMIZED PLAN ==========\n"
+ "========== OPTIMIZED PLAN "
+ getTimeMetricString(SummaryProfile::getPrettyNereidsOptimizeTime) + " ==========\n"
+ optimizedPlan.treeString();
break;
default:
Expand Down Expand Up @@ -564,4 +570,22 @@ public List<PlannerHook> getHooks() {
public void addHook(PlannerHook hook) {
this.hooks.add(hook);
}

private String getTimeMetricString(Function<SummaryProfile, String> profileSupplier) {
return getProfile(summaryProfile -> {
String metricString = profileSupplier.apply(summaryProfile);
return (metricString == null || "N/A".equals(metricString)) ? "" : "(time: " + metricString + ")";
}, "");
}

private <T> T getProfile(Function<SummaryProfile, T> profileSupplier, T defaultMetric) {
T metric = null;
if (statementContext.getConnectContext().getExecutor() != null) {
SummaryProfile summaryProfile = statementContext.getConnectContext().getExecutor().getSummaryProfile();
if (summaryProfile != null) {
metric = profileSupplier.apply(summaryProfile);
}
}
return metric == null ? defaultMetric : metric;
}
}
4 changes: 4 additions & 0 deletions fe/fe-core/src/main/java/org/apache/doris/qe/ConnectProcessor.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -197,6 +197,7 @@ public void executeQuery(MysqlCommand mysqlCommand, String originStmt) throws Ex

List<StatementBase> stmts = null;
Exception nereidsParseException = null;
long parseSqlStartTime = System.currentTimeMillis();
// Nereids do not support prepare and execute now, so forbid prepare command, only process query command
if (mysqlCommand == MysqlCommand.COM_QUERY && ctx.getSessionVariable().isEnableNereidsPlanner()) {
try {
Expand Down Expand Up @@ -241,6 +242,7 @@ public void executeQuery(MysqlCommand mysqlCommand, String originStmt) throws Ex
LOG.warn("Try to parse multi origSingleStmt failed, originStmt: \"{}\"", convertedStmt);
}
}
long parseSqlFinishTime = System.currentTimeMillis();

boolean usingOrigSingleStmt = origSingleStmtList != null && origSingleStmtList.size() == stmts.size();
for (int i = 0; i < stmts.size(); ++i) {
Expand All @@ -255,6 +257,8 @@ public void executeQuery(MysqlCommand mysqlCommand, String originStmt) throws Ex
parsedStmt.setOrigStmt(new OriginStatement(convertedStmt, i));
parsedStmt.setUserInfo(ctx.getCurrentUserIdentity());
executor = new StmtExecutor(ctx, parsedStmt);
executor.getProfile().getSummaryProfile().setParseSqlStartTime(parseSqlStartTime);
executor.getProfile().getSummaryProfile().setParseSqlFinishTime(parseSqlFinishTime);
ctx.setExecutor(executor);

try {
Expand Down
2 changes: 1 addition & 1 deletion fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -637,7 +637,7 @@ private void executeByNereids(TUniqueId queryId) throws Exception {
}
context.getState().setError(ErrorCode.ERR_UNKNOWN_ERROR, e.getMessage());
throw new NereidsException("Command (" + originStmt.originStmt + ") process failed.",
new AnalysisException(e.getMessage(), e));
new AnalysisException(e.getMessage() == null ? e.toString() : e.getMessage(), e));
}
} else {
context.getState().setIsQuery(true);
Expand Down

0 comments on commit 1a98c8e

Please sign in to comment.