[ https://issues.apache.org/jira/browse/CALCITE-3257?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Xiening Dai updated CALCITE-3257: --------------------------------- Description: To repro - 1. Set Log4J log level to TRACE. So planner will dump rel node info every time at rule match (https://github.com/apache/calcite/blob/3124a85b93ff2f1b79484c7bd4cc41835d4f1920/core/src/main/java/org/apache/calcite/plan/volcano/RuleQueue.java#L435) 2. Run JdbcTest.testInnerJoinValues. Get below exception - java.lang.AssertionError: rel [rel#2128:EnumerableProject.ENUMERABLE.[](input=RelSubset#2122,EMPNO=$0,DESC=$3)] has lower cost {309.75 rows, 215.5 cpu, 0.0 io} than best cost {322.5 rows, 241.0 cpu, 0.0 io} of subset [rel#2119:Subset#5.ENUMERABLE.[]] at org.apache.calcite.util.Litmus$1.fail(Litmus.java:31) at org.apache.calcite.plan.volcano.VolcanoPlanner.isValid(VolcanoPlanner.java:888) at org.apache.calcite.plan.volcano.VolcanoPlanner.register(VolcanoPlanner.java:851) at org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:868) at org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:90) at org.apache.calcite.rel.AbstractRelNode.onRegister(AbstractRelNode.java:329) at org.apache.calcite.plan.volcano.VolcanoPlanner.registerImpl(VolcanoPlanner.java:1656) at org.apache.calcite.plan.volcano.VolcanoPlanner.register(VolcanoPlanner.java:846) at org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:868) at org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:1927) at org.apache.calcite.plan.volcano.VolcanoRuleCall.transformTo(VolcanoRuleCall.java:129) at org.apache.calcite.plan.RelOptRuleCall.transformTo(RelOptRuleCall.java:236) at org.apache.calcite.rel.rules.AggregateProjectMergeRule.onMatch(AggregateProjectMergeRule.java:74) at org.apache.calcite.plan.volcano.VolcanoRuleCall.onMatch(VolcanoRuleCall.java:208) at org.apache.calcite.plan.volcano.VolcanoPlanner.findBestExp(VolcanoPlanner.java:631) at org.apache.calcite.tools.Programs.lambda$standard$3(Programs.java:286) at org.apache.calcite.tools.Programs$SequenceProgram.run(Programs.java:346) at org.apache.calcite.prepare.Prepare.optimize(Prepare.java:189) at org.apache.calcite.prepare.Prepare.prepareSql(Prepare.java:314) at org.apache.calcite.prepare.Prepare.prepareSql(Prepare.java:231) at org.apache.calcite.prepare.CalcitePrepareImpl.prepare2_(CalcitePrepareImpl.java:638) at org.apache.calcite.prepare.CalcitePrepareImpl.prepare_(CalcitePrepareImpl.java:502) at org.apache.calcite.prepare.CalcitePrepareImpl.prepareSql(CalcitePrepareImpl.java:472) at org.apache.calcite.jdbc.CalciteConnectionImpl.parseQuery(CalciteConnectionImpl.java:231) at org.apache.calcite.jdbc.CalciteMetaImpl.prepareAndExecute(CalciteMetaImpl.java:550) at org.apache.calcite.avatica.AvaticaConnection.prepareAndExecuteInternal(AvaticaConnection.java:675) at org.apache.calcite.avatica.AvaticaStatement.executeInternal(AvaticaStatement.java:156) at org.apache.calcite.avatica.AvaticaStatement.executeQuery(AvaticaStatement.java:227) at org.apache.calcite.test.CalciteAssert.assertQuery(CalciteAssert.java:522) at org.apache.calcite.test.CalciteAssert$AssertQuery.lambda$returns$1(CalciteAssert.java:1466) at org.apache.calcite.test.CalciteAssert$AssertQuery.withConnection(CalciteAssert.java:1398) at org.apache.calcite.test.CalciteAssert$AssertQuery.returns(CalciteAssert.java:1464) at org.apache.calcite.test.CalciteAssert$AssertQuery.explainMatches(CalciteAssert.java:1561) at org.apache.calcite.test.CalciteAssert$AssertQuery.explainContains(CalciteAssert.java:1556) at org.apache.calcite.test.JdbcTest.testInnerJoinValues(JdbcTest.java:2580) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.junit.runner.JUnitCore.run(JUnitCore.java:137) at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47) at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242) at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70) Suppressed: org.apache.calcite.util.TestUtil$ExtraInformation: With materializationsEnabled=false, limit=0, sql=explain plan for select empno, desc from sales.emps, (SELECT * FROM (VALUES (10, 'SameName')) AS t (id, desc)) as sn where emps.deptno = sn.id and sn.desc = 'SameName' group by empno, desc at org.apache.calcite.util.TestUtil.rethrow(TestUtil.java:268) at org.apache.calcite.test.CalciteAssert.assertQuery(CalciteAssert.java:554) ... 28 more was: To repro - 1. Set Log4J log level to TRACE. So planner will dump rel node info every time at rule match (https://github.com/apache/calcite/blob/3124a85b93ff2f1b79484c7bd4cc41835d4f1920/core/src/main/java/org/apache/calcite/plan/volcano/RuleQueue.java#L435) 2. Run JdbcTest.testInnerJoinValues. Get below exception - java.lang.AssertionError: rel [rel#2128:EnumerableProject.ENUMERABLE.[](input=RelSubset#2122,EMPNO=$0,DESC=$3)] has lower cost {309.75 rows, 215.5 cpu, 0.0 io} than best cost {322.5 rows, 241.0 cpu, 0.0 io} of subset [rel#2119:Subset#5.ENUMERABLE.[]] at org.apache.calcite.util.Litmus$1.fail(Litmus.java:31) at org.apache.calcite.plan.volcano.VolcanoPlanner.isValid(VolcanoPlanner.java:888) at org.apache.calcite.plan.volcano.VolcanoPlanner.register(VolcanoPlanner.java:851) at org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:868) at org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:90) at org.apache.calcite.rel.AbstractRelNode.onRegister(AbstractRelNode.java:329) at org.apache.calcite.plan.volcano.VolcanoPlanner.registerImpl(VolcanoPlanner.java:1656) at org.apache.calcite.plan.volcano.VolcanoPlanner.register(VolcanoPlanner.java:846) at org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:868) at org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:1927) at org.apache.calcite.plan.volcano.VolcanoRuleCall.transformTo(VolcanoRuleCall.java:129) at org.apache.calcite.plan.RelOptRuleCall.transformTo(RelOptRuleCall.java:236) at org.apache.calcite.rel.rules.AggregateProjectMergeRule.onMatch(AggregateProjectMergeRule.java:74) at org.apache.calcite.plan.volcano.VolcanoRuleCall.onMatch(VolcanoRuleCall.java:208) at org.apache.calcite.plan.volcano.VolcanoPlanner.findBestExp(VolcanoPlanner.java:631) at org.apache.calcite.tools.Programs.lambda$standard$3(Programs.java:286) at org.apache.calcite.tools.Programs$SequenceProgram.run(Programs.java:346) at org.apache.calcite.prepare.Prepare.optimize(Prepare.java:189) at org.apache.calcite.prepare.Prepare.prepareSql(Prepare.java:314) at org.apache.calcite.prepare.Prepare.prepareSql(Prepare.java:231) at org.apache.calcite.prepare.CalcitePrepareImpl.prepare2_(CalcitePrepareImpl.java:638) at org.apache.calcite.prepare.CalcitePrepareImpl.prepare_(CalcitePrepareImpl.java:502) at org.apache.calcite.prepare.CalcitePrepareImpl.prepareSql(CalcitePrepareImpl.java:472) at org.apache.calcite.jdbc.CalciteConnectionImpl.parseQuery(CalciteConnectionImpl.java:231) at org.apache.calcite.jdbc.CalciteMetaImpl.prepareAndExecute(CalciteMetaImpl.java:550) at org.apache.calcite.avatica.AvaticaConnection.prepareAndExecuteInternal(AvaticaConnection.java:675) at org.apache.calcite.avatica.AvaticaStatement.executeInternal(AvaticaStatement.java:156) at org.apache.calcite.avatica.AvaticaStatement.executeQuery(AvaticaStatement.java:227) at org.apache.calcite.test.CalciteAssert.assertQuery(CalciteAssert.java:522) at org.apache.calcite.test.CalciteAssert$AssertQuery.lambda$returns$1(CalciteAssert.java:1466) at org.apache.calcite.test.CalciteAssert$AssertQuery.withConnection(CalciteAssert.java:1398) at org.apache.calcite.test.CalciteAssert$AssertQuery.returns(CalciteAssert.java:1464) at org.apache.calcite.test.CalciteAssert$AssertQuery.explainMatches(CalciteAssert.java:1561) at org.apache.calcite.test.CalciteAssert$AssertQuery.explainContains(CalciteAssert.java:1556) at org.apache.calcite.test.JdbcTest.testInnerJoinValues(JdbcTest.java:2580) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.junit.runner.JUnitCore.run(JUnitCore.java:137) at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47) at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242) at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70) Suppressed: org.apache.calcite.util.TestUtil$ExtraInformation: With materializationsEnabled=false, limit=0, sql=explain plan for select empno, desc from sales.emps, (SELECT * FROM (VALUES (10, 'SameName')) AS t (id, desc)) as sn where emps.deptno = sn.id and sn.desc = 'SameName' group by empno, desc at org.apache.calcite.util.TestUtil.rethrow(TestUtil.java:268) at org.apache.calcite.test.CalciteAssert.assertQuery(CalciteAssert.java:554) ... 28 more A simple fix will just add a call to RelOptCluster.invalidateMetadataQuery() after dumping rel nodes. > Need to clear RelMetaDataQuery cache after dumping RelNodes and Graphviz > ------------------------------------------------------------------------ > > Key: CALCITE-3257 > URL: https://issues.apache.org/jira/browse/CALCITE-3257 > Project: Calcite > Issue Type: Bug > Components: core > Reporter: Xiening Dai > Priority: Major > > To repro - > 1. Set Log4J log level to TRACE. So planner will dump rel node info every > time at rule match > (https://github.com/apache/calcite/blob/3124a85b93ff2f1b79484c7bd4cc41835d4f1920/core/src/main/java/org/apache/calcite/plan/volcano/RuleQueue.java#L435) > 2. Run JdbcTest.testInnerJoinValues. Get below exception - > java.lang.AssertionError: rel > [rel#2128:EnumerableProject.ENUMERABLE.[](input=RelSubset#2122,EMPNO=$0,DESC=$3)] > has lower cost {309.75 rows, 215.5 cpu, 0.0 io} than best cost {322.5 rows, > 241.0 cpu, 0.0 io} of subset [rel#2119:Subset#5.ENUMERABLE.[]] > at org.apache.calcite.util.Litmus$1.fail(Litmus.java:31) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.isValid(VolcanoPlanner.java:888) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.register(VolcanoPlanner.java:851) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:868) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:90) > at > org.apache.calcite.rel.AbstractRelNode.onRegister(AbstractRelNode.java:329) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.registerImpl(VolcanoPlanner.java:1656) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.register(VolcanoPlanner.java:846) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:868) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:1927) > at > org.apache.calcite.plan.volcano.VolcanoRuleCall.transformTo(VolcanoRuleCall.java:129) > at > org.apache.calcite.plan.RelOptRuleCall.transformTo(RelOptRuleCall.java:236) > at > org.apache.calcite.rel.rules.AggregateProjectMergeRule.onMatch(AggregateProjectMergeRule.java:74) > at > org.apache.calcite.plan.volcano.VolcanoRuleCall.onMatch(VolcanoRuleCall.java:208) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.findBestExp(VolcanoPlanner.java:631) > at > org.apache.calcite.tools.Programs.lambda$standard$3(Programs.java:286) > at > org.apache.calcite.tools.Programs$SequenceProgram.run(Programs.java:346) > at org.apache.calcite.prepare.Prepare.optimize(Prepare.java:189) > at org.apache.calcite.prepare.Prepare.prepareSql(Prepare.java:314) > at org.apache.calcite.prepare.Prepare.prepareSql(Prepare.java:231) > at > org.apache.calcite.prepare.CalcitePrepareImpl.prepare2_(CalcitePrepareImpl.java:638) > at > org.apache.calcite.prepare.CalcitePrepareImpl.prepare_(CalcitePrepareImpl.java:502) > at > org.apache.calcite.prepare.CalcitePrepareImpl.prepareSql(CalcitePrepareImpl.java:472) > at > org.apache.calcite.jdbc.CalciteConnectionImpl.parseQuery(CalciteConnectionImpl.java:231) > at > org.apache.calcite.jdbc.CalciteMetaImpl.prepareAndExecute(CalciteMetaImpl.java:550) > at > org.apache.calcite.avatica.AvaticaConnection.prepareAndExecuteInternal(AvaticaConnection.java:675) > at > org.apache.calcite.avatica.AvaticaStatement.executeInternal(AvaticaStatement.java:156) > at > org.apache.calcite.avatica.AvaticaStatement.executeQuery(AvaticaStatement.java:227) > at > org.apache.calcite.test.CalciteAssert.assertQuery(CalciteAssert.java:522) > at > org.apache.calcite.test.CalciteAssert$AssertQuery.lambda$returns$1(CalciteAssert.java:1466) > at > org.apache.calcite.test.CalciteAssert$AssertQuery.withConnection(CalciteAssert.java:1398) > at > org.apache.calcite.test.CalciteAssert$AssertQuery.returns(CalciteAssert.java:1464) > at > org.apache.calcite.test.CalciteAssert$AssertQuery.explainMatches(CalciteAssert.java:1561) > at > org.apache.calcite.test.CalciteAssert$AssertQuery.explainContains(CalciteAssert.java:1556) > at > org.apache.calcite.test.JdbcTest.testInnerJoinValues(JdbcTest.java:2580) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:498) > at > org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) > at > org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) > at > org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) > at > org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) > at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) > at > org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) > at > org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) > at org.junit.runners.ParentRunner.run(ParentRunner.java:363) > at org.junit.runner.JUnitCore.run(JUnitCore.java:137) > at > com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68) > at > com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47) > at > com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242) > at > com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70) > Suppressed: org.apache.calcite.util.TestUtil$ExtraInformation: With > materializationsEnabled=false, limit=0, sql=explain plan for select empno, > desc from sales.emps, > (SELECT * FROM (VALUES (10, 'SameName')) AS t (id, desc)) as sn > where emps.deptno = sn.id and sn.desc = 'SameName' group by empno, desc > at org.apache.calcite.util.TestUtil.rethrow(TestUtil.java:268) > at > org.apache.calcite.test.CalciteAssert.assertQuery(CalciteAssert.java:554) > ... 28 more -- This message was sent by Atlassian JIRA (v7.6.14#76016)