branch-3.1:[fix](nereids) Fix profile lock table,translate summary time err and add ut test #52601

fe/fe-core/src/main/java/org/apache/doris/common/profile/SummaryProfile.java

@@ -533,32 +533,32 @@ public void setParseSqlFinishTime(long parseSqlFinishTime) {
         this.parseSqlFinishTime = parseSqlFinishTime;
     }
 
-    public void setNereidsLockTableFinishTime() {
-        this.nereidsLockTableFinishTime = TimeUtils.getStartTimeMs();
+    public void setNereidsLockTableFinishTime(long lockTableFinishTime) {
+        this.nereidsLockTableFinishTime = lockTableFinishTime;
     }
 
-    public void setNereidsCollectTablePartitionFinishTime() {
-        this.nereidsCollectTablePartitionFinishTime = TimeUtils.getStartTimeMs();
+    public void setNereidsCollectTablePartitionFinishTime(long collectTablePartitionFinishTime) {
+        this.nereidsCollectTablePartitionFinishTime = collectTablePartitionFinishTime;
     }
 
     public void addCollectTablePartitionTime(long elapsed) {
         nereidsCollectTablePartitionTime += elapsed;
     }
 
-    public void setNereidsAnalysisTime() {
-        this.nereidsAnalysisFinishTime = TimeUtils.getStartTimeMs();
+    public void setNereidsAnalysisTime(long analysisFinishTime) {
+        this.nereidsAnalysisFinishTime = analysisFinishTime;
     }
 
-    public void setNereidsRewriteTime() {
-        this.nereidsRewriteFinishTime = TimeUtils.getStartTimeMs();
+    public void setNereidsRewriteTime(long rewriteFinishTime) {
+        this.nereidsRewriteFinishTime = rewriteFinishTime;
     }
 
-    public void setNereidsOptimizeTime() {
-        this.nereidsOptimizeFinishTime = TimeUtils.getStartTimeMs();
+    public void setNereidsOptimizeTime(long optimizeFinishTime) {
+        this.nereidsOptimizeFinishTime = optimizeFinishTime;
     }
 
-    public void setNereidsTranslateTime() {
-        this.nereidsTranslateFinishTime = TimeUtils.getStartTimeMs();
+    public void setNereidsTranslateTime(long translateFinishTime) {
+        this.nereidsTranslateFinishTime = translateFinishTime;
     }
 
     public void setNereidsGarbageCollectionTime(long nereidsGarbageCollectionTime) {
@@ -569,7 +569,7 @@ public void sumBeFoldTime(long beFoldConstTimeOnce) {
         this.nereidsBeFoldConstTime += beFoldConstTimeOnce;
     }
 
-    public void setDistributeTime() {
+    public void setDistributeTime(long distributeFinishTime) {
         this.distributeFinishTime = TimeUtils.getStartTimeMs();
     }
 
@@ -613,18 +613,18 @@ public void setCreateScanRangeFinishTime() {
         this.createScanRangeFinishTime = TimeUtils.getStartTimeMs();
     }
 
-    public void setQueryPlanFinishTime() {
+    public void setQueryPlanFinishTime(long planFinishTime) {
         if (queryPlanFinishTime == -1) {
-            this.queryPlanFinishTime = TimeUtils.getStartTimeMs();
+            this.queryPlanFinishTime = planFinishTime;
         }
     }
 
-    public void setQueryScheduleFinishTime() {
-        this.queryScheduleFinishTime = TimeUtils.getStartTimeMs();
+    public void setQueryScheduleFinishTime(long scheduleFinishTime) {
+        this.queryScheduleFinishTime = scheduleFinishTime;
     }
 
-    public void setQueryFetchResultFinishTime() {
-        this.queryFetchResultFinishTime = TimeUtils.getStartTimeMs();
+    public void setQueryFetchResultFinishTime(long fetchResultFinishTime) {
+        this.queryFetchResultFinishTime = fetchResultFinishTime;
     }
 
     public void setTempStartTime() {

fe/fe-core/src/main/java/org/apache/doris/nereids/NereidsPlanner.java

@@ -30,6 +30,7 @@
 import org.apache.doris.common.UserException;
 import org.apache.doris.common.profile.SummaryProfile;
 import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.common.util.TimeUtils;
 import org.apache.doris.common.util.Util;
 import org.apache.doris.mysql.FieldInfo;
 import org.apache.doris.nereids.exceptions.AnalysisException;
@@ -366,7 +367,8 @@ protected void collectAndLockTable(boolean showPlanProcess) {
             LOG.debug("End collect and lock table");
         }
         if (statementContext.getConnectContext().getExecutor() != null) {
-            statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsLockTableFinishTime();
+            statementContext.getConnectContext().getExecutor().getSummaryProfile()
+                    .setNereidsLockTableFinishTime(TimeUtils.getStartTimeMs());
         }
     }
 
@@ -382,7 +384,8 @@ protected void analyze(boolean showPlanProcess) {
         }
 
         if (statementContext.getConnectContext().getExecutor() != null) {
-            statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsAnalysisTime();
+            statementContext.getConnectContext().getExecutor().getSummaryProfile()
+                    .setNereidsAnalysisTime(TimeUtils.getStartTimeMs());
         }
     }
 
@@ -399,7 +402,8 @@ protected void rewrite(boolean showPlanProcess) {
             LOG.debug("End rewrite plan");
         }
         if (statementContext.getConnectContext().getExecutor() != null) {
-            statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsRewriteTime();
+            statementContext.getConnectContext().getExecutor().getSummaryProfile()
+                    .setNereidsRewriteTime(TimeUtils.getStartTimeMs());
         }
         cascadesContext.getStatementContext().getPlannerHooks().forEach(hook -> hook.afterRewrite(this));
     }
@@ -428,7 +432,8 @@ protected void optimize() {
             LOG.debug("End optimize plan");
         }
         if (statementContext.getConnectContext().getExecutor() != null) {
-            statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsOptimizeTime();
+            statementContext.getConnectContext().getExecutor().getSummaryProfile()
+                    .setNereidsOptimizeTime(TimeUtils.getStartTimeMs());
         }
     }
 
@@ -440,9 +445,6 @@ private void splitFragments(PhysicalPlan resultPlan) {
         PlanTranslatorContext planTranslatorContext = new PlanTranslatorContext(cascadesContext);
         PhysicalPlanTranslator physicalPlanTranslator = new PhysicalPlanTranslator(planTranslatorContext,
                 statementContext.getConnectContext().getStatsErrorEstimator());
-        if (statementContext.getConnectContext().getExecutor() != null) {
-            statementContext.getConnectContext().getExecutor().getSummaryProfile().setNereidsTranslateTime();
-        }
         SessionVariable sessionVariable = cascadesContext.getConnectContext().getSessionVariable();
         if (sessionVariable.isEnableNereidsTrace()) {
             CounterEvent.clearCounter();
@@ -452,6 +454,11 @@ private void splitFragments(PhysicalPlan resultPlan) {
         }
         PlanFragment root = physicalPlanTranslator.translatePlan(physicalPlan);
 
+        if (statementContext.getConnectContext().getExecutor() != null) {
+            statementContext.getConnectContext().getExecutor().getSummaryProfile()
+                    .setNereidsTranslateTime(TimeUtils.getStartTimeMs());
+        }
+
         scanNodeList.addAll(planTranslatorContext.getScanNodes());
         physicalRelations.addAll(planTranslatorContext.getPhysicalRelations());
         descTable = planTranslatorContext.getDescTable();
@@ -544,7 +551,8 @@ private void distribute(PhysicalPlan physicalPlan, ExplainLevel explainLevel) {
 
         distributedPlans = new DistributePlanner(fragments).plan();
         if (statementContext.getConnectContext().getExecutor() != null) {
-            statementContext.getConnectContext().getExecutor().getSummaryProfile().setDistributeTime();
+            statementContext.getConnectContext().getExecutor().getSummaryProfile()
+                    .setDistributeTime(TimeUtils.getStartTimeMs());
         }
     }
 

fe/fe-core/src/main/java/org/apache/doris/nereids/rules/exploration/mv/InitMaterializationContextHook.java

@@ -26,6 +26,7 @@
 import org.apache.doris.catalog.MaterializedIndexMeta;
 import org.apache.doris.catalog.OlapTable;
 import org.apache.doris.catalog.TableIf;
+import org.apache.doris.common.util.TimeUtils;
 import org.apache.doris.mtmv.MTMVCache;
 import org.apache.doris.mtmv.MTMVPlanUtil;
 import org.apache.doris.mtmv.MTMVUtil;
@@ -68,7 +69,7 @@ public void afterRewrite(NereidsPlanner planner) {
         StatementContext statementContext = cascadesContext.getStatementContext();
         if (statementContext.getConnectContext().getExecutor() != null) {
             statementContext.getConnectContext().getExecutor().getSummaryProfile()
-                    .setNereidsCollectTablePartitionFinishTime();
+                    .setNereidsCollectTablePartitionFinishTime(TimeUtils.getStartTimeMs());
         }
         initMaterializationContext(planner.getCascadesContext());
     }

fe/fe-core/src/main/java/org/apache/doris/nereids/trees/plans/commands/LoadCommand.java

@@ -142,7 +142,7 @@ public void run(ConnectContext ctx, StmtExecutor executor) throws Exception {
         } else {
             throw new AnalysisException("Multi insert into statements are unsupported.");
         }
-        profile.getSummaryProfile().setQueryPlanFinishTime();
+        profile.getSummaryProfile().setQueryPlanFinishTime(TimeUtils.getStartTimeMs());
         submitInsertStmtPlan(ctx, executor, plans);
     }
 

fe/fe-core/src/main/java/org/apache/doris/qe/Coordinator.java

@@ -618,7 +618,7 @@ protected void processFragmentAssignmentAndParams() throws Exception {
             computeFragmentExecParams();
         } finally {
             if (context != null && context.getExecutor() != null) {
-                context.getExecutor().getSummaryProfile().setDistributeTime();
+                context.getExecutor().getSummaryProfile().setDistributeTime(TimeUtils.getStartTimeMs());
             }
         }
     }

fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java

@@ -869,7 +869,7 @@ private void executeByNereids(TUniqueId queryId) throws Exception {
                 LOG.warn("Nereids plan query failed:\n{}", originStmt.originStmt, e);
                 throw new NereidsException(new AnalysisException(e.getMessage(), e));
             } finally {
-                profile.getSummaryProfile().setQueryPlanFinishTime();
+                profile.getSummaryProfile().setQueryPlanFinishTime(TimeUtils.getStartTimeMs());
             }
 
             handleQueryWithRetry(queryId);
@@ -1593,7 +1593,7 @@ private void analyzeAndGenerateQueryPlan(TQueryOptions tQueryOptions) throws Use
         if (parsedStmt instanceof QueryStmt || parsedStmt instanceof InsertStmt) {
             planner.plan(parsedStmt, tQueryOptions);
         }
-        profile.getSummaryProfile().setQueryPlanFinishTime();
+        profile.getSummaryProfile().setQueryPlanFinishTime(TimeUtils.getStartTimeMs());
     }
 
     private void resetAnalyzerAndStmt() {
@@ -1953,7 +1953,7 @@ public void executeAndSendResult(boolean isOutfileQuery, boolean isSendFields,
 
         try {
             coordBase.exec();
-            profile.getSummaryProfile().setQueryScheduleFinishTime();
+            profile.getSummaryProfile().setQueryScheduleFinishTime(TimeUtils.getStartTimeMs());
             updateProfile(false);
 
             if (context.getConnectType().equals(ConnectType.ARROW_FLIGHT_SQL)) {
@@ -2050,7 +2050,7 @@ public void executeAndSendResult(boolean isOutfileQuery, boolean isSendFields,
 
             statisticsForAuditLog = batch.getQueryStatistics() == null ? null : batch.getQueryStatistics().toBuilder();
             context.getState().setEof();
-            profile.getSummaryProfile().setQueryFetchResultFinishTime();
+            profile.getSummaryProfile().setQueryFetchResultFinishTime(TimeUtils.getStartTimeMs());
         } catch (Exception e) {
             // notify all be cancel running fragment
             // in some case may block all fragment handle threads

fe/fe-core/src/test/java/org/apache/doris/common/profile/SummaryProfileTest.java

@@ -0,0 +1,58 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements.  See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership.  The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License.  You may obtain a copy of the License at
+//
+//   http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied.  See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common.profile;
+
+import com.google.common.collect.ImmutableMap;
+import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.Test;
+
+public class SummaryProfileTest {
+
+    @Test
+    public void testPlanSummary() {
+        SummaryProfile profile = new SummaryProfile();
+        profile.setQueryBeginTime(1);
+        profile.setParseSqlStartTime(3);
+        profile.setParseSqlFinishTime(6);
+        profile.setNereidsLockTableFinishTime(10);
+        profile.setNereidsAnalysisTime(15);
+        profile.setNereidsRewriteTime(21);
+        profile.setNereidsCollectTablePartitionFinishTime(28);
+        profile.setNereidsOptimizeTime(36);
+        profile.setNereidsTranslateTime(45);
+        profile.setQueryPlanFinishTime(66);
+        profile.setQueryScheduleFinishTime(78);
+        profile.setQueryFetchResultFinishTime(91);
+
+        profile.addCollectTablePartitionTime(7);
+        // update summary time
+        profile.update(ImmutableMap.of());
+
+        RuntimeProfile executionSummary = profile.getExecutionSummary();
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.PARSE_SQL_TIME), "3ms");
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.PLAN_TIME), "60ms");
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.NEREIDS_LOCK_TABLE_TIME), "4ms");
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.NEREIDS_ANALYSIS_TIME), "5ms");
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.NEREIDS_REWRITE_TIME), "6ms");
+
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.NEREIDS_OPTIMIZE_TIME), "8ms");
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.NEREIDS_TRANSLATE_TIME), "9ms");
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.SCHEDULE_TIME), "12ms");
+        Assertions.assertEquals(executionSummary.getInfoString(SummaryProfile.WAIT_FETCH_RESULT_TIME), "13ms");
+    }
+}