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)