Uploaded image for project: 'Calcite'
  1. Calcite
  2. CALCITE-4704

Log produced plan after rule application using explain formatting

    XMLWordPrintableJSON

Details

    • Improvement
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 1.27.0
    • 1.29.0
    • core

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

      Attachments

        Issue Links

          is related to

          Improvement - An improvement or enhancement to an existing feature or task. CALCITE-4991 Improve RuleEventLogger to also print input rels in FULL_PLAN mode

          • Major - Major loss of function.
          • Closed

          Task - A task that needs to be done. HIVE-25816 Log CBO plan after rule application for debugging purposes

          • Major - Major loss of function.
          • Closed
          links to

          Web Link GitHub Pull Request #2469

          Activity

            People

              zabetak Stamatis Zampetakis
              zabetak Stamatis Zampetakis
              Votes:
              2 Vote for this issue
              Watchers:
              9 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 0.5h
                  0.5h