Stamatis Zampetakis created CALCITE-4704:
--------------------------------------------
Summary: 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
Fix For: 1.28.0
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)
