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 90125b079ebcb65..31173c42b081b33 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 @@ -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"; @@ -87,7 +88,7 @@ public class SummaryProfile { START_TIME, END_TIME, TOTAL_TIME, TASK_STATE, USER, DEFAULT_DB, SQL_STATEMENT); public static final ImmutableList 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, @@ -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; @@ -204,6 +207,8 @@ private void updateSummaryProfile(Map 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()); @@ -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(); } @@ -441,28 +454,35 @@ public Map 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"; } diff --git a/fe/fe-core/src/main/java/org/apache/doris/common/util/TimeUtils.java b/fe/fe-core/src/main/java/org/apache/doris/common/util/TimeUtils.java index 0076ddcaf0b1838..d9b5b149c3cb831 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/common/util/TimeUtils.java +++ b/fe/fe-core/src/main/java/org/apache/doris/common/util/TimeUtils.java @@ -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; @@ -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; @@ -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 Pair timer(Callable 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)); + } + } } diff --git a/fe/fe-core/src/main/java/org/apache/doris/nereids/NereidsPlanner.java b/fe/fe-core/src/main/java/org/apache/doris/nereids/NereidsPlanner.java index 156f9abc5ae8d6f..214f29cd85d4e19 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/nereids/NereidsPlanner.java +++ b/fe/fe-core/src/main/java/org/apache/doris/nereids/NereidsPlanner.java @@ -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; @@ -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; /** @@ -212,6 +214,10 @@ 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) { @@ -219,10 +225,6 @@ public Plan plan(LogicalPlan plan, PhysicalProperties requireProperties, Explain } } - if (statementContext.getConnectContext().getExecutor() != null) { - statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsRewriteTime(); - } - optimize(); if (statementContext.getConnectContext().getExecutor() != null) { statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsOptimizeTime(); @@ -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: @@ -564,4 +570,22 @@ public List getHooks() { public void addHook(PlannerHook hook) { this.hooks.add(hook); } + + private String getTimeMetricString(Function profileSupplier) { + return getProfile(summaryProfile -> { + String metricString = profileSupplier.apply(summaryProfile); + return (metricString == null || "N/A".equals(metricString)) ? "" : "(time: " + metricString + ")"; + }, ""); + } + + private T getProfile(Function 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; + } } diff --git a/fe/fe-core/src/main/java/org/apache/doris/qe/ConnectProcessor.java b/fe/fe-core/src/main/java/org/apache/doris/qe/ConnectProcessor.java index 6fd2abbf5f92425..c22d105a8be97f9 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/qe/ConnectProcessor.java +++ b/fe/fe-core/src/main/java/org/apache/doris/qe/ConnectProcessor.java @@ -197,6 +197,7 @@ public void executeQuery(MysqlCommand mysqlCommand, String originStmt) throws Ex List 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 { @@ -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) { @@ -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 { diff --git a/fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java b/fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java index 7879f5ed86f95e3..3be880fe3adc0f3 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java +++ b/fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java @@ -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);