[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-12-17 Thread Julian Hyde (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17461796#comment-17461796
 ] 

Julian Hyde commented on CALCITE-4704:
--

[~zabetak], Can you get this in before 1.29?

> 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.29.0
>
>  Time Spent: 20m
>  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:
>  

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-12-10 Thread Stamatis Zampetakis (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17457188#comment-17457188
 ] 

Stamatis Zampetakis commented on CALCITE-4704:
--

I updated the pull request and added an SLF4J marker for the log message 
carrying the plan in explain format. Using the marker users can decide (via 
their logger configuration) if they want to see or not the more verbose message 
with the full plan.

I will probably merge the PR in the following days so if you have more comments 
please let me know.

> 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.29.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], 

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-10-12 Thread Stamatis Zampetakis (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17427910#comment-17427910
 ] 

Stamatis Zampetakis commented on CALCITE-4704:
--

It might be hard to finalize in the next day or so. I will move it to 1.29.0.

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

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-10-12 Thread Julian Hyde (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17427491#comment-17427491
 ] 

Julian Hyde commented on CALCITE-4704:
--

[~zabetak], Can you get this in before 1.28?

> 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:
>  

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-09-11 Thread Xurenhe (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17413483#comment-17413483
 ] 

Xurenhe commented on CALCITE-4704:
--

+1
It's wonderful feature.

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

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-09-09 Thread Haisheng Yuan (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17412755#comment-17412755
 ] 

Haisheng Yuan commented on CALCITE-4704:


OK, cancelling my -1. Change it to +1. :)

> 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:
>  

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-09-09 Thread Alessandro Solimando (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17412391#comment-17412391
 ] 

Alessandro Solimando commented on CALCITE-4704:
---

I find the feature very useful and I am using it already for debugging plan 
issues (I am cherrypicking the changes for now when needed, it would be great 
to have it in Calcite).

I understand [~hyuan]'s concern, but I think that adding this extra logging 
capability conditionally (as already proposed) is acceptable.

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

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-07-28 Thread Stamatis Zampetakis (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=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], 

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-07-27 Thread Haisheng Yuan (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=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])
> 

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-07-27 Thread Haisheng Yuan (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17388241#comment-17388241
 ] 

Haisheng Yuan commented on CALCITE-4704:


I would suggest logging the matched partial tree only, instead of the whole 
plan tree or the sub-trees. Otherwise, for each rule, we will see the plan tree 
till the leaf node, even the leaf nodes don't participate the rule matching. 
FYI, here is Orca optimizer's logging for transformation rule's result:

{code:java}
2021-07-27 11:22:53:888062 PDT,THD000,TRACE,"Xform: CXformGbAgg2StreamAgg
Input:
+--CLogicalGbAgg( Global ) Grp Cols: ["c" (9)][Global], Minimal Grp Cols: ["c" 
(9)], Generates Duplicates :[ 1 ]rows:1   width:12  rebinds:1   origin: 
[Grp:9, GrpExpr:1]
   |--CLogicalGbAgg( Local ) Grp Cols: ["c" (9)][Local], Minimal Grp Cols: ["c" 
(9)], Generates Duplicates :[ 1 ]rows:1   width:12  rebinds:1   origin: 
[Grp:13, GrpExpr:0]
   +--CScalarProjectList   origin: [Grp:17, GrpExpr:0]

Output:
Alternatives:
0:
+--CPhysicalStreamAgg( Global, multi-stage ) Grp Cols: ["c" (9)], Minimal Grp 
Cols:["c" (9)], Generates Duplicates :[ 1 ]cost:-0.50
   |--CLogicalGbAgg( Local ) Grp Cols: ["c" (9)][Local], Minimal Grp Cols: ["c" 
(9)], Generates Duplicates :[ 1 ]rows:1   width:12  rebinds:1   origin: 
[Grp:13, GrpExpr:0]
   +--CScalarProjectList   origin: [Grp:17, GrpExpr:0]
{code}
 

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

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-07-27 Thread Vladimir Sitnikov (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17388164#comment-17388164
 ] 

Vladimir Sitnikov commented on CALCITE-4704:


{quote} by extra category? A separate logger? {quote}
Yes, something like 
{code:java}
private static final Logger SHORT_PLANS;
private static final Logger FULL_PLANS;
...
{code}

{quote}Do you mean  "before"/"after" registering the produced RelNode. {quote}
I mean "before rule application" and "after rule application"


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

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-07-27 Thread Stamatis Zampetakis (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17388155#comment-17388155
 ] 

Stamatis Zampetakis commented on CALCITE-4704:
--

Thanks for the feedback! I created a PR with an initial proposal.

[~vladimirsitnikov] what do you mean by extra category? A separate logger? 

I'm not sure what you mean by "before" and "after" explains. Do you mean  
"before"/"after" registering the produced \{{RelNode}}. 

Logging the entire tree can indeed be quite verbose as opposed to the current 
situation so I am fine delegating this to a new logger or using another logging 
level.

The {{alter session trace}} idea is nice but I think it is tailored around 
use-cases where we are running Calcite as "stand-alone" application. I am 
mostly interested to have enough debug information even when a project uses 
directly the planner APIs.

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

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-07-27 Thread Vladimir Sitnikov (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17388040#comment-17388040
 ] 

Vladimir Sitnikov commented on CALCITE-4704:


How about adding an extra category for the full tree logging so one can 
explicitly enable or disable tree logging?

I'm afraid if we always log "before and after" explains, the system would log 
too much information.

Side ideas:
a) log "after" plans as "diffs"
b) implement "per-session trace file". For instance: "alter session trace 
(explain) to ...; explain plan for ...; alter session disable trace". Then 
fine-grained output could be written to a dedicated trace file so it is might 
be easier to parse in the future (e.g. open with visualizers, etc)


> 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
> 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:
>  

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-07-27 Thread duan xiong (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17388033#comment-17388033
 ] 

duan xiong commented on CALCITE-4704:
-

+1. 

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

[jira] [Commented] (CALCITE-4704) Log produced plan after rule application using explain formatting

2021-07-27 Thread Stamatis Zampetakis (Jira)


[ 
https://issues.apache.org/jira/browse/CALCITE-4704?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17388002#comment-17388002
 ] 

Stamatis Zampetakis commented on CALCITE-4704:
--

We could either modify the existing logging to display the plan using 
{{RelOptUtil#toString}} or add additional logging possibly by adding a new 
{{RelOptListener.}}

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