From f94013ce8f5724c4a43632ae4092c5020279fb77 Mon Sep 17 00:00:00 2001 From: 924060929 <924060929@qq.com> Date: Fri, 23 Feb 2024 18:03:25 +0800 Subject: [PATCH] show process time when execute explain plan in nereids --- .../apache/doris/common/util/TimeUtils.java | 23 ++++++++++ .../apache/doris/nereids/NereidsPlanner.java | 44 ++++++++++++++----- .../doris/nereids/StatementContext.java | 11 +++++ .../nereids/glue/LogicalPlanAdapter.java | 9 ++++ .../doris/nereids/parser/NereidsParser.java | 9 +++- .../org/apache/doris/qe/StmtExecutor.java | 4 +- 6 files changed, 85 insertions(+), 15 deletions(-) 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..a7ec766a68a30ed 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.util.TimeUtils; import org.apache.doris.nereids.CascadesContext.Lock; import org.apache.doris.nereids.exceptions.AnalysisException; import org.apache.doris.nereids.glue.LogicalPlanAdapter; @@ -74,6 +75,7 @@ import java.util.List; import java.util.Optional; import java.util.stream.Collectors; +import javax.annotation.Nullable; /** * Planner to do query plan in Nereids. @@ -90,6 +92,12 @@ public class NereidsPlanner extends Planner { private Plan rewrittenPlan; private Plan optimizedPlan; private PhysicalPlan physicalPlan; + @Nullable + private Long parseTime; + private long analyzeTime; + private long rewriteTime; + private long optimizeTime; + // The cost of optimized plan private double cost = 0; private List hooks = new ArrayList<>(); @@ -110,6 +118,7 @@ public void plan(StatementBase queryStmt, org.apache.doris.thrift.TQueryOptions } LogicalPlanAdapter logicalPlanAdapter = (LogicalPlanAdapter) queryStmt; + parseTime = statementContext.getParseTime(); ExplainLevel explainLevel = getExplainLevel(queryStmt.getExplainOptions()); @@ -271,7 +280,7 @@ private void analyze() { if (LOG.isDebugEnabled()) { LOG.debug("Start analyze plan"); } - cascadesContext.newAnalyzer().analyze(); + analyzeTime = TimeUtils.timer(() -> cascadesContext.newAnalyzer().analyze()); getHooks().forEach(hook -> hook.afterAnalyze(this)); NereidsTracer.logImportantTime("EndAnalyzePlan"); if (LOG.isDebugEnabled()) { @@ -286,7 +295,7 @@ private void rewrite() { if (LOG.isDebugEnabled()) { LOG.debug("Start rewrite plan"); } - Rewriter.getWholeTreeRewriter(cascadesContext).execute(); + rewriteTime = TimeUtils.timer(() -> Rewriter.getWholeTreeRewriter(cascadesContext).execute()); NereidsTracer.logImportantTime("EndRewritePlan"); if (LOG.isDebugEnabled()) { LOG.debug("End rewrite plan"); @@ -298,7 +307,7 @@ private void optimize() { if (LOG.isDebugEnabled()) { LOG.debug("Start optimize plan"); } - new Optimizer(cascadesContext).execute(); + optimizeTime = TimeUtils.timer(() -> new Optimizer(cascadesContext).execute()); NereidsTracer.logImportantTime("EndOptimizePlan"); if (LOG.isDebugEnabled()) { LOG.debug("End optimize plan"); @@ -404,37 +413,48 @@ public String getHintExplainString(List hints) { public String getExplainString(ExplainOptions explainOptions) { ExplainLevel explainLevel = getExplainLevel(explainOptions); String plan = ""; + String parseTimeString = ""; switch (explainLevel) { case PARSED_PLAN: - plan = parsedPlan.treeString(); + if (parseTime != null) { + parseTimeString = "(time: " + parseTime + " ms)"; + } + plan = "========== PARSED PLAN " + parseTimeString + " ==========\n" + + parsedPlan.treeString(); break; case ANALYZED_PLAN: - plan = analyzedPlan.treeString(); + plan = "========== ANALYZED PLAN (time: " + analyzeTime + " ms) ==========\n" + + analyzedPlan.treeString(); break; case REWRITTEN_PLAN: - plan = rewrittenPlan.treeString(); + plan = "========== REWRITTEN PLAN (time: " + rewriteTime + " ms) ==========\n" + + rewrittenPlan.treeString(); break; case OPTIMIZED_PLAN: - plan = "cost = " + cost + "\n" + optimizedPlan.treeString(); + plan = "========== OPTIMIZED PLAN (time: " + optimizeTime + " ms) ==========\n" + + "cost = " + cost + "\n" + optimizedPlan.treeString(); break; case SHAPE_PLAN: plan = optimizedPlan.shape(""); break; case MEMO_PLAN: plan = cascadesContext.getMemo().toString() - + "\n\n========== OPTIMIZED PLAN ==========\n" + + "\n\n========== OPTIMIZED PLAN (time: " + optimizeTime + " ms) ==========\n" + optimizedPlan.treeString() + "\n\n========== MATERIALIZATIONS ==========\n" + MaterializationContext.toString(cascadesContext.getMaterializationContexts()); break; case ALL_PLAN: - plan = "========== PARSED PLAN ==========\n" + if (parseTime != null) { + parseTimeString = "(time: " + parseTime + " ms)"; + } + plan = "========== PARSED PLAN " + parseTimeString + " ==========\n" + parsedPlan.treeString() + "\n\n" - + "========== ANALYZED PLAN ==========\n" + + "========== ANALYZED PLAN (time: " + analyzeTime + " ms) ==========\n" + analyzedPlan.treeString() + "\n\n" - + "========== REWRITTEN PLAN ==========\n" + + "========== REWRITTEN PLAN (time: " + rewriteTime + " ms) ==========\n" + rewrittenPlan.treeString() + "\n\n" - + "========== OPTIMIZED PLAN ==========\n" + + "========== OPTIMIZED PLAN (time: " + optimizeTime + " ms) ==========\n" + optimizedPlan.treeString(); break; default: diff --git a/fe/fe-core/src/main/java/org/apache/doris/nereids/StatementContext.java b/fe/fe-core/src/main/java/org/apache/doris/nereids/StatementContext.java index 5c894fd46ef2b90..cb50b189cc4af0f 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/nereids/StatementContext.java +++ b/fe/fe-core/src/main/java/org/apache/doris/nereids/StatementContext.java @@ -52,6 +52,7 @@ import java.util.List; import java.util.Map; import java.util.Set; +import javax.annotation.Nullable; import javax.annotation.concurrent.GuardedBy; /** @@ -70,6 +71,8 @@ public class StatementContext { // NOTICE: we set the plan parsed by DorisParser to parsedStatement and if the plan is command, create a // LogicalPlanAdapter with the logical plan in the command. private StatementBase parsedStatement; + @Nullable + private Long parseTime; private ColumnAliasGenerator columnAliasGenerator; private int joinCount = 0; @@ -339,4 +342,12 @@ public boolean isHasUnknownColStats() { public void setHasUnknownColStats(boolean hasUnknownColStats) { this.hasUnknownColStats = hasUnknownColStats; } + + public Long getParseTime() { + return parseTime; + } + + public void setParseTime(Long parseTime) { + this.parseTime = parseTime; + } } diff --git a/fe/fe-core/src/main/java/org/apache/doris/nereids/glue/LogicalPlanAdapter.java b/fe/fe-core/src/main/java/org/apache/doris/nereids/glue/LogicalPlanAdapter.java index 4d9b70c455efa9d..e4aeb3e83d93d6b 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/nereids/glue/LogicalPlanAdapter.java +++ b/fe/fe-core/src/main/java/org/apache/doris/nereids/glue/LogicalPlanAdapter.java @@ -44,6 +44,7 @@ public class LogicalPlanAdapter extends StatementBase implements Queriable { private List resultExprs; private ArrayList colLabels; private List viewDdlSqls; + private Long parseTime; public LogicalPlanAdapter(LogicalPlan logicalPlan, StatementContext statementContext) { this.logicalPlan = logicalPlan; @@ -105,6 +106,14 @@ public StatementContext getStatementContext() { return statementContext; } + public Long getParseTime() { + return parseTime; + } + + public void setParseTime(Long parseTime) { + this.parseTime = parseTime; + } + public String toDigest() { // TODO: generate real digest return ""; diff --git a/fe/fe-core/src/main/java/org/apache/doris/nereids/parser/NereidsParser.java b/fe/fe-core/src/main/java/org/apache/doris/nereids/parser/NereidsParser.java index 0ee3f5d068f9ce5..b69867e53239a66 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/nereids/parser/NereidsParser.java +++ b/fe/fe-core/src/main/java/org/apache/doris/nereids/parser/NereidsParser.java @@ -20,6 +20,7 @@ import org.apache.doris.analysis.StatementBase; import org.apache.doris.catalog.Env; import org.apache.doris.common.Pair; +import org.apache.doris.common.util.TimeUtils; import org.apache.doris.nereids.DorisLexer; import org.apache.doris.nereids.DorisParser; import org.apache.doris.nereids.StatementContext; @@ -75,10 +76,14 @@ public List parseSQL(String sql, SessionVariable sessionVariable) * ParseSQL with logicalPlanBuilder. */ public List parseSQL(String originStr, @Nullable LogicalPlanBuilder logicalPlanBuilder) { - List> logicalPlans = parseMultiple(originStr, logicalPlanBuilder); + Pair>, Long> astAndParseTime = TimeUtils.timer( + () -> parseMultiple(originStr, logicalPlanBuilder)); + List> logicalPlans = astAndParseTime.first; List statementBases = Lists.newArrayList(); for (Pair parsedPlanToContext : logicalPlans) { - statementBases.add(new LogicalPlanAdapter(parsedPlanToContext.first, parsedPlanToContext.second)); + LogicalPlanAdapter plan = new LogicalPlanAdapter(parsedPlanToContext.first, parsedPlanToContext.second); + plan.setParseTime(astAndParseTime.second); + statementBases.add(plan); } return statementBases; } 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..047e22ee38d114a 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 @@ -274,10 +274,12 @@ public StmtExecutor(ConnectContext ctx, StatementBase parsedStmt) { } this.isProxy = false; if (parsedStmt instanceof LogicalPlanAdapter) { - this.statementContext = ((LogicalPlanAdapter) parsedStmt).getStatementContext(); + LogicalPlanAdapter logicalPlanAdapter = (LogicalPlanAdapter) parsedStmt; + this.statementContext = logicalPlanAdapter.getStatementContext(); this.statementContext.setConnectContext(ctx); this.statementContext.setOriginStatement(originStmt); this.statementContext.setParsedStatement(parsedStmt); + this.statementContext.setParseTime(logicalPlanAdapter.getParseTime()); } else { this.statementContext = new StatementContext(ctx, originStmt); this.statementContext.setParsedStatement(parsedStmt);