Skip to content
This repository was archived by the owner on Jan 7, 2025. It is now read-only.

Commit ce8e1ad

Browse files
skyzhskyzh
authored
feat(core): add more logging to facilitate debugging (#191)
* remove heuristics in cascades, dead code now * add more logging to the apply rule process --------- Signed-off-by: Alex Chi <[email protected]>
1 parent d73c26c commit ce8e1ad

File tree

10 files changed

+74
-100
lines changed

10 files changed

+74
-100
lines changed

‎optd-core/src/cascades/memo.rs

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ use std::{
77
use anyhow::{bail, Result};
88
use itertools::Itertools;
99
use std::any::Any;
10+
use tracing::trace;
1011

1112
use crate::{
1213
cost::Cost,
@@ -235,6 +236,7 @@ impl<T: RelNodeTyp> Memo<T> {
235236
group_id: ReducedGroupId,
236237
memo_node: RelMemoNode<T>,
237238
) {
239+
trace!(event = "add_expr_to_group", group_id = %group_id, expr_id = %expr_id, memo_node = %memo_node);
238240
if let Entry::Occupied(mut entry) = self.groups.entry(group_id) {
239241
let group = entry.get_mut();
240242
group.group_exprs.insert(expr_id);
@@ -252,6 +254,7 @@ impl<T: RelNodeTyp> Memo<T> {
252254
// return true: replace success, the expr_id is replaced by the new rel_node
253255
// return false: replace failed as the new rel node already exists in other groups,
254256
// the old expr_id should be marked as all rules are fired for it
257+
#[allow(dead_code)]
255258
pub fn replace_group_expr(
256259
&mut self,
257260
expr_id: ExprId,

‎optd-core/src/cascades/optimizer.rs

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ use std::{
55
};
66

77
use anyhow::Result;
8+
use tracing::trace;
89

910
use crate::{
1011
cost::CostModel,
@@ -228,6 +229,7 @@ impl<T: RelNodeTyp> CascadesOptimizer<T> {
228229
}
229230

230231
fn fire_optimize_tasks(&mut self, group_id: GroupId) -> Result<()> {
232+
trace!(event = "fire_optimize_tasks", root_group_id = %group_id);
231233
self.tasks
232234
.push_back(Box::new(OptimizeGroupTask::new(group_id)));
233235
// get the task from the stack
@@ -292,6 +294,7 @@ impl<T: RelNodeTyp> CascadesOptimizer<T> {
292294
self.memo.add_new_group_expr(expr, group_id)
293295
}
294296

297+
#[allow(dead_code)]
295298
pub(super) fn replace_group_expr(
296299
&mut self,
297300
expr: RelNodeRef<T>,

‎optd-core/src/cascades/tasks/apply_rule.rs

Lines changed: 3 additions & 40 deletions
Original file line numberDiff line numberDiff line change
@@ -196,52 +196,15 @@ impl<T: RelNodeTyp> Task<T> for ApplyRuleTask {
196196
let mut tasks = vec![];
197197
let binding_exprs = match_and_pick_expr(rule.matcher(), self.expr_id, optimizer);
198198
for expr in binding_exprs {
199+
trace!(event = "before_apply_rule", task = "apply_rule", binding = ?expr.iter().map(|(k, v)| format!("{}=>{}", k, v)).join(","));
199200
let applied = rule.apply(optimizer, expr);
200201

201202
if rule_wrapper.optimize_type() == OptimizeType::Heuristics {
202-
assert!(
203-
applied.len() <= 1,
204-
"rules registered as heuristics should always return equal or less than one expr"
205-
);
206-
207-
if applied.is_empty() {
208-
continue;
209-
}
210-
211-
let RelNode { typ, .. } = &applied[0];
212-
213-
assert!(
214-
!rule.is_impl_rule(),
215-
"impl rule registered should not be registered as heuristics"
216-
);
217-
218-
if let Some(group_id_2) = typ.extract_group() {
219-
// If this is a group, merge the groups!
220-
optimizer.merge_group(group_id, group_id_2);
221-
// mark the old expr as a dead end
222-
(0..optimizer.rules().len())
223-
.for_each(|i| optimizer.mark_rule_fired(self.expr_id, i));
224-
continue;
225-
}
226-
227-
for new_expr in applied {
228-
// replace the old expr with the new expr
229-
optimizer.replace_group_expr(new_expr.into(), group_id, self.expr_id);
230-
231-
// expr replacement will treat the new expr as not explored, but we need to mark current rule fired
232-
optimizer.mark_rule_fired(self.expr_id, self.rule_id);
233-
234-
trace!(event = "apply_rule replace", expr_id = %self.expr_id, rule_id = %self.rule_id);
235-
236-
tasks.push(
237-
Box::new(OptimizeExpressionTask::new(self.expr_id, self.exploring))
238-
as Box<dyn Task<T>>,
239-
);
240-
}
241-
continue;
203+
panic!("no more heuristics rule in cascades");
242204
}
243205

244206
for expr in applied {
207+
trace!(event = "after_apply_rule", task = "apply_rule", binding=%expr);
245208
let RelNode { typ, .. } = &expr;
246209
if let Some(group_id_2) = typ.extract_group() {
247210
// If this is a group, merge the groups!

‎optd-datafusion-repr/src/lib.rs

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -114,19 +114,19 @@ impl DatafusionOptimizer {
114114
ProjectFilterTransposeRule::new(),
115115
)));
116116
// add all filter pushdown rules as heuristic rules
117-
rule_wrappers.push(RuleWrapper::new_heuristic(Arc::new(
117+
rule_wrappers.push(RuleWrapper::new_cascades(Arc::new(
118118
FilterProjectTransposeRule::new(),
119119
)));
120-
rule_wrappers.push(RuleWrapper::new_heuristic(Arc::new(
120+
rule_wrappers.push(RuleWrapper::new_cascades(Arc::new(
121121
FilterCrossJoinTransposeRule::new(),
122122
)));
123-
rule_wrappers.push(RuleWrapper::new_heuristic(Arc::new(
123+
rule_wrappers.push(RuleWrapper::new_cascades(Arc::new(
124124
FilterInnerJoinTransposeRule::new(),
125125
)));
126-
rule_wrappers.push(RuleWrapper::new_heuristic(Arc::new(
126+
rule_wrappers.push(RuleWrapper::new_cascades(Arc::new(
127127
FilterSortTransposeRule::new(),
128128
)));
129-
rule_wrappers.push(RuleWrapper::new_heuristic(Arc::new(
129+
rule_wrappers.push(RuleWrapper::new_cascades(Arc::new(
130130
FilterAggTransposeRule::new(),
131131
)));
132132
rule_wrappers.push(RuleWrapper::new_cascades(Arc::new(HashJoinRule::new()))); // 17

‎optd-sqlplannertest/README.md

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -47,3 +47,9 @@ Currently we have the following options for the explain task:
4747
- `physical_datafusion`: datafusion's physical plan.
4848
- `join_orders`: physical join orders.
4949
- `logical_join_orders`: logical join orders.
50+
51+
## Tracing a query
52+
53+
```
54+
RUST_LOG=optd_core=trace cargo run -p optd-sqlplannertest --bin planner_test_apply -- pushdowns &> log
55+
```

‎optd-sqlplannertest/src/bin/planner_test_apply.rs

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,8 @@ struct Cli {
1313

1414
#[tokio::main]
1515
async fn main() -> Result<()> {
16+
env_logger::init();
17+
1618
let cli = Cli::parse();
1719

1820
if cli.directories.is_empty() {

‎optd-sqlplannertest/tests/subqueries/subquery_unnesting.planner.sql

Lines changed: 21 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -55,29 +55,26 @@ LogicalProjection { exprs: [ #0, #1 ] }
5555
└── LogicalScan { table: t2 }
5656
PhysicalProjection { exprs: [ #0, #1 ] }
5757
└── PhysicalProjection { exprs: [ #0, #1, #3 ] }
58-
└── PhysicalProjection { exprs: [ #2, #3, #0, #1 ] }
59-
└── PhysicalProjection { exprs: [ #0, #1, #2, #3 ] }
60-
└── PhysicalProjection { exprs: [ #2, #3, #0, #1 ] }
61-
└── PhysicalHashJoin { join_type: Inner, left_keys: [ #0 ], right_keys: [ #0 ] }
62-
├── PhysicalScan { table: t1 }
63-
└── PhysicalAgg
64-
├── aggrs:Agg(Sum)
65-
│ └── [ Cast { cast_to: Int64, expr: #2 } ]
66-
├── groups: [ #1 ]
67-
└── PhysicalProjection { exprs: [ #2, #0, #1 ] }
68-
└── PhysicalNestedLoopJoin
69-
├── join_type: Inner
70-
├── cond:And
71-
│ ├── Eq
72-
│ │ ├── #0
73-
│ │ └── #2
74-
│ └── true
75-
├── PhysicalFilter
76-
│ ├── cond:Gt
77-
│ │ ├── #0
78-
│ │ └── 100(i64)
79-
│ └── PhysicalScan { table: t2 }
80-
└── PhysicalAgg { aggrs: [], groups: [ #0 ] }
81-
└── PhysicalScan { table: t1 }
58+
└── PhysicalFilter
59+
├── cond:Gt
60+
│ ├── #3
61+
│ └── 100(i64)
62+
└── PhysicalProjection { exprs: [ #2, #3, #0, #1 ] }
63+
└── PhysicalProjection { exprs: [ #0, #1, #2, #3 ] }
64+
└── PhysicalProjection { exprs: [ #2, #3, #0, #1 ] }
65+
└── PhysicalHashJoin { join_type: Inner, left_keys: [ #0 ], right_keys: [ #0 ] }
66+
├── PhysicalScan { table: t1 }
67+
└── PhysicalAgg
68+
├── aggrs:Agg(Sum)
69+
│ └── [ Cast { cast_to: Int64, expr: #2 } ]
70+
├── groups: [ #1 ]
71+
└── PhysicalFilter
72+
├── cond:Eq
73+
│ ├── #1
74+
│ └── #0
75+
└── PhysicalNestedLoopJoin { join_type: Inner, cond: true }
76+
├── PhysicalAgg { aggrs: [], groups: [ #0 ] }
77+
│ └── PhysicalScan { table: t1 }
78+
└── PhysicalScan { table: t2 }
8279
*/
8380

‎optd-sqlplannertest/tests/tpch/tpch-01-05.planner.sql

Lines changed: 17 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -374,13 +374,13 @@ PhysicalLimit { skip: 0(u64), fetch: 100(u64) }
374374
│ │ │ ├── PhysicalProjection { exprs: [ #0, #1, #3, #4 ] }
375375
│ │ │ │ └── PhysicalHashJoin { join_type: Inner, left_keys: [ #0 ], right_keys: [ #0 ] }
376376
│ │ │ │ ├── PhysicalProjection { exprs: [ #0, #1 ] }
377-
│ │ │ │ │ └── PhysicalProjection { exprs: [ #0, #2, #4, #5 ] }
378-
│ │ │ │ │ └── PhysicalFilter
379-
│ │ │ │ │ ├── cond:And
380-
│ │ │ │ │ │ ├── Eq
381-
│ │ │ │ │ │ │ ├── #5
382-
│ │ │ │ │ │ │ └── 4(i32)
383-
│ │ │ │ │ │ └── Like { expr: #4, pattern: "%TIN", negated: false, case_insensitive: false }
377+
│ │ │ │ │ └── PhysicalFilter
378+
│ │ │ │ │ ├── cond:And
379+
│ │ │ │ │ │ ├── Eq
380+
│ │ │ │ │ │ │ ├── #3
381+
│ │ │ │ │ │ │ └── 4(i32)
382+
│ │ │ │ │ │ └── Like { expr: #2, pattern: "%TIN", negated: false, case_insensitive: false }
383+
│ │ │ │ │ └── PhysicalProjection { exprs: [ #0, #2, #4, #5 ] }
384384
│ │ │ │ │ └── PhysicalScan { table: part }
385385
│ │ │ │ └── PhysicalProjection { exprs: [ #0, #1, #3 ] }
386386
│ │ │ │ └── PhysicalScan { table: partsupp }
@@ -515,17 +515,17 @@ PhysicalLimit { skip: 0(u64), fetch: 10(u64) }
515515
├── PhysicalProjection { exprs: [ #1, #3, #4 ] }
516516
│ └── PhysicalHashJoin { join_type: Inner, left_keys: [ #0 ], right_keys: [ #1 ] }
517517
│ ├── PhysicalProjection { exprs: [ #0 ] }
518-
│ │ └── PhysicalProjection { exprs: [ #0, #6 ] }
519-
│ │ └── PhysicalFilter
520-
│ │ ├── cond:Eq
521-
│ │ │ ├── #6
522-
│ │ │ └── "FURNITURE"
518+
│ │ └── PhysicalFilter
519+
│ │ ├── cond:Eq
520+
│ │ │ ├── #1
521+
│ │ │ └── "FURNITURE"
522+
│ │ └── PhysicalProjection { exprs: [ #0, #6 ] }
523523
│ │ └── PhysicalScan { table: customer }
524-
│ └── PhysicalProjection { exprs: [ #0, #1, #4, #7 ] }
525-
│ └── PhysicalFilter
526-
│ ├── cond:Lt
527-
│ │ ├── #4
528-
│ │ └── 9218(i64)
524+
│ └── PhysicalFilter
525+
│ ├── cond:Lt
526+
│ │ ├── #2
527+
│ │ └── 9218(i64)
528+
│ └── PhysicalProjection { exprs: [ #0, #1, #4, #7 ] }
529529
│ └── PhysicalScan { table: orders }
530530
└── PhysicalProjection { exprs: [ #0, #1, #2 ] }
531531
└── PhysicalProjection { exprs: [ #0, #5, #6, #10 ] }

‎optd-sqlplannertest/tests/tpch/tpch-06-10.planner.sql

Lines changed: 13 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -298,13 +298,13 @@ PhysicalSort
298298
│ ├── #45
299299
│ └── "FRANCE"
300300
├── PhysicalHashJoin { join_type: Inner, left_keys: [ #3 ], right_keys: [ #0 ] }
301-
│ ├── PhysicalHashJoin { join_type: Inner, left_keys: [ #0 ], right_keys: [ #2 ] }
302-
│ │ ├── PhysicalScan { table: supplier }
303-
│ │ └── PhysicalHashJoin { join_type: Inner, left_keys: [ #17 ], right_keys: [ #0 ] }
304-
│ │ ├── PhysicalHashJoin { join_type: Inner, left_keys: [ #0 ], right_keys: [ #0 ] }
305-
│ │ │ ├── PhysicalFilter { cond: Between { expr: #10, lower: Cast { cast_to: Date32, expr: "1995-01-01" }, upper: Cast { cast_to: Date32, expr: "1996-12-31" } } }
306-
│ │ │ │ └── PhysicalScan { table: lineitem }
307-
│ │ │ └── PhysicalScan { table: orders }
301+
│ ├── PhysicalHashJoin { join_type: Inner, left_keys: [ #7 ], right_keys: [ #0 ] }
302+
│ │ ├── PhysicalHashJoin { join_type: Inner, left_keys: [ #0 ], right_keys: [ #2 ] }
303+
│ │ │ ├── PhysicalScan { table: supplier }
304+
│ │ │ └── PhysicalFilter { cond: Between { expr: #10, lower: Cast { cast_to: Date32, expr: "1995-01-01" }, upper: Cast { cast_to: Date32, expr: "1996-12-31" } } }
305+
│ │ │ └── PhysicalScan { table: lineitem }
306+
│ │ └── PhysicalHashJoin { join_type: Inner, left_keys: [ #1 ], right_keys: [ #0 ] }
307+
│ │ ├── PhysicalScan { table: orders }
308308
│ │ └── PhysicalScan { table: customer }
309309
│ └── PhysicalScan { table: nation }
310310
└── PhysicalScan { table: nation }
@@ -469,14 +469,14 @@ PhysicalSort
469469
│ │ │ │ │ └── "ECONOMY ANODIZED STEEL"
470470
│ │ │ │ └── PhysicalScan { table: part }
471471
│ │ │ └── PhysicalScan { table: supplier }
472-
│ │ └── PhysicalHashJoin { join_type: Inner, left_keys: [ #17 ], right_keys: [ #0 ] }
472+
│ │ └── PhysicalHashJoin { join_type: Inner, left_keys: [ #28 ], right_keys: [ #0 ] }
473473
│ │ ├── PhysicalHashJoin { join_type: Inner, left_keys: [ #0 ], right_keys: [ #0 ] }
474474
│ │ │ ├── PhysicalScan { table: lineitem }
475-
│ │ │ └── PhysicalFilter { cond: Between { expr: #4, lower: Cast { cast_to: Date32, expr: "1995-01-01" }, upper: Cast { cast_to: Date32, expr: "1996-12-31" } } }
476-
│ │ │ └── PhysicalScan { table: orders }
477-
│ │ └── PhysicalHashJoin { join_type: Inner, left_keys: [ #3 ], right_keys: [ #0 ] }
478-
│ │ ├── PhysicalScan { table: customer }
479-
│ │ └── PhysicalScan { table: nation }
475+
│ │ │ └── PhysicalHashJoin { join_type: Inner, left_keys: [ #1 ], right_keys: [ #0 ] }
476+
│ │ │ ├── PhysicalFilter { cond: Between { expr: #4, lower: Cast { cast_to: Date32, expr: "1995-01-01" }, upper: Cast { cast_to: Date32, expr: "1996-12-31" } } }
477+
│ │ │ │ └── PhysicalScan { table: orders }
478+
│ │ │ └── PhysicalScan { table: customer }
479+
│ │ └── PhysicalScan { table: nation }
480480
│ └── PhysicalScan { table: nation }
481481
└── PhysicalFilter
482482
├── cond:Eq

‎optd-sqlplannertest/tests/tpch/tpch-16-20.planner.sql

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -180,7 +180,7 @@ PhysicalProjection
180180
├── cond:And
181181
│ ├── Eq
182182
│ │ ├── #2
183-
│ │ └── #0
183+
│ │ └── #4
184184
│ └── Lt
185185
│ ├── Cast { cast_to: Decimal128(30, 15), expr: #0 }
186186
│ └── #3

0 commit comments

Comments
 (0)