[ https://issues.apache.org/jira/browse/CALCITE-3257?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16909486#comment-16909486 ]
Xiening Dai commented on CALCITE-3257: -------------------------------------- I agree with your assumption. Current cost propagation logic wouldn't work if the parent node cost is already exists in the cache - in which case there's no chance for recomputing the cost based on the change of input cost. I think that's why we purge cache every time the rule fires (https://github.com/apache/calcite/blob/979a825fab0757c506363f5df6ed7997674e8726/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoRuleCall.java#L130). *RuleQueue.dump() calls into dumpGraphviz() which indeed calls getCost() for rel node*. At that point, new cache entry is added, causing problem in the next rule cost propagation. Your change might as well fix this particular case in the bug. But I think it's still important to keep the behavior consistent regardless the log level, aka purging the cache between rules. In the future, we might be able to improve the cache so that it can be reused across rules, which would be a huge gain of performance. But before that, I think we still need this fix so cache is purged after each dump(). > 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 > Labels: pull-request-available > Time Spent: 20m > Remaining Estimate: 0h > > 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.testNotExistsCorrelated. Get below exception - > java.lang.AssertionError: rel > [rel#63:EnumerableAggregate.ENUMERABLE.[](input=RelSubset#62,group={0})] has > lower cost {131.0 rows, 216.0 cpu, 0.0 io} than best cost {131.5 rows, 216.0 > cpu, 0.0 io} of subset [rel#60:Subset#4.ENUMERABLE.[]] > at org.apache.calcite.util.Litmus$1.fail(Litmus.java:31) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.isValid(VolcanoPlanner.java:889) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.register(VolcanoPlanner.java:852) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:869) > at > org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:1928) > 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.convert.ConverterRule.onMatch(ConverterRule.java:141) > 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.testNotExistsCorrelated(JdbcTest.java:4562) > 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 * from > "hr"."emps" where not exists ( > select 1 from "hr"."depts" > where "emps"."deptno"="depts"."deptno") > 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)