This is an automated email from the ASF dual-hosted git repository.
xy720 pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/doris.git
The following commit(s) were added to refs/heads/master by this push:
new 28c63a4809d [fix](profile) Nereids Optimize Time shows N/A when MV
pre-rewrite is skipped (#67532)
28c63a4809d is described below
commit 28c63a4809dabc4adc2b8b4de1d3099b53c5a2de
Author: xy720 <[email protected]>
AuthorDate: Mon Sep 7 22:12:27 2026 +0800
[fix](profile) Nereids Optimize Time shows N/A when MV pre-rewrite is
skipped (#67532)
`getPrettyNereidsOptimizeTime` computes the elapsed time as
`optimizeFinish - preRewriteByMvFinish`,
But `preRewriteByMvFinish` is only set at the tail of
`preMaterializedViewRewrite`, which early-exits whenever pre-rewrite is
not needed.
The start marker stays at -1, `getPrettyTime` sees -1 and returns "N/A"
— even though CBO did run and `optimizeFinish` is set.
This misleads users on any query that skips MV pre-rewrite:
1.MV refresh,
2.INSERT, large joins using DpHyper,
3.Sessions with `enable_materialized_view_rewrite=false`,
4.Queries that don't touch any MV at all
Example:
an MV refresh with
`Rewrite Time: 4ms`,
`Translate Time:239ms`
still prints `Optimize Time: N/A`, misleading anyone reading the profile
into thinking CBO was skipped.
Fall back the start marker through earlier phase finish times
(`preRewriteByMv -> collectTablePartition -> rewrite`) so the elapsed
time is shown whenever the upstream phase actually finished.
---
.../doris/common/profile/SummaryProfile.java | 12 ++-
.../org/apache/doris/nereids/NereidsPlanner.java | 114 +++++++++++----------
.../doris/common/profile/SummaryProfileTest.java | 46 +++++++++
3 files changed, 114 insertions(+), 58 deletions(-)
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 d2f6aea5992..0a595d0fbfe 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
@@ -945,7 +945,10 @@ public class SummaryProfile {
}
public int getNereidsOptimizeTimeMs() {
- return getTimeMs(nereidsOptimizeFinishTime,
nereidsCollectTablePartitionFinishTime);
+ long start = nereidsCollectTablePartitionFinishTime != -1
+ ? nereidsCollectTablePartitionFinishTime
+ : nereidsRewriteFinishTime;
+ return getTimeMs(nereidsOptimizeFinishTime, start);
}
public int getNereidsTranslateTimeMs() {
@@ -1050,7 +1053,12 @@ public class SummaryProfile {
}
public String getPrettyNereidsOptimizeTime() {
- return getPrettyTime(nereidsOptimizeFinishTime,
nereidsPreRewriteByMvFinishTime, TUnit.TIME_MS);
+ long start = nereidsPreRewriteByMvFinishTime != -1
+ ? nereidsPreRewriteByMvFinishTime
+ : (nereidsCollectTablePartitionFinishTime != -1
+ ? nereidsCollectTablePartitionFinishTime
+ : nereidsRewriteFinishTime);
+ return getPrettyTime(nereidsOptimizeFinishTime, start, TUnit.TIME_MS);
}
public String getPrettyNereidsTranslateTime() {
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 09c8ecd1d9c..1053699fff0 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
@@ -536,64 +536,66 @@ public class NereidsPlanner extends Planner {
if (!cascadesContext.getStatementContext().isNeedPreMvRewrite()) {
return;
}
- if (LOG.isDebugEnabled()) {
- LOG.debug("Start pre rewrite plan by mv");
- }
- List<Plan> tmpPlansForMvRewrite =
cascadesContext.getStatementContext().getTmpPlanForMvRewrite();
- Plan originalPlan = cascadesContext.getRewritePlan();
- List<Plan> plansWhichContainMv = new ArrayList<>();
- // because tmpPlansForMvRewrite only one, so timeout is cumulative
which is ok
- for (Plan planForRewrite : tmpPlansForMvRewrite) {
- SessionVariable sessionVariable =
cascadesContext.getConnectContext()
- .getSessionVariable();
- int timeoutSecond = sessionVariable.nereidsTimeoutSecond;
- boolean enableTimeout = sessionVariable.enableNereidsTimeout;
- try {
- // set mv rewrite timeout
- sessionVariable.nereidsTimeoutSecond =
PreMaterializedViewRewriter.convertMillisToCeilingSeconds(
-
sessionVariable.materializedViewRewriteDurationThresholdMs);
- sessionVariable.enableNereidsTimeout = true;
- // pre rewrite
- Plan rewrittenPlan =
MaterializedViewUtils.rewriteByRules(cascadesContext,
- PreMaterializedViewRewriter::rewrite, planForRewrite,
planForRewrite, true);
- Plan ruleOptimizedPlan =
MaterializedViewUtils.rewriteByRules(cascadesContext,
- childOptContext -> {
-
Rewriter.getWholeTreeRewriterWithoutCostBasedJobs(childOptContext).execute();
- return childOptContext.getRewritePlan();
- }, rewrittenPlan, planForRewrite, false);
- if (ruleOptimizedPlan == null) {
- continue;
- }
- // after rbo, maybe the plan changed a lot, so we need to
normalize it with original plan
- Plan normalizedPlan =
MaterializedViewUtils.normalizeSinkExpressions(
- ruleOptimizedPlan, originalPlan);
- if (normalizedPlan != null) {
- plansWhichContainMv.add(normalizedPlan);
- }
- } catch (Exception e) {
- LOG.error("pre mv rewrite in rbo rewrite fail, query id is {}",
-
cascadesContext.getConnectContext().getQueryIdentifier(), e);
+ try {
+ if (LOG.isDebugEnabled()) {
+ LOG.debug("Start pre rewrite plan by mv");
+ }
+ List<Plan> tmpPlansForMvRewrite =
cascadesContext.getStatementContext().getTmpPlanForMvRewrite();
+ Plan originalPlan = cascadesContext.getRewritePlan();
+ List<Plan> plansWhichContainMv = new ArrayList<>();
+ // because tmpPlansForMvRewrite only one, so timeout is cumulative
which is ok
+ for (Plan planForRewrite : tmpPlansForMvRewrite) {
+ SessionVariable sessionVariable =
cascadesContext.getConnectContext()
+ .getSessionVariable();
+ int timeoutSecond = sessionVariable.nereidsTimeoutSecond;
+ boolean enableTimeout = sessionVariable.enableNereidsTimeout;
+ try {
+ // set mv rewrite timeout
+ sessionVariable.nereidsTimeoutSecond =
PreMaterializedViewRewriter.convertMillisToCeilingSeconds(
+
sessionVariable.materializedViewRewriteDurationThresholdMs);
+ sessionVariable.enableNereidsTimeout = true;
+ // pre rewrite
+ Plan rewrittenPlan =
MaterializedViewUtils.rewriteByRules(cascadesContext,
+ PreMaterializedViewRewriter::rewrite,
planForRewrite, planForRewrite, true);
+ Plan ruleOptimizedPlan =
MaterializedViewUtils.rewriteByRules(cascadesContext,
+ childOptContext -> {
+
Rewriter.getWholeTreeRewriterWithoutCostBasedJobs(childOptContext).execute();
+ return childOptContext.getRewritePlan();
+ }, rewrittenPlan, planForRewrite, false);
+ if (ruleOptimizedPlan == null) {
+ continue;
+ }
+ // after rbo, maybe the plan changed a lot, so we need to
normalize it with original plan
+ Plan normalizedPlan =
MaterializedViewUtils.normalizeSinkExpressions(
+ ruleOptimizedPlan, originalPlan);
+ if (normalizedPlan != null) {
+ plansWhichContainMv.add(normalizedPlan);
+ }
+ } catch (Exception e) {
+ LOG.error("pre mv rewrite in rbo rewrite fail, query id is
{}",
+
cascadesContext.getConnectContext().getQueryIdentifier(), e);
- } finally {
- sessionVariable.nereidsTimeoutSecond = timeoutSecond;
- sessionVariable.enableNereidsTimeout = enableTimeout;
+ } finally {
+ sessionVariable.nereidsTimeoutSecond = timeoutSecond;
+ sessionVariable.enableNereidsTimeout = enableTimeout;
+ }
+ }
+ // clear the rewritten plans which are tmp optimized, should be
filled by full optimize later
+ statementContext.getRewrittenPlansByMv().clear();
+ // if rule-based optimized, would not be rewritten by cbo, so
clear materialized hooks
+ this.cascadesContext.getStatementContext().setPreMvRewritten(true);
+ if (!plansWhichContainMv.isEmpty()) {
+
plansWhichContainMv.forEach(statementContext::addRewrittenPlanByMv);
+ }
+ NereidsTracer.logImportantTime("EndPreRewritePlanByMv");
+ if (LOG.isDebugEnabled()) {
+ LOG.debug("End pre rewrite plan by mv");
+ }
+ } finally {
+ if (statementContext.getConnectContext().getExecutor() != null) {
+
statementContext.getConnectContext().getExecutor().getSummaryProfile()
+
.setNereidsPreRewriteByMvFinishTime(TimeUtils.getStartTimeMs());
}
- }
- // clear the rewritten plans which are tmp optimized, should be filled
by full optimize later
- statementContext.getRewrittenPlansByMv().clear();
- // if rule-based optimized, would not be rewritten by cbo, so clear
materialized hooks
- this.cascadesContext.getStatementContext().setPreMvRewritten(true);
- if (plansWhichContainMv.isEmpty()) {
- return;
- }
- plansWhichContainMv.forEach(statementContext::addRewrittenPlanByMv);
- NereidsTracer.logImportantTime("EndPreRewritePlanByMv");
- if (LOG.isDebugEnabled()) {
- LOG.debug("End pre rewrite plan by mv");
- }
- if (statementContext.getConnectContext().getExecutor() != null) {
-
statementContext.getConnectContext().getExecutor().getSummaryProfile()
-
.setNereidsPreRewriteByMvFinishTime(TimeUtils.getStartTimeMs());
}
}
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
index f6e8d5a677d..001d63364fc 100644
---
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
@@ -131,4 +131,50 @@ public class SummaryProfileTest {
SummaryProfile.EXTERNAL_TABLE_GET_FILE_SCAN_TASKS_TIME));
Assertions.assertEquals(28, profile.getExternalCatalogMetaTimeMs());
}
+
+ @Test
+ public void testOptimizeTimeFallbackWhenPreMvSkipped() {
+ SummaryProfile profile = new SummaryProfile();
+ profile.setQueryBeginTime(1);
+ profile.setParseSqlStartTime(3);
+ profile.setParseSqlFinishTime(6);
+ profile.setNereidsLockTableStartTime(8);
+ profile.setNereidsLockTableFinishTime(10);
+ profile.setNereidsAnalysisTime(15);
+ profile.setNereidsRewriteTime(21);
+ profile.setNereidsOptimizeTime(36);
+ profile.setNereidsTranslateTime(45);
+ profile.setNereidsDistributeTime(55);
+ profile.setQueryPlanFinishTime(66);
+
+ profile.update(ImmutableMap.of());
+ RuntimeProfile executionSummary = profile.getExecutionSummary();
+
+ Assertions.assertEquals("N/A",
executionSummary.getInfoString(SummaryProfile.NEREIDS_PRE_REWRITE_BY_MV_TIME));
+ Assertions.assertEquals("15ms",
executionSummary.getInfoString(SummaryProfile.NEREIDS_OPTIMIZE_TIME));
+ Assertions.assertEquals(15, profile.getNereidsOptimizeTimeMs());
+ }
+
+ @Test
+ public void testPreMvAttemptedButEmpty() {
+ SummaryProfile profile = new SummaryProfile();
+ profile.setQueryBeginTime(1);
+ profile.setParseSqlStartTime(3);
+ profile.setParseSqlFinishTime(6);
+ profile.setNereidsLockTableStartTime(8);
+ profile.setNereidsLockTableFinishTime(10);
+ profile.setNereidsAnalysisTime(15);
+ profile.setNereidsRewriteTime(21);
+ profile.setNereidsCollectTablePartitionFinishTime(28);
+ profile.setNereidsPreRewriteByMvFinishTime(58);
+ profile.setNereidsOptimizeTime(60);
+ profile.setNereidsTranslateTime(65);
+
+ profile.update(ImmutableMap.of());
+ RuntimeProfile executionSummary = profile.getExecutionSummary();
+
+ Assertions.assertEquals("30ms",
executionSummary.getInfoString(SummaryProfile.NEREIDS_PRE_REWRITE_BY_MV_TIME));
+ Assertions.assertEquals("2ms",
executionSummary.getInfoString(SummaryProfile.NEREIDS_OPTIMIZE_TIME));
+ Assertions.assertEquals(32, profile.getNereidsOptimizeTimeMs());
+ }
}
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
