feat(optimizer): optimizer trace log (#17746)

BohuTANG · web-flow · commit 9b6639e62242 · 2025-04-10T15:03:48.000+08:00
* refactor(optimizer): move rule/utils

* re-org the tests

* feat(optimizer): optimizer trace

* merge with main

* add enable_optimizer_trace setting

* add optimizer trace log summary
diff --git a/Cargo.lock b/Cargo.lock
diff --git a/Cargo.toml b/Cargo.toml
@@ -471,6 +471,7 @@ serfig = "0.1.0"
 sha1 = "0.10.5"
 sha2 = "0.10.8"
 simdutf8 = "0.1.4"
+similar = "2.7.0"
 simple_hll = { version = "0.0.1", features = ["serde_borsh"] }
 simsearch = "0.2"
 siphasher = "0.3"
diff --git a/src/query/settings/src/settings_default.rs b/src/query/settings/src/settings_default.rs
@@ -1242,6 +1242,14 @@ impl DefaultSettings {
                     scope: SettingScope::Both,
                     range: Some(SettingRange::Numeric(0..=1)),
                 }),
+                ("enable_optimizer_trace", DefaultSettingValue {
+                    value: UserSettingValue::UInt64(0),
+                    desc: "Enables optimizer trace.",
+                    mode: SettingMode::Both,
+                    scope: SettingScope::Both,
+                    range: Some(SettingRange::Numeric(0..=1)),
+                }),
+
             ]);
 
             Ok(Arc::new(DefaultSettings {
diff --git a/src/query/settings/src/settings_getter_setter.rs b/src/query/settings/src/settings_getter_setter.rs
@@ -924,4 +924,8 @@ impl Settings {
     pub fn get_enable_use_vacuum2_to_purge_transient_table_data(&self) -> Result<bool> {
         Ok(self.try_get_u64("use_vacuum2_to_purge_transient_table_data")? == 1)
     }
+
+    pub fn get_enable_optimizer_trace(&self) -> Result<bool> {
+        Ok(self.try_get_u64("enable_optimizer_trace")? == 1)
+    }
 }
diff --git a/src/query/sql/Cargo.toml b/src/query/sql/Cargo.toml
@@ -67,6 +67,7 @@ regex = { workspace = true }
 roaring = { workspace = true }
 serde = { workspace = true }
 sha2 = { workspace = true }
+similar = { workspace = true }
 simsearch = { workspace = true }
 tokio = { workspace = true }
 unicase = { workspace = true }
diff --git a/src/query/sql/src/planner/optimizer/optimizer_api.rs b/src/query/sql/src/planner/optimizer/optimizer_api.rs
@@ -25,7 +25,7 @@ pub trait Optimizer: Send + Sync {
     async fn optimize(&mut self, expr: &SExpr) -> Result<SExpr>;
 
     /// Returns a unique identifier for this optimizer.
-    fn name(&self) -> &'static str;
+    fn name(&self) -> String;
 
     /// Get the memo if this optimizer maintains one.
     /// Default implementation returns None for optimizers that don't use a memo.
diff --git a/src/query/sql/src/planner/optimizer/optimizer_context.rs b/src/query/sql/src/planner/optimizer/optimizer_context.rs
@@ -41,6 +41,10 @@ pub struct OptimizerContext {
     // Optimizer state flags
     #[educe(Debug(ignore))]
     flags: RwLock<HashMap<String, bool>>,
+
+    // Enable optimizer tracing
+    #[educe(Debug(ignore))]
+    enable_trace: RwLock<bool>,
 }
 
 impl OptimizerContext {
@@ -56,6 +60,7 @@ impl OptimizerContext {
             sample_executor: RwLock::new(None),
             planning_agg_index: RwLock::new(false),
             flags: RwLock::new(HashMap::new()),
+            enable_trace: RwLock::new(false),
         })
     }
 
@@ -134,4 +139,13 @@ impl OptimizerContext {
         let flags = self.flags.read();
         *flags.get(name).unwrap_or(&false)
     }
+
+    pub fn set_enable_trace(self: &Arc<Self>, enable: bool) -> Arc<Self> {
+        *self.enable_trace.write() = enable;
+        self.clone()
+    }
+
+    pub fn get_enable_trace(self: &Arc<Self>) -> bool {
+        *self.enable_trace.read()
+    }
 }
diff --git a/src/query/sql/src/planner/optimizer/optimizers/cascades/cascade.rs b/src/query/sql/src/planner/optimizer/optimizers/cascades/cascade.rs
@@ -246,8 +246,8 @@ impl CascadesOptimizer {
 
 #[async_trait::async_trait]
 impl Optimizer for CascadesOptimizer {
-    fn name(&self) -> &'static str {
-        "CascadesOptimizer"
+    fn name(&self) -> String {
+        "CascadesOptimizer".to_string()
     }
 
     async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {
diff --git a/src/query/sql/src/planner/optimizer/optimizers/hyper_dp/dphyp.rs b/src/query/sql/src/planner/optimizer/optimizers/hyper_dp/dphyp.rs
@@ -862,8 +862,8 @@ impl DPhpy {
 
 #[async_trait::async_trait]
 impl Optimizer for DPhpy {
-    fn name(&self) -> &'static str {
-        "DPhpy"
+    fn name(&self) -> String {
+        "DPhpy".to_string()
     }
 
     async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {
diff --git a/src/query/sql/src/planner/optimizer/optimizers/operator/aggregate/normalize_aggregate.rs b/src/query/sql/src/planner/optimizer/optimizers/operator/aggregate/normalize_aggregate.rs
@@ -181,8 +181,8 @@ impl Default for RuleNormalizeAggregateOptimizer {
 
 #[async_trait::async_trait]
 impl Optimizer for RuleNormalizeAggregateOptimizer {
-    fn name(&self) -> &'static str {
-        "RuleNormalizeAggregateOptimizer"
+    fn name(&self) -> String {
+        "RuleNormalizeAggregateOptimizer".to_string()
     }
 
     async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {
diff --git a/src/query/sql/src/planner/optimizer/optimizers/operator/aggregate/stats_aggregate.rs b/src/query/sql/src/planner/optimizer/optimizers/operator/aggregate/stats_aggregate.rs
@@ -223,8 +223,8 @@ impl RuleStatsAggregateOptimizer {
 
 #[async_trait::async_trait]
 impl Optimizer for RuleStatsAggregateOptimizer {
-    fn name(&self) -> &'static str {
-        "RuleStatsAggregateOptimizer"
+    fn name(&self) -> String {
+        "RuleStatsAggregateOptimizer".to_string()
     }
 
     async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {
diff --git a/src/query/sql/src/planner/optimizer/optimizers/operator/decorrelate/subquery_decorrelator.rs b/src/query/sql/src/planner/optimizer/optimizers/operator/decorrelate/subquery_decorrelator.rs
@@ -814,8 +814,8 @@ pub fn check_child_expr_in_subquery(
 #[async_trait::async_trait]
 impl Optimizer for SubqueryDecorrelatorOptimizer {
     /// Returns the name of this optimizer
-    fn name(&self) -> &'static str {
-        "SubqueryRewriter"
+    fn name(&self) -> String {
+        "SubqueryRewriter".to_string()
     }
 
     /// Optimize the expression by rewriting subqueries
diff --git a/src/query/sql/src/planner/optimizer/optimizers/operator/filter/deduplicate_join_condition.rs b/src/query/sql/src/planner/optimizer/optimizers/operator/filter/deduplicate_join_condition.rs
@@ -237,8 +237,8 @@ impl DeduplicateJoinConditionOptimizer {
 
 #[async_trait::async_trait]
 impl Optimizer for DeduplicateJoinConditionOptimizer {
-    fn name(&self) -> &'static str {
-        "DeduplicateJoinConditionOptimizer"
+    fn name(&self) -> String {
+        "DeduplicateJoinConditionOptimizer".to_string()
     }
 
     async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {
diff --git a/src/query/sql/src/planner/optimizer/optimizers/operator/filter/pull_up_filter.rs b/src/query/sql/src/planner/optimizer/optimizers/operator/filter/pull_up_filter.rs
@@ -257,8 +257,8 @@ impl PullUpFilterOptimizer {
 
 #[async_trait::async_trait]
 impl Optimizer for PullUpFilterOptimizer {
-    fn name(&self) -> &'static str {
-        "PullUpFilterOptimizer"
+    fn name(&self) -> String {
+        "PullUpFilterOptimizer".to_string()
     }
 
     async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {
diff --git a/src/query/sql/src/planner/optimizer/optimizers/operator/join/single_to_inner.rs b/src/query/sql/src/planner/optimizer/optimizers/operator/join/single_to_inner.rs
@@ -69,8 +69,8 @@ impl Default for SingleToInnerOptimizer {
 
 #[async_trait::async_trait]
 impl Optimizer for SingleToInnerOptimizer {
-    fn name(&self) -> &'static str {
-        "SingleToInnerOptimizer"
+    fn name(&self) -> String {
+        "SingleToInnerOptimizer".to_string()
     }
 
     async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {
diff --git a/src/query/sql/src/planner/optimizer/optimizers/recursive/recursive.rs b/src/query/sql/src/planner/optimizer/optimizers/recursive/recursive.rs
@@ -91,8 +91,18 @@ impl RecursiveRuleOptimizer {
 
 #[async_trait::async_trait]
 impl Optimizer for RecursiveRuleOptimizer {
-    fn name(&self) -> &'static str {
-        "RecursiveOptimizer"
+    fn name(&self) -> String {
+        let total = self.rules.len();
+        let preview = if total <= 3 {
+            self.rules
+                .iter()
+                .map(|rule_id| format!("{:?}", rule_id))
+                .collect::<Vec<_>>()
+                .join(",")
+        } else {
+            format!("{:?},{:?},...({})", self.rules[0], self.rules[1], total - 2)
+        };
+        format!("RecursiveOptimizer[{}]", preview)
     }
 
     async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {
diff --git a/src/query/sql/src/planner/optimizer/pipeline/mod.rs b/src/query/sql/src/planner/optimizer/pipeline/mod.rs
@@ -15,5 +15,7 @@
 mod common;
 #[allow(clippy::module_inception)]
 mod pipeline;
+mod trace;
 
 pub use pipeline::OptimizerPipeline;
+pub use trace::OptimizerTrace;
diff --git a/src/query/sql/src/planner/optimizer/pipeline/pipeline.rs b/src/query/sql/src/planner/optimizer/pipeline/pipeline.rs
@@ -13,6 +13,7 @@
 // limitations under the License.
 
 use std::sync::Arc;
+use std::time::Instant;
 
 use databend_common_exception::Result;
 use log::info;
@@ -21,6 +22,8 @@ use super::common::contains_local_table_scan;
 use super::common::contains_warehouse_table_scan;
 use crate::optimizer::ir::Memo;
 use crate::optimizer::ir::SExpr;
+use crate::optimizer::pipeline::trace::OptimizerExecution;
+use crate::optimizer::pipeline::trace::OptimizerTraceCollector;
 use crate::optimizer::Optimizer;
 use crate::optimizer::OptimizerContext;
 
@@ -33,6 +36,9 @@ pub struct OptimizerPipeline {
     /// The memo captured during optimization (if any)
     memo: Option<Memo>,
 
+    /// The trace collector for generating reports
+    trace_collector: OptimizerTraceCollector,
+
     s_expr: SExpr,
 }
 
@@ -43,6 +49,7 @@ impl OptimizerPipeline {
             opt_ctx,
             optimizers: Vec::new(),
             memo: None,
+            trace_collector: OptimizerTraceCollector::new(),
             s_expr,
         };
 
@@ -91,13 +98,43 @@ impl OptimizerPipeline {
     pub async fn execute(&mut self) -> Result<SExpr> {
         // Then apply all optimizers in sequence
         let mut current_expr = self.s_expr.clone();
-        for optimizer in &mut self.optimizers {
+        let total_optimizers = self.optimizers.len();
+
+        // Update trace status from context
+        self.trace_collector
+            .set_enable_trace(self.opt_ctx.get_enable_trace());
+        for (idx, optimizer) in self.optimizers.iter_mut().enumerate() {
+            let before_expr = current_expr.clone();
+
+            // Measure optimizer execution time
+            let start_time = Instant::now();
             current_expr = optimizer.optimize(&current_expr).await?;
+            let duration = start_time.elapsed();
+
             if let Some(memo) = optimizer.memo() {
                 self.memo = Some(memo.clone());
             }
+
+            // Create execution info and trace optimizer
+            {
+                let metadata_ref = self.opt_ctx.get_metadata();
+                let execution = OptimizerExecution {
+                    name: optimizer.name(),
+                    index: idx,
+                    total: total_optimizers,
+                    time: duration,
+                    before: &before_expr,
+                    after: &current_expr,
+                };
+
+                self.trace_collector
+                    .trace_optimizer(execution, &metadata_ref.read())?;
+            }
         }
 
+        // Generate and log the report
+        self.trace_collector.log_report();
+
         Ok(current_expr)
     }
 
diff --git a/src/query/sql/src/planner/optimizer/pipeline/trace/expr_diff.rs b/src/query/sql/src/planner/optimizer/pipeline/trace/expr_diff.rs
@@ -0,0 +1,68 @@
+// Copyright 2021 Datafuse Labs
+//
+// Licensed 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.
+
+use databend_common_exception::Result;
+use similar::ChangeTag;
+use similar::TextDiff;
+
+use crate::optimizer::ir::SExpr;
+use crate::planner::format::FormatOptions;
+use crate::planner::format::MetadataIdHumanizer;
+use crate::Metadata;
+
+impl SExpr {
+    /// Compares this SExpr with another SExpr and returns a diff of their string representations.
+    ///
+    /// # Arguments
+    /// * `other` - The other SExpr to compare with.
+    /// * `metadata` - The metadata used for humanizing IDs.
+    ///
+    /// # Returns
+    /// A string containing the diff between the two SExpr instances.
+    pub fn diff(&self, other: &SExpr, metadata: &Metadata) -> Result<String> {
+        let self_str = self.pretty_format(metadata)?;
+        let other_str = other.pretty_format(metadata)?;
+
+        if self_str == other_str {
+            return Ok("No differences found.".to_string());
+        }
+
+        let diff = TextDiff::from_lines(&self_str, &other_str);
+
+        let mut diff_output = String::new();
+        for change in diff.iter_all_changes() {
+            let sign = match change.tag() {
+                ChangeTag::Delete => "-",
+                ChangeTag::Insert => "+",
+                ChangeTag::Equal => " ",
+            };
+            diff_output.push_str(&format!("{}{}", sign, change));
+        }
+
+        Ok(diff_output)
+    }
+
+    /// Formats this SExpr into a pretty-printed string using metadata.
+    ///
+    /// # Arguments
+    /// * `metadata` - The metadata used for humanizing IDs.
+    ///
+    /// # Returns
+    /// A Result containing the formatted SExpr string.
+    pub fn pretty_format(&self, metadata: &Metadata) -> Result<String> {
+        let options = FormatOptions { verbose: false };
+        let humanizer = MetadataIdHumanizer::new(metadata, options);
+        Ok(self.to_format_tree(&humanizer)?.format_pretty()?)
+    }
+}
diff --git a/src/query/sql/src/planner/optimizer/pipeline/trace/mod.rs b/src/query/sql/src/planner/optimizer/pipeline/trace/mod.rs
@@ -0,0 +1,21 @@
+// Copyright 2021 Datafuse Labs
+//
+// Licensed 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.
+
+mod expr_diff;
+#[allow(clippy::module_inception)]
+mod trace;
+
+pub use trace::OptimizerExecution;
+pub use trace::OptimizerTrace;
+pub use trace::OptimizerTraceCollector;
diff --git a/src/query/sql/src/planner/optimizer/pipeline/trace/trace.rs b/src/query/sql/src/planner/optimizer/pipeline/trace/trace.rs
diff --git a/src/query/sql/src/planner/optimizer/statistics/collect_statistics.rs b/src/query/sql/src/planner/optimizer/statistics/collect_statistics.rs
diff --git a/src/query/sql/src/planner/planner.rs b/src/query/sql/src/planner/planner.rs

Original file line number	Diff line number	Diff line change
`@@ -924,4 +924,8 @@ impl Settings {`
`924`	`924`	`pub fn get_enable_use_vacuum2_to_purge_transient_table_data(&self) -> Result<bool> {`
`925`	`925`	`Ok(self.try_get_u64("use_vacuum2_to_purge_transient_table_data")? == 1)`
`926`	`926`	`}`
	`927`	`+`
	`928`	`+ pub fn get_enable_optimizer_trace(&self) -> Result<bool> {`
	`929`	`+ Ok(self.try_get_u64("enable_optimizer_trace")? == 1)`
	`930`	`+ }`
`927`	`931`	`}`
Original file line number	Diff line number	Diff line change
`@@ -246,8 +246,8 @@ impl CascadesOptimizer {`
`246`	`246`
`247`	`247`	`#[async_trait::async_trait]`
`248`	`248`	`impl Optimizer for CascadesOptimizer {`
`249`		`- fn name(&self) -> &'static str {`
`250`		`- "CascadesOptimizer"`
	`249`	`+ fn name(&self) -> String {`
	`250`	`+ "CascadesOptimizer".to_string()`
`251`	`251`	`}`
`252`	`252`
`253`	`253`	`async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {`
Original file line number	Diff line number	Diff line change
`@@ -862,8 +862,8 @@ impl DPhpy {`
`862`	`862`
`863`	`863`	`#[async_trait::async_trait]`
`864`	`864`	`impl Optimizer for DPhpy {`
`865`		`- fn name(&self) -> &'static str {`
`866`		`- "DPhpy"`
	`865`	`+ fn name(&self) -> String {`
	`866`	`+ "DPhpy".to_string()`
`867`	`867`	`}`
`868`	`868`
`869`	`869`	`async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {`
Original file line number	Diff line number	Diff line change
`@@ -181,8 +181,8 @@ impl Default for RuleNormalizeAggregateOptimizer {`
`181`	`181`
`182`	`182`	`#[async_trait::async_trait]`
`183`	`183`	`impl Optimizer for RuleNormalizeAggregateOptimizer {`
`184`		`- fn name(&self) -> &'static str {`
`185`		`- "RuleNormalizeAggregateOptimizer"`
	`184`	`+ fn name(&self) -> String {`
	`185`	`+ "RuleNormalizeAggregateOptimizer".to_string()`
`186`	`186`	`}`
`187`	`187`
`188`	`188`	`async fn optimize(&mut self, s_expr: &SExpr) -> Result<SExpr> {`