show process time when execute explain plan in nereids

924060929 · Feb 23, 2024 · f94013c · f94013c
1 parent 176be48
commit f94013c
Show file tree

Hide file tree

Showing 6 changed files with 85 additions and 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
@@ -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 <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));
+        }
+    }
 }
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
@@ -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<PlannerHook> 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<Hint> 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
@@ -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
@@ -44,6 +44,7 @@ public class LogicalPlanAdapter extends StatementBase implements Queriable {
     private List<Expr> resultExprs;
     private ArrayList<String> colLabels;
     private List<String> 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
@@ -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<StatementBase> parseSQL(String sql, SessionVariable sessionVariable)
      * ParseSQL with logicalPlanBuilder.
      */
     public List<StatementBase> parseSQL(String originStr, @Nullable LogicalPlanBuilder logicalPlanBuilder) {
-        List<Pair<LogicalPlan, StatementContext>> logicalPlans = parseMultiple(originStr, logicalPlanBuilder);
+        Pair<List<Pair<LogicalPlan, StatementContext>>, Long> astAndParseTime = TimeUtils.timer(
+                () -> parseMultiple(originStr, logicalPlanBuilder));
+        List<Pair<LogicalPlan, StatementContext>> logicalPlans = astAndParseTime.first;
         List<StatementBase> statementBases = Lists.newArrayList();
         for (Pair<LogicalPlan, StatementContext> 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
@@ -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);