This is an automated email from the ASF dual-hosted git repository.
hyuan pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/calcite.git
The following commit(s) were added to refs/heads/master by this push:
new 789a2ae [CALCITE-3915] Add rule listener to report rule attempts and
time at DEBUG log level (Xiening Dai)
789a2ae is described below
commit 789a2ae7f4de582c6de16c2bcec747372f941b44
Author: Xiening Dai <[email protected]>
AuthorDate: Fri Apr 10 19:58:09 2020 -0700
[CALCITE-3915] Add rule listener to report rule attempts and time at DEBUG
log level (Xiening Dai)
1. Fix current VolcanoPlanner's rule listener to use
MulticastRelOptListener so
multiple listeners can be added at the same time.
2. Create a RuleAttemptsListener that records attempts of each rule and the
time of rule firing. The listener is only added when logger is at DEBUG
level,
or finer level.
Close #1910
---
.../apache/calcite/plan/AbstractRelOptPlanner.java | 97 +++++++++++++++++++++-
.../org/apache/calcite/plan/hep/HepPlanner.java | 2 +-
.../org/apache/calcite/plan/volcano/RelSet.java | 6 +-
.../org/apache/calcite/plan/volcano/RelSubset.java | 12 +--
.../calcite/plan/volcano/VolcanoPlanner.java | 17 +---
.../calcite/plan/volcano/VolcanoRuleCall.java | 16 ++--
.../apache/calcite/util/trace/CalciteTrace.java | 7 ++
7 files changed, 122 insertions(+), 35 deletions(-)
diff --git
a/core/src/main/java/org/apache/calcite/plan/AbstractRelOptPlanner.java
b/core/src/main/java/org/apache/calcite/plan/AbstractRelOptPlanner.java
index 3d1487f..85b060f 100644
--- a/core/src/main/java/org/apache/calcite/plan/AbstractRelOptPlanner.java
+++ b/core/src/main/java/org/apache/calcite/plan/AbstractRelOptPlanner.java
@@ -25,15 +25,22 @@ import org.apache.calcite.rex.RexExecutor;
import org.apache.calcite.util.CancelFlag;
import org.apache.calcite.util.Pair;
import org.apache.calcite.util.Util;
+import org.apache.calcite.util.trace.CalciteTrace;
import com.google.common.collect.ImmutableList;
+import org.slf4j.Logger;
+
+import java.text.NumberFormat;
+import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collections;
+import java.util.HashMap;
import java.util.HashSet;
import java.util.LinkedHashMap;
import java.util.LinkedHashSet;
import java.util.List;
+import java.util.Locale;
import java.util.Map;
import java.util.Set;
import java.util.concurrent.atomic.AtomicBoolean;
@@ -45,6 +52,11 @@ import static org.apache.calcite.util.Static.RESOURCE;
* Abstract base for implementations of the {@link RelOptPlanner} interface.
*/
public abstract class AbstractRelOptPlanner implements RelOptPlanner {
+ //~ Static fields/initializers ---------------------------------------------
+
+ /** Logger for rule attempts information. */
+ private static final Logger RULE_ATTEMPTS_LOGGER =
CalciteTrace.getRuleAttemptsTracer();
+
//~ Instance fields --------------------------------------------------------
/**
@@ -57,6 +69,8 @@ public abstract class AbstractRelOptPlanner implements
RelOptPlanner {
private MulticastRelOptListener listener;
+ private RuleAttemptsListener ruleAttemptsListener;
+
private Pattern ruleDescExclusionFilter;
protected final AtomicBoolean cancelFlag;
@@ -92,6 +106,11 @@ public abstract class AbstractRelOptPlanner implements
RelOptPlanner {
// these types, but some operands may use them.
classes.add(RelNode.class);
classes.add(RelSubset.class);
+
+ if (RULE_ATTEMPTS_LOGGER.isDebugEnabled()) {
+ this.ruleAttemptsListener = new RuleAttemptsListener();
+ addListener(this.ruleAttemptsListener);
+ }
}
//~ Methods ----------------------------------------------------------------
@@ -272,6 +291,13 @@ public abstract class AbstractRelOptPlanner implements
RelOptPlanner {
// do nothing
}
+ protected void dumpRuleAttemptsInfo() {
+ if (this.ruleAttemptsListener != null) {
+ RULE_ATTEMPTS_LOGGER.debug("Rule Attempts Info for " +
this.getClass().getSimpleName());
+ RULE_ATTEMPTS_LOGGER.debug(this.ruleAttemptsListener.dump());
+ }
+ }
+
/**
* Fires a rule, taking care of tracing and listener notification.
*
@@ -406,7 +432,7 @@ public abstract class AbstractRelOptPlanner implements
RelOptPlanner {
}
}
- protected MulticastRelOptListener getListener() {
+ public RelOptListener getListener() {
return listener;
}
@@ -434,4 +460,73 @@ public abstract class AbstractRelOptPlanner implements
RelOptPlanner {
: Collections.singletonList(relType);
return Pair.of(digest, v);
}
+
+ /** Listener for counting the attempts of each rule. Only enabled under
DEBUG level.*/
+ private class RuleAttemptsListener implements RelOptListener {
+ private long beforeTimestamp;
+ private Map<String, Pair<Long, Long>> ruleAttempts;
+
+ RuleAttemptsListener() {
+ ruleAttempts = new HashMap<>();
+ }
+
+ @Override public void relEquivalenceFound(RelEquivalenceEvent event) {
+ }
+
+ @Override public void ruleAttempted(RuleAttemptedEvent event) {
+ if (event.isBefore()) {
+ this.beforeTimestamp = System.nanoTime();
+ } else {
+ long elapsed = (System.nanoTime() - this.beforeTimestamp) / 1000;
+ String rule = event.getRuleCall().getRule().toString();
+ if (ruleAttempts.containsKey(rule)) {
+ Pair<Long, Long> p = ruleAttempts.get(rule);
+ ruleAttempts.put(rule, Pair.of(p.left + 1, p.right + elapsed));
+ } else {
+ ruleAttempts.put(rule, Pair.of(1L, elapsed));
+ }
+ }
+ }
+
+ @Override public void ruleProductionSucceeded(RuleProductionEvent event) {
+ }
+
+ @Override public void relDiscarded(RelDiscardedEvent event) {
+ }
+
+ @Override public void relChosen(RelChosenEvent event) {
+ }
+
+ public String dump() {
+ // Sort rules by number of attempts descending, then by rule elapsed
time descending,
+ // then by rule name ascending.
+ List<Map.Entry<String, Pair<Long, Long>>> list =
+ new ArrayList<>(this.ruleAttempts.entrySet());
+ Collections.sort(list,
+ (left, right) -> {
+ int res = right.getValue().left.compareTo(left.getValue().left);
+ if (res == 0) {
+ res = right.getValue().right.compareTo(left.getValue().right);
+ }
+ if (res == 0) {
+ res = left.getKey().compareTo(right.getKey());
+ }
+ return res;
+ });
+
+ // Print out rule attempts and time
+ StringBuilder sb = new StringBuilder();
+ sb.append(String
+ .format(Locale.ROOT, "%n%-60s%20s%20s%n", "Rules", "Attempts", "Time
(us)"));
+ NumberFormat usFormat = NumberFormat.getNumberInstance(Locale.US);
+ for (Map.Entry<String, Pair<Long, Long>> entry : list) {
+ sb.append(
+ String.format(Locale.ROOT, "%-60s%20s%20s%n",
+ entry.getKey(),
+ usFormat.format(entry.getValue().left),
+ usFormat.format(entry.getValue().right)));
+ }
+ return sb.toString();
+ }
+ }
}
diff --git a/core/src/main/java/org/apache/calcite/plan/hep/HepPlanner.java
b/core/src/main/java/org/apache/calcite/plan/hep/HepPlanner.java
index 33d93ef..44b4fb8 100644
--- a/core/src/main/java/org/apache/calcite/plan/hep/HepPlanner.java
+++ b/core/src/main/java/org/apache/calcite/plan/hep/HepPlanner.java
@@ -189,7 +189,7 @@ public class HepPlanner extends AbstractRelOptPlanner {
// Get rid of everything except what's in the final plan.
collectGarbage();
-
+ dumpRuleAttemptsInfo();
return buildFinalPlan(root);
}
diff --git a/core/src/main/java/org/apache/calcite/plan/volcano/RelSet.java
b/core/src/main/java/org/apache/calcite/plan/volcano/RelSet.java
index 5f75bdf..55e6464 100644
--- a/core/src/main/java/org/apache/calcite/plan/volcano/RelSet.java
+++ b/core/src/main/java/org/apache/calcite/plan/volcano/RelSet.java
@@ -242,7 +242,7 @@ class RelSet {
subsets.add(subset);
final VolcanoPlanner planner = (VolcanoPlanner) cluster.getPlanner();
- if (planner.listener != null) {
+ if (planner.getListener() != null) {
postEquivalenceEvent(planner, subset);
}
} else if ((required && !subset.isRequired())
@@ -272,7 +272,7 @@ class RelSet {
rel,
"equivalence class " + id,
false);
- planner.listener.relEquivalenceFound(event);
+ planner.getListener().relEquivalenceFound(event);
}
/**
@@ -291,7 +291,7 @@ class RelSet {
VolcanoPlanner planner =
(VolcanoPlanner) rel.getCluster().getPlanner();
- if (planner.listener != null) {
+ if (planner.getListener() != null) {
postEquivalenceEvent(planner, rel);
}
}
diff --git a/core/src/main/java/org/apache/calcite/plan/volcano/RelSubset.java
b/core/src/main/java/org/apache/calcite/plan/volcano/RelSubset.java
index eb401d3..cdaebb2 100644
--- a/core/src/main/java/org/apache/calcite/plan/volcano/RelSubset.java
+++ b/core/src/main/java/org/apache/calcite/plan/volcano/RelSubset.java
@@ -292,14 +292,14 @@ public class RelSubset extends AbstractRelNode {
}
VolcanoPlanner planner = (VolcanoPlanner) rel.getCluster().getPlanner();
- if (planner.listener != null) {
+ if (planner.getListener() != null) {
RelOptListener.RelEquivalenceEvent event =
new RelOptListener.RelEquivalenceEvent(
planner,
rel,
this,
true);
- planner.listener.relEquivalenceFound(event);
+ planner.getListener().relEquivalenceFound(event);
}
// If this isn't the first rel in the set, it must have compatible
@@ -327,12 +327,12 @@ public class RelSubset extends AbstractRelNode {
CheapestPlanReplacer replacer = new CheapestPlanReplacer(planner);
final RelNode cheapest = replacer.visit(this, -1, null);
- if (planner.listener != null) {
+ if (planner.getListener() != null) {
RelOptListener.RelChosenEvent event =
new RelOptListener.RelChosenEvent(
planner,
null);
- planner.listener.relChosen(event);
+ planner.getListener().relChosen(event);
}
return cheapest;
@@ -642,12 +642,12 @@ public class RelSubset extends AbstractRelNode {
}
if (ordinal != -1) {
- if (planner.listener != null) {
+ if (planner.getListener() != null) {
RelOptListener.RelChosenEvent event =
new RelOptListener.RelChosenEvent(
planner,
p);
- planner.listener.relChosen(event);
+ planner.getListener().relChosen(event);
}
}
diff --git
a/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoPlanner.java
b/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoPlanner.java
index 520f412..dd6274f 100644
--- a/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoPlanner.java
+++ b/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoPlanner.java
@@ -25,7 +25,6 @@ import org.apache.calcite.plan.ConventionTraitDef;
import org.apache.calcite.plan.RelOptCost;
import org.apache.calcite.plan.RelOptCostFactory;
import org.apache.calcite.plan.RelOptLattice;
-import org.apache.calcite.plan.RelOptListener;
import org.apache.calcite.plan.RelOptMaterialization;
import org.apache.calcite.plan.RelOptMaterializations;
import org.apache.calcite.plan.RelOptPlanner;
@@ -152,11 +151,6 @@ public class VolcanoPlanner extends AbstractRelOptPlanner {
private int nextSetId = 0;
- /**
- * Listener for this planner, or null if none set.
- */
- RelOptListener listener;
-
private RelNode originalRoot;
/**
@@ -518,6 +512,7 @@ public class VolcanoPlanner extends AbstractRelOptPlanner {
pw.flush();
LOGGER.trace(sw.toString());
}
+ dumpRuleAttemptsInfo();
RelNode cheapest = root.buildCheapestPlan(this);
if (LOGGER.isDebugEnabled()) {
LOGGER.debug(
@@ -1278,16 +1273,6 @@ public class VolcanoPlanner extends
AbstractRelOptPlanner {
}
// implement RelOptPlanner
- public void addListener(RelOptListener newListener) {
- // TODO jvs 6-Apr-2006: new superclass AbstractRelOptPlanner
- // now defines a multicast listener; just need to hook it in
- if (listener != null) {
- throw Util.needToImplement("multiple VolcanoPlanner listeners");
- }
- listener = newListener;
- }
-
- // implement RelOptPlanner
public void registerMetadataProviders(List<RelMetadataProvider> list) {
list.add(0, new VolcanoRelMetadataProvider());
}
diff --git
a/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoRuleCall.java
b/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoRuleCall.java
index a099fd8..990a48c 100644
--- a/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoRuleCall.java
+++ b/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoRuleCall.java
@@ -114,14 +114,14 @@ public class VolcanoRuleCall extends RelOptRuleCall {
id, getRule(), Arrays.toString(rels), relDesc);
}
- if (volcanoPlanner.listener != null) {
+ if (volcanoPlanner.getListener() != null) {
RelOptListener.RuleProductionEvent event =
new RelOptListener.RuleProductionEvent(
volcanoPlanner,
rel,
this,
true);
- volcanoPlanner.listener.ruleProductionSucceeded(event);
+ volcanoPlanner.getListener().ruleProductionSucceeded(event);
}
final RelNode relCopy = rel;
@@ -144,14 +144,14 @@ public class VolcanoRuleCall extends RelOptRuleCall {
volcanoPlanner.ensureRegistered(rel, rels[0]);
rels[0].getCluster().invalidateMetadataQuery();
- if (volcanoPlanner.listener != null) {
+ if (volcanoPlanner.getListener() != null) {
RelOptListener.RuleProductionEvent event =
new RelOptListener.RuleProductionEvent(
volcanoPlanner,
rel,
this,
false);
- volcanoPlanner.listener.ruleProductionSucceeded(event);
+ volcanoPlanner.getListener().ruleProductionSucceeded(event);
}
} catch (Exception e) {
throw new RuntimeException("Error occurred while applying rule "
@@ -207,14 +207,14 @@ public class VolcanoRuleCall extends RelOptRuleCall {
id, getRule(), Arrays.toString(rels));
}
- if (volcanoPlanner.listener != null) {
+ if (volcanoPlanner.getListener() != null) {
RelOptListener.RuleAttemptedEvent event =
new RelOptListener.RuleAttemptedEvent(
volcanoPlanner,
rels[0],
this,
true);
- volcanoPlanner.listener.ruleAttempted(event);
+ volcanoPlanner.getListener().ruleAttempted(event);
}
if (LOGGER.isDebugEnabled()) {
@@ -239,14 +239,14 @@ public class VolcanoRuleCall extends RelOptRuleCall {
this.generatedRelList = null;
}
- if (volcanoPlanner.listener != null) {
+ if (volcanoPlanner.getListener() != null) {
RelOptListener.RuleAttemptedEvent event =
new RelOptListener.RuleAttemptedEvent(
volcanoPlanner,
rels[0],
this,
false);
- volcanoPlanner.listener.ruleAttempted(event);
+ volcanoPlanner.getListener().ruleAttempted(event);
}
} catch (Exception e) {
throw new RuntimeException("Error while applying rule " + getRule()
diff --git a/core/src/main/java/org/apache/calcite/util/trace/CalciteTrace.java
b/core/src/main/java/org/apache/calcite/util/trace/CalciteTrace.java
index e5afb31..fc21ab7 100644
--- a/core/src/main/java/org/apache/calcite/util/trace/CalciteTrace.java
+++ b/core/src/main/java/org/apache/calcite/util/trace/CalciteTrace.java
@@ -18,6 +18,7 @@ package org.apache.calcite.util.trace;
import org.apache.calcite.linq4j.function.Function2;
import org.apache.calcite.linq4j.function.Functions;
+import org.apache.calcite.plan.AbstractRelOptPlanner;
import org.apache.calcite.plan.RelImplementor;
import org.apache.calcite.plan.RelOptPlanner;
import org.apache.calcite.prepare.Prepare;
@@ -118,6 +119,12 @@ public abstract class CalciteTrace {
return LoggerFactory.getLogger("org.apache.calcite.sql2rel");
}
+ public static Logger getRuleAttemptsTracer() {
+ return LoggerFactory.getLogger(
+ AbstractRelOptPlanner.class.getName() + ".rule_execution_summary"
+ );
+ }
+
/**
* The tracers report important/useful information related with the execution
* of unit tests.
