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 697cdca65bda97..1410f9618811e3 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 @@ -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() { 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 0cd604cbd80d4c..351b7f717177be 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 @@ -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()); } } diff --git a/fe/fe-core/src/main/java/org/apache/doris/nereids/rules/exploration/mv/InitMaterializationContextHook.java b/fe/fe-core/src/main/java/org/apache/doris/nereids/rules/exploration/mv/InitMaterializationContextHook.java index ca912c0d9da6ee..d08c49b1fad7ca 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/nereids/rules/exploration/mv/InitMaterializationContextHook.java +++ b/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()); } diff --git a/fe/fe-core/src/main/java/org/apache/doris/nereids/trees/plans/commands/LoadCommand.java b/fe/fe-core/src/main/java/org/apache/doris/nereids/trees/plans/commands/LoadCommand.java index 7d592af0632b02..0701d5f1b80ed1 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/nereids/trees/plans/commands/LoadCommand.java +++ b/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); } diff --git a/fe/fe-core/src/main/java/org/apache/doris/qe/Coordinator.java b/fe/fe-core/src/main/java/org/apache/doris/qe/Coordinator.java index 452afb20847e03..2eb4f115b4c07c 100644 --- a/fe/fe-core/src/main/java/org/apache/doris/qe/Coordinator.java +++ b/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()); } } } 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 a3cbc1fc272bc7..3383651f779ad3 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 @@ -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 diff --git a/fe/fe-core/src/test/java/org/apache/doris/common/profile/SummaryProfileTest.java b/fe/fe-core/src/test/java/org/apache/doris/common/profile/SummaryProfileTest.java new file mode 100644 index 00000000000000..438e80fe3ee831 --- /dev/null +++ b/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"); + } +}