This is an automated email from the ASF dual-hosted git repository. zabetak pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/hive.git
The following commit(s) were added to refs/heads/master by this push: new 9087fa9 HIVE-25816: Log CBO plan after rule application for debugging purposes (Stamatis Zampetakis, reviewed by Krisztian Kasa) 9087fa9 is described below commit 9087fa93cd785223f4f2552ec836e7580c78830a Author: Stamatis Zampetakis <zabe...@gmail.com> AuthorDate: Thu Dec 16 16:27:56 2021 +0100 HIVE-25816: Log CBO plan after rule application for debugging purposes (Stamatis Zampetakis, reviewed by Krisztian Kasa) Closes #2887 --- data/conf/hive-log4j2.properties | 11 ++- .../hadoop/hive/ql/optimizer/calcite/Bug.java | 5 ++ .../hive/ql/optimizer/calcite/RuleEventLogger.java | 82 ++++++++++++++++++++++ .../hadoop/hive/ql/parse/CalcitePlanner.java | 7 +- 4 files changed, 102 insertions(+), 3 deletions(-) diff --git a/data/conf/hive-log4j2.properties b/data/conf/hive-log4j2.properties index 3072efd..eac59b3 100644 --- a/data/conf/hive-log4j2.properties +++ b/data/conf/hive-log4j2.properties @@ -50,7 +50,7 @@ appender.DRFA.strategy.type = DefaultRolloverStrategy appender.DRFA.strategy.max = 30 # list of all loggers -loggers = HadoopIPC, HadoopSecurity, Hdfs, HdfsServer, HadoopMetrics2, Mortbay, Yarn, YarnServer, Tez, HadoopConf, Zookeeper, ServerCnxn, NIOServerCnxn, ClientCnxn, ClientCnxnSocket, ClientCnxnSocketNIO, DataNucleus, Datastore, JPOX, Operator, Serde2Lazy, ObjectStore, CalcitePlanner, AmazonAws, ApacheHttp, Thrift, Jetty, BlockStateChange, swo +loggers = HadoopIPC, HadoopSecurity, Hdfs, HdfsServer, HadoopMetrics2, Mortbay, Yarn, YarnServer, Tez, HadoopConf, Zookeeper, ServerCnxn, NIOServerCnxn, ClientCnxn, ClientCnxnSocket, ClientCnxnSocketNIO, DataNucleus, Datastore, JPOX, Operator, Serde2Lazy, ObjectStore, CalcitePlanner, AmazonAws, ApacheHttp, Thrift, Jetty, BlockStateChange, swo, CBORuleLogger logger.HadoopIPC.name = org.apache.hadoop.ipc logger.HadoopIPC.level = WARN @@ -121,6 +121,15 @@ logger.ObjectStore.level = INFO logger.CalcitePlanner.name = org.apache.calcite.plan.RelOptPlanner logger.CalcitePlanner.level = INFO +# Change logger level to DEBUG, to see all application of CBO rules and the operators they produce +logger.CBORuleLogger.name = org.apache.hadoop.hive.ql.optimizer.calcite.RuleEventLogger +logger.CBORuleLogger.level = OFF +logger.CBORuleLogger.filter.marker.type = MarkerFilter +logger.CBORuleLogger.filter.marker.marker = FULL_PLAN +# Change filter to ACCEPT, to see the produced plan after every rule invocation using the EXPLAIN CBO format +logger.CBORuleLogger.filter.marker.onMatch = DENY +logger.CBORuleLogger.filter.marker.onMisMatch = NEUTRAL + logger.AmazonAws.name=com.amazonaws logger.AmazonAws.level = INFO diff --git a/ql/src/java/org/apache/hadoop/hive/ql/optimizer/calcite/Bug.java b/ql/src/java/org/apache/hadoop/hive/ql/optimizer/calcite/Bug.java index ce0636d..a05fb80 100644 --- a/ql/src/java/org/apache/hadoop/hive/ql/optimizer/calcite/Bug.java +++ b/ql/src/java/org/apache/hadoop/hive/ql/optimizer/calcite/Bug.java @@ -69,4 +69,9 @@ public final class Bug { * Whether <a href="https://issues.apache.org/jira/browse/CALCITE-4574">CALCITE-4574</a> is fixed. */ public static final boolean CALCITE_4574_FIXED = false; + + /** + * Whether <a href="https://issues.apache.org/jira/browse/CALCITE-4704">CALCITE-4704</a> is fixed. + */ + public static final boolean CALCITE_4704_FIXED = false; } diff --git a/ql/src/java/org/apache/hadoop/hive/ql/optimizer/calcite/RuleEventLogger.java b/ql/src/java/org/apache/hadoop/hive/ql/optimizer/calcite/RuleEventLogger.java new file mode 100644 index 0000000..f5ab294 --- /dev/null +++ b/ql/src/java/org/apache/hadoop/hive/ql/optimizer/calcite/RuleEventLogger.java @@ -0,0 +1,82 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.hadoop.hive.ql.optimizer.calcite; + +import org.apache.calcite.plan.RelOptListener; +import org.apache.calcite.plan.RelOptRuleCall; +import org.apache.calcite.plan.RelOptUtil; +import org.apache.calcite.rel.RelNode; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.Marker; +import org.slf4j.MarkerFactory; + +import java.util.Arrays; +import java.util.stream.Collectors; + +/** + * Listener for logging useful debugging information on certain rule events. + */ +public class RuleEventLogger implements RelOptListener { + private static final Logger LOG = LoggerFactory.getLogger(RuleEventLogger.class.getName()); + private static final Marker FULL = MarkerFactory.getMarker("FULL_PLAN"); + + public RuleEventLogger() { + if (Bug.CALCITE_4704_FIXED) { + throw new IllegalStateException("Class redundant after fix is merged into Calcite"); + } + } + + @Override + public void relEquivalenceFound(final RelEquivalenceEvent event) { + + } + + @Override + public void ruleAttempted(final RuleAttemptedEvent event) { + if (event.isBefore() && LOG.isDebugEnabled()) { + RelOptRuleCall call = event.getRuleCall(); + String ruleArgs = Arrays.stream(call.rels).map(rel -> "rel#" + rel.getId() + ":" + rel.getRelTypeName()) + .collect(Collectors.joining(",")); + LOG.debug("call#{}: Apply rule [{}] to [{}]", call.id, call.getRule(), ruleArgs); + } + } + + @Override + public void ruleProductionSucceeded(RuleProductionEvent event) { + if (event.isBefore() && LOG.isDebugEnabled()) { + RelOptRuleCall call = event.getRuleCall(); + RelNode newRel = event.getRel(); + String description = newRel == null ? "null" : "rel#" + newRel.getId() + ":" + newRel.getRelTypeName(); + LOG.debug("call#{}: Rule [{}] produced [{}]", call.id, call.getRule(), description); + if (newRel != null) { + LOG.debug(FULL, "call#{}: Full plan for [{}]:{}", call.id, description, + System.lineSeparator() + RelOptUtil.toString(newRel)); + } + } + } + + @Override + public void relDiscarded(final RelDiscardedEvent event) { + + } + + @Override + public void relChosen(final RelChosenEvent event) { + + } +} diff --git a/ql/src/java/org/apache/hadoop/hive/ql/parse/CalcitePlanner.java b/ql/src/java/org/apache/hadoop/hive/ql/parse/CalcitePlanner.java index 12dcebd..1b7af3e 100644 --- a/ql/src/java/org/apache/hadoop/hive/ql/parse/CalcitePlanner.java +++ b/ql/src/java/org/apache/hadoop/hive/ql/parse/CalcitePlanner.java @@ -164,6 +164,7 @@ import org.apache.hadoop.hive.ql.optimizer.calcite.HiveCalciteUtil; import org.apache.hadoop.hive.ql.optimizer.calcite.HiveConfPlannerContext; import org.apache.hadoop.hive.ql.optimizer.calcite.HiveDefaultRelMetadataProvider; import org.apache.hadoop.hive.ql.optimizer.calcite.HiveTezModelRelMetadataProvider; +import org.apache.hadoop.hive.ql.optimizer.calcite.RuleEventLogger; import org.apache.hadoop.hive.ql.optimizer.calcite.rules.HiveAggregateSortLimitRule; import org.apache.hadoop.hive.ql.optimizer.calcite.rules.HiveJoinSwapConstraintsRule; import org.apache.hadoop.hive.ql.optimizer.calcite.rules.HiveSemiJoinProjectTransposeRule; @@ -519,7 +520,9 @@ public class CalcitePlanner extends SemanticAnalyzer { corrScalarRexSQWithAgg, new HiveConfPlannerContext(isCorrelatedColumns, heuristicMaterializationStrategy, isExplainPlan), statsSource); - return HiveVolcanoPlanner.createPlanner(confContext); + RelOptPlanner planner = HiveVolcanoPlanner.createPlanner(confContext); + planner.addListener(new RuleEventLogger()); + return planner; } @Override @@ -2413,7 +2416,7 @@ public class CalcitePlanner extends SemanticAnalyzer { // Create planner and copy context HepPlanner planner = new HepPlanner(program, basePlan.getCluster().getPlanner().getContext()); - + planner.addListener(new RuleEventLogger()); List<RelMetadataProvider> list = Lists.newArrayList(); list.add(mdProvider); planner.registerMetadataProviders(list);