[
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17388241#comment-17388241
]
Haisheng Yuan commented on CALCITE-4704:
----------------------------------------
I would suggest logging the matched partial tree only, instead of the whole
plan tree or the sub-trees. Otherwise, for each rule, we will see the plan tree
till the leaf node, even the leaf nodes don't participate the rule matching.
FYI, here is Orca optimizer's logging for transformation rule's result:
{code:java}
2021-07-27 11:22:53:888062 PDT,THD000,TRACE,"Xform: CXformGbAgg2StreamAgg
Input:
+--CLogicalGbAgg( Global ) Grp Cols: ["c" (9)][Global], Minimal Grp Cols: ["c"
(9)], Generates Duplicates :[ 1 ] rows:1 width:12 rebinds:1 origin:
[Grp:9, GrpExpr:1]
|--CLogicalGbAgg( Local ) Grp Cols: ["c" (9)][Local], Minimal Grp Cols: ["c"
(9)], Generates Duplicates :[ 1 ] rows:1 width:12 rebinds:1 origin:
[Grp:13, GrpExpr:0]
+--CScalarProjectList origin: [Grp:17, GrpExpr:0]
Output:
Alternatives:
0:
+--CPhysicalStreamAgg( Global, multi-stage ) Grp Cols: ["c" (9)], Minimal Grp
Cols:["c" (9)], Generates Duplicates :[ 1 ] cost:-0.500000
|--CLogicalGbAgg( Local ) Grp Cols: ["c" (9)][Local], Minimal Grp Cols: ["c"
(9)], Generates Duplicates :[ 1 ] rows:1 width:12 rebinds:1 origin:
[Grp:13, GrpExpr:0]
+--CScalarProjectList origin: [Grp:17, GrpExpr:0]
{code}
> Log produced plan after rule application using explain formatting
> -----------------------------------------------------------------
>
> Key: CALCITE-4704
> URL: https://issues.apache.org/jira/browse/CALCITE-4704
> Project: Calcite
> Issue Type: Improvement
> Components: core
> Affects Versions: 1.27.0
> Reporter: Stamatis Zampetakis
> Assignee: Stamatis Zampetakis
> Priority: Major
> Labels: pull-request-available
> Fix For: 1.28.0
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> In many cases, we want to identify which rule lead to a certain
> transformation in the plan or need to observe how the query plan evolves by
> applying some rules in order to fix some bug or find the right place to
> introduce another optimization step.
> Currently there are some logs during the application of a rule triggered by
> the
> [HepPlanner|https://github.com/apache/calcite/blob/e04f3b08dcfb6910ff4df3810772c346b25ed424/core/src/main/java/org/apache/calcite/plan/AbstractRelOptPlanner.java#L367]
> and
> [VolcanoPlanner|https://github.com/apache/calcite/blob/e04f3b08dcfb6910ff4df3810772c346b25ed424/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoRuleCall.java#L126]
> but they more or less display only the top operator of the transformation
> and not the whole subtree. Moreover, the {{RelNode#toString}} used in these
> logs, is not self-contained, so in order to check the transformation the log
> entry needs to be matched with other logs.
> It would help if instead of displaying only the top operator we logged the
> equivalent of explain (i.e., {{RelOptUtil.toString}}) on the transformed
> sub-tree.
> You can find below some extracts from the current logs and how the proposed
> log could look like.
> *HepPlanner*
> +Current logging+
> {noformat}
> 2021-07-27 14:37:58,252 [ForkJoinPool-1-worker-9] DEBUG - call#0: Rule
> FilterIntoJoinRule arguments
> [rel#9:LogicalFilter.NONE.[](input=HepRelVertex#8,condition==($7, $8)),
> rel#7:LogicalJoin.NONE.[](left=HepRelVertex#5,right=HepRelVertex#6,condition=true,joinType=left)]
> produced
> rel#14:LogicalProject.NONE.[](input=LogicalJoin#13,inputs=0..7,exprs=[CAST($8):TINYINT,
> $9, $10])
> 2021-07-27 14:37:58,266 [ForkJoinPool-1-worker-9] DEBUG - call#1: Rule
> ProjectJoinTransposeRule arguments
> [rel#16:LogicalProject.NONE.[](input=HepRelVertex#15,inputs=0..7,exprs=[CAST($8):TINYINT,
> $9, $10]),
> rel#13:LogicalJoin.NONE.[](left=HepRelVertex#5,right=HepRelVertex#6,condition==($7,
> $8),joinType=inner)] produced
> rel#21:LogicalProject.NONE.[](input=LogicalJoin#20,inputs=0..7,exprs=[$11,
> $9, $10])
> 2021-07-27 14:37:58,269 [ForkJoinPool-1-worker-9] DEBUG - call#3: Rule
> ProjectMergeRule arguments
> [rel#11:LogicalProject.NONE.[](input=HepRelVertex#27,exprs=[$1]),
> rel#26:LogicalProject.NONE.[](input=HepRelVertex#25,inputs=0..7,exprs=[$11,
> $9, $10])] produced
> rel#28:LogicalProject.NONE.[](input=HepRelVertex#25,exprs=[$1])
> 2021-07-27 14:37:58,272 [ForkJoinPool-1-worker-9] DEBUG - call#4: Rule
> ProjectJoinTransposeRule arguments
> [rel#28:LogicalProject.NONE.[](input=HepRelVertex#25,exprs=[$1]),
> rel#24:LogicalJoin.NONE.[](left=HepRelVertex#22,right=HepRelVertex#23,condition==($7,
> $8),joinType=inner)] produced
> rel#33:LogicalProject.NONE.[](input=LogicalJoin#32,inputs=0)
> 2021-07-27 14:37:58,274 [ForkJoinPool-1-worker-9] DEBUG - call#6: Rule
> ProjectMergeRule arguments
> [rel#30:LogicalProject.NONE.[](input=HepRelVertex#22,exprs=[$1, $7]),
> rel#18:LogicalProject.NONE.[0](input=HepRelVertex#5,inputs=0..7)] produced
> rel#40:LogicalProject.NONE.[](input=HepRelVertex#5,exprs=[$1, $7])
> 2021-07-27 14:37:58,275 [ForkJoinPool-1-worker-9] DEBUG - call#7: Rule
> ProjectMergeRule arguments
> [rel#31:LogicalProject.NONE.[0](input=HepRelVertex#23,inputs=0),
> rel#19:LogicalProject.NONE.[[0],
> [3]](input=HepRelVertex#6,inputs=0..2,exprs=[CAST($0):TINYINT])] produced
> rel#42:LogicalProject.NONE.[0](input=HepRelVertex#6,inputs=0)
> {noformat}
> +Proposed logging+
> {noformat}
> 2021-07-27 14:37:58,260 [ForkJoinPool-1-worker-9] DEBUG - Rule
> FilterIntoJoinRule produced:
> LogicalProject(EMPNO=[$0], ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4],
> SAL=[$5], COMM=[$6], DEPTNO=[$7], DEPTNO0=[CAST($8):TINYINT], DNAME=[$9],
> LOC=[$10])
> LogicalJoin(condition=[=($7, $8)], joinType=[inner])
> LogicalTableScan(table=[[scott, EMP]])
> LogicalTableScan(table=[[scott, DEPT]])
> 2021-07-27 14:37:58,267 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectJoinTransposeRule produced:
> LogicalProject(EMPNO=[$0], ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4],
> SAL=[$5], COMM=[$6], DEPTNO=[$7], DEPTNO0=[$11], DNAME=[$9], LOC=[$10])
> LogicalJoin(condition=[=($7, $8)], joinType=[inner])
> LogicalProject(EMPNO=[$0], ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4],
> SAL=[$5], COMM=[$6], DEPTNO=[$7])
> LogicalTableScan(table=[[scott, EMP]])
> LogicalProject(DEPTNO=[$0], DNAME=[$1], LOC=[$2],
> EXPR$0=[CAST($0):TINYINT])
> LogicalTableScan(table=[[scott, DEPT]])
> 2021-07-27 14:37:58,270 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectMergeRule produced:
> LogicalProject(ENAME=[$1])
> LogicalJoin(condition=[=($7, $8)], joinType=[inner])
> LogicalProject(EMPNO=[$0], ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4],
> SAL=[$5], COMM=[$6], DEPTNO=[$7])
> LogicalTableScan(table=[[scott, EMP]])
> LogicalProject(DEPTNO=[$0], DNAME=[$1], LOC=[$2],
> EXPR$0=[CAST($0):TINYINT])
> LogicalTableScan(table=[[scott, DEPT]])
> 2021-07-27 14:37:58,272 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectJoinTransposeRule produced:
> LogicalProject(ENAME=[$0])
> LogicalJoin(condition=[=($1, $2)], joinType=[inner])
> LogicalProject(ENAME=[$1], DEPTNO=[$7])
> LogicalProject(EMPNO=[$0], ENAME=[$1], JOB=[$2], MGR=[$3],
> HIREDATE=[$4], SAL=[$5], COMM=[$6], DEPTNO=[$7])
> LogicalTableScan(table=[[scott, EMP]])
> LogicalProject(DEPTNO=[$0])
> LogicalProject(DEPTNO=[$0], DNAME=[$1], LOC=[$2],
> EXPR$0=[CAST($0):TINYINT])
> LogicalTableScan(table=[[scott, DEPT]])
> 2021-07-27 14:37:58,274 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectMergeRule produced:
> LogicalProject(ENAME=[$1], DEPTNO=[$7])
> LogicalTableScan(table=[[scott, EMP]])
> 2021-07-27 14:37:58,275 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectMergeRule produced:
> LogicalProject(DEPTNO=[$0])
> LogicalTableScan(table=[[scott, DEPT]])
> {noformat}
> *VolcanoPlanner*
> +Current logging+
> {noformat}
> 2021-07-27 14:48:15,846 [ForkJoinPool-1-worker-9] DEBUG - call#3: Apply rule
> [FilterIntoJoinRule] to
> [rel#9:LogicalFilter.NONE.[](input=RelSubset#8,condition==($7, $8)),
> rel#7:LogicalJoin.NONE.[](left=RelSubset#5,right=RelSubset#6,condition=true,joinType=left)]
> 2021-07-27 14:48:15,850 [ForkJoinPool-1-worker-9] DEBUG - Transform to:
> rel#14 via FilterIntoJoinRule
> 2021-07-27 14:48:15,851 [ForkJoinPool-1-worker-9] TRACE - call#3: Rule
> FilterIntoJoinRule arguments
> [rel#9:LogicalFilter.NONE.[](input=RelSubset#8,condition==($7, $8)),
> rel#7:LogicalJoin.NONE.[](left=RelSubset#5,right=RelSubset#6,condition=true,joinType=left)]
> created rel#14:LogicalProject
> 2021-07-27 14:48:15,858 [ForkJoinPool-1-worker-9] DEBUG - call#10: Apply rule
> [ProjectJoinTransposeRule] to
> [rel#16:LogicalProject.NONE.[](input=RelSubset#15,inputs=0..7,exprs=[CAST($8):TINYINT,
> $9, $10]),
> rel#13:LogicalJoin.NONE.[](left=RelSubset#5,right=RelSubset#6,condition==($7,
> $8),joinType=inner)]
> 2021-07-27 14:48:15,863 [ForkJoinPool-1-worker-9] DEBUG - Transform to:
> rel#20 via ProjectJoinTransposeRule
> 2021-07-27 14:48:15,863 [ForkJoinPool-1-worker-9] TRACE - call#10: Rule
> ProjectJoinTransposeRule arguments
> [rel#16:LogicalProject.NONE.[](input=RelSubset#15,inputs=0..7,exprs=[CAST($8):TINYINT,
> $9, $10]),
> rel#13:LogicalJoin.NONE.[](left=RelSubset#5,right=RelSubset#6,condition==($7,
> $8),joinType=inner)] created rel#20:LogicalProject
> 2021-07-27 14:48:15,873 [ForkJoinPool-1-worker-9] DEBUG - call#13: Apply rule
> [ProjectMergeRule] to
> [rel#11:LogicalProject.NONE.[](input=RelSubset#10,exprs=[$1]),
> rel#16:LogicalProject.NONE.[](input=RelSubset#15,inputs=0..7,exprs=[CAST($8):TINYINT,
> $9, $10])]
> 2021-07-27 14:48:15,874 [ForkJoinPool-1-worker-9] DEBUG - Transform to:
> rel#26 via ProjectMergeRule
> 2021-07-27 14:48:15,874 [ForkJoinPool-1-worker-9] TRACE - call#13: Rule
> ProjectMergeRule arguments
> [rel#11:LogicalProject.NONE.[](input=RelSubset#10,exprs=[$1]),
> rel#16:LogicalProject.NONE.[](input=RelSubset#15,inputs=0..7,exprs=[CAST($8):TINYINT,
> $9, $10])] created rel#26:LogicalProject
> 2021-07-27 14:48:15,884 [ForkJoinPool-1-worker-9] DEBUG - call#26: Apply rule
> [ProjectMergeRule] to
> [rel#11:LogicalProject.NONE.[](input=RelSubset#10,exprs=[$1]),
> rel#25:LogicalProject.NONE.[](input=RelSubset#24,inputs=0..7,exprs=[$11, $9,
> $10])]
> 2021-07-27 14:48:15,885 [ForkJoinPool-1-worker-9] DEBUG - Transform to:
> rel#27 via ProjectMergeRule
> 2021-07-27 14:48:15,885 [ForkJoinPool-1-worker-9] TRACE - call#26: Rule
> ProjectMergeRule arguments
> [rel#11:LogicalProject.NONE.[](input=RelSubset#10,exprs=[$1]),
> rel#25:LogicalProject.NONE.[](input=RelSubset#24,inputs=0..7,exprs=[$11, $9,
> $10])] created rel#27:LogicalProject
> 2021-07-27 14:48:15,889 [ForkJoinPool-1-worker-9] DEBUG - call#28: Apply rule
> [ProjectJoinTransposeRule] to
> [rel#26:LogicalProject.NONE.[](input=RelSubset#15,exprs=[$1]),
> rel#13:LogicalJoin.NONE.[](left=RelSubset#5,right=RelSubset#6,condition==($7,
> $8),joinType=inner)]
> 2021-07-27 14:48:15,890 [ForkJoinPool-1-worker-9] DEBUG - Transform to:
> rel#31 via ProjectJoinTransposeRule
> 2021-07-27 14:48:15,890 [ForkJoinPool-1-worker-9] TRACE - call#28: Rule
> ProjectJoinTransposeRule arguments
> [rel#26:LogicalProject.NONE.[](input=RelSubset#15,exprs=[$1]),
> rel#13:LogicalJoin.NONE.[](left=RelSubset#5,right=RelSubset#6,condition==($7,
> $8),joinType=inner)] created rel#31:LogicalProject
> 2021-07-27 14:48:15,897 [ForkJoinPool-1-worker-9] DEBUG - call#32: Apply rule
> [ProjectJoinTransposeRule] to
> [rel#27:LogicalProject.NONE.[](input=RelSubset#24,exprs=[$1]),
> rel#23:LogicalJoin.NONE.[](left=RelSubset#21,right=RelSubset#22,condition==($7,
> $8),joinType=inner)]
> 2021-07-27 14:48:15,898 [ForkJoinPool-1-worker-9] DEBUG - Transform to:
> rel#40 via ProjectJoinTransposeRule
> 2021-07-27 14:48:15,898 [ForkJoinPool-1-worker-9] TRACE - call#32: Rule
> ProjectJoinTransposeRule arguments
> [rel#27:LogicalProject.NONE.[](input=RelSubset#24,exprs=[$1]),
> rel#23:LogicalJoin.NONE.[](left=RelSubset#21,right=RelSubset#22,condition==($7,
> $8),joinType=inner)] created rel#40:LogicalProject
> 2021-07-27 14:48:15,909 [ForkJoinPool-1-worker-9] DEBUG - call#49: Apply rule
> [ProjectMergeRule] to
> [rel#37:LogicalProject.NONE.[](input=RelSubset#21,exprs=[$1, $7]),
> rel#17:LogicalProject.NONE.[0](input=RelSubset#5,inputs=0..7)]
> 2021-07-27 14:48:15,909 [ForkJoinPool-1-worker-9] DEBUG - Transform to:
> rel#46 via ProjectMergeRule
> 2021-07-27 14:48:15,909 [ForkJoinPool-1-worker-9] TRACE - call#49: Rule
> ProjectMergeRule arguments
> [rel#37:LogicalProject.NONE.[](input=RelSubset#21,exprs=[$1, $7]),
> rel#17:LogicalProject.NONE.[0](input=RelSubset#5,inputs=0..7)] created
> rel#46:LogicalProject
> 2021-07-27 14:48:15,914 [ForkJoinPool-1-worker-9] DEBUG - call#53: Apply rule
> [ProjectMergeRule] to
> [rel#38:LogicalProject.NONE.[](input=RelSubset#22,inputs=0),
> rel#18:LogicalProject.NONE.[[0],
> [3]](input=RelSubset#6,inputs=0..2,exprs=[CAST($0):TINYINT])]
> 2021-07-27 14:48:15,915 [ForkJoinPool-1-worker-9] DEBUG - Transform to:
> rel#47 via ProjectMergeRule
> 2021-07-27 14:48:15,915 [ForkJoinPool-1-worker-9] TRACE - call#53: Rule
> ProjectMergeRule arguments
> [rel#38:LogicalProject.NONE.[](input=RelSubset#22,inputs=0),
> rel#18:LogicalProject.NONE.[[0],
> [3]](input=RelSubset#6,inputs=0..2,exprs=[CAST($0):TINYINT])] created
> rel#47:LogicalProject
> {noformat}
> +Proposed logging+
> {noformat}
> 2021-07-27 14:48:15,854 [ForkJoinPool-1-worker-9] DEBUG - Rule
> FilterIntoJoinRule produced:
> LogicalProject(EMPNO=[$0], ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4],
> SAL=[$5], COMM=[$6], DEPTNO=[$7], DEPTNO0=[CAST($8):TINYINT], DNAME=[$9],
> LOC=[$10])
> LogicalJoin(condition=[=($7, $8)], joinType=[inner])
> LogicalTableScan(subset=[rel#5:RelSubset#0.NONE.[0]], table=[[scott,
> EMP]])
> LogicalTableScan(subset=[rel#6:RelSubset#1.NONE.[0]], table=[[scott,
> DEPT]])
> 2021-07-27 14:48:15,867 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectJoinTransposeRule produced:
> LogicalProject(EMPNO=[$0], ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4],
> SAL=[$5], COMM=[$6], DEPTNO=[$7], DEPTNO0=[$11], DNAME=[$9], LOC=[$10])
> LogicalJoin(condition=[=($7, $8)], joinType=[inner])
> LogicalProject(EMPNO=[$0], ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4],
> SAL=[$5], COMM=[$6], DEPTNO=[$7])
> LogicalTableScan(subset=[rel#5:RelSubset#0.NONE.[0]], table=[[scott,
> EMP]])
> LogicalProject(DEPTNO=[$0], DNAME=[$1], LOC=[$2],
> EXPR$0=[CAST($0):TINYINT])
> LogicalTableScan(subset=[rel#6:RelSubset#1.NONE.[0]], table=[[scott,
> DEPT]])
> 2021-07-27 14:48:15,875 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectMergeRule produced:
> LogicalProject(ENAME=[$1])
> LogicalJoin(subset=[rel#15:RelSubset#5.NONE.[]], condition=[=($7, $8)],
> joinType=[inner])
> LogicalTableScan(subset=[rel#5:RelSubset#0.NONE.[0]], table=[[scott,
> EMP]])
> LogicalTableScan(subset=[rel#6:RelSubset#1.NONE.[0]], table=[[scott,
> DEPT]])
> 2021-07-27 14:48:15,886 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectMergeRule produced:
> LogicalProject(ENAME=[$1])
> LogicalJoin(subset=[rel#24:RelSubset#8.NONE.[]], condition=[=($7, $8)],
> joinType=[inner])
> LogicalProject(subset=[rel#21:RelSubset#6.NONE.[0]], EMPNO=[$0],
> ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4], SAL=[$5], COMM=[$6],
> DEPTNO=[$7])
> LogicalTableScan(subset=[rel#5:RelSubset#0.NONE.[0]], table=[[scott,
> EMP]])
> LogicalProject(subset=[rel#22:RelSubset#7.NONE.[]], DEPTNO=[$0],
> DNAME=[$1], LOC=[$2], EXPR$0=[CAST($0):TINYINT])
> LogicalTableScan(subset=[rel#6:RelSubset#1.NONE.[0]], table=[[scott,
> DEPT]])
> 2021-07-27 14:48:15,893 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectJoinTransposeRule produced:
> LogicalProject(ENAME=[$0])
> LogicalJoin(condition=[=($1, $2)], joinType=[inner])
> LogicalProject(ENAME=[$1], DEPTNO=[$7])
> LogicalTableScan(subset=[rel#5:RelSubset#0.NONE.[0]], table=[[scott,
> EMP]])
> LogicalProject(DEPTNO=[$0])
> LogicalTableScan(subset=[rel#6:RelSubset#1.NONE.[0]], table=[[scott,
> DEPT]])
> 2021-07-27 14:48:15,901 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectJoinTransposeRule produced:
> LogicalProject(ENAME=[$0])
> LogicalJoin(condition=[=($1, $2)], joinType=[inner])
> LogicalProject(ENAME=[$1], DEPTNO=[$7])
> LogicalProject(subset=[rel#21:RelSubset#6.NONE.[0]], EMPNO=[$0],
> ENAME=[$1], JOB=[$2], MGR=[$3], HIREDATE=[$4], SAL=[$5], COMM=[$6],
> DEPTNO=[$7])
> LogicalTableScan(subset=[rel#5:RelSubset#0.NONE.[0]], table=[[scott,
> EMP]])
> LogicalProject(DEPTNO=[$0])
> LogicalProject(subset=[rel#22:RelSubset#7.NONE.[]], DEPTNO=[$0],
> DNAME=[$1], LOC=[$2], EXPR$0=[CAST($0):TINYINT])
> LogicalTableScan(subset=[rel#6:RelSubset#1.NONE.[0]], table=[[scott,
> DEPT]])
> 2021-07-27 14:48:15,911 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectMergeRule produced:
> LogicalProject(ENAME=[$1], DEPTNO=[$7])
> LogicalTableScan(subset=[rel#5:RelSubset#0.NONE.[0]], table=[[scott, EMP]])
> 2021-07-27 14:48:15,916 [ForkJoinPool-1-worker-9] DEBUG - Rule
> ProjectMergeRule produced:
> LogicalProject(DEPTNO=[$0])
> LogicalTableScan(subset=[rel#6:RelSubset#1.NONE.[0]], table=[[scott, DEPT]])
> {noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
