[ https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17388245#comment-17388245 ]
Haisheng Yuan commented on CALCITE-4704: ---------------------------------------- For complicated queries, i.e. tpcds queries, the proposed change to log the whole tree will just print out much more useless tree nodes. So I am against the change. However making the log format and information more readable is worth doing. > 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)