[CALCITE-4704] Log produced plan after rule application using explain formatting

• Type: Improvement
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.27.0
• Fix Version/s: 1.29.0
• Component/s: core
• Labels: pull-request-available
• Assignee: Stamatis Zampetakis
• Reporter: Stamatis Zampetakis
• Created: 27/Jul/21 12:01
• Updated: 21/Jan/22 10:46
• Resolved: 04/Jan/22 08:27

Description

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 and VolcanoPlanner 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

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)

Proposed logging

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]])

VolcanoPlanner
Current logging

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

Proposed logging

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]])

Issue Links

• is related to: CALCITE-4991 Improve RuleEventLogger to also print input rels in FULL_PLAN mode
• is related to: HIVE-25816 Log CBO plan after rule application for debugging purposes
• links to: GitHub Pull Request #2469