Skip to content

Commit

Permalink
HIVE-25816: Log CBO plan after rule application for debugging purpose…
Browse files Browse the repository at this point in the history
…s (Stamatis Zampetakis, reviewed by Krisztian Kasa)

Closes #2887
  • Loading branch information
zabetak committed Dec 22, 2021
1 parent 16730f5 commit 9087fa9
Show file tree
Hide file tree
Showing 4 changed files with 102 additions and 3 deletions.
11 changes: 10 additions & 1 deletion data/conf/hive-log4j2.properties
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Original file line number Diff line number Diff line change
@@ -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) {

}
}
Original file line number Diff line number Diff line change
Expand Up @@ -164,6 +164,7 @@
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;
Expand Down Expand Up @@ -519,7 +520,9 @@ private static RelOptPlanner createPlanner(
corrScalarRexSQWithAgg,
new HiveConfPlannerContext(isCorrelatedColumns, heuristicMaterializationStrategy, isExplainPlan),
statsSource);
return HiveVolcanoPlanner.createPlanner(confContext);
RelOptPlanner planner = HiveVolcanoPlanner.createPlanner(confContext);
planner.addListener(new RuleEventLogger());
return planner;
}

@Override
Expand Down Expand Up @@ -2413,7 +2416,7 @@ protected RelNode executeProgram(RelNode basePlan, HepProgram program,
// 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);
Expand Down

0 comments on commit 9087fa9

Please sign in to comment.