[
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17388591#comment-17388591
]
Stamatis Zampetakis commented on CALCITE-4704:
----------------------------------------------
[~hyuan] Seeing the complete tree after each rule application may be verbose
but if it can be enabled/disabled on demand as [~vladimirsitnikov] suggested I
don't see a big problem with moving forward with this change. Moreover, I
wouldn't say that it is useless since like that it is easier to see the
evolution of the plan especially when the same rule applies to multiple parts
of the query.
> 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)
