You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@calcite.apache.org by za...@apache.org on 2021/12/18 13:02:46 UTC
[calcite] branch master updated: [CALCITE-4704] Log plan on rule application using explain formatting
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/calcite.git
The following commit(s) were added to refs/heads/master by this push:
new e42b85a [CALCITE-4704] Log plan on rule application using explain formatting
e42b85a is described below
commit e42b85a45bd16dd58db1546736e653deda5463fe
Author: Stamatis Zampetakis <za...@gmail.com>
AuthorDate: Tue Jul 27 18:40:39 2021 +0300
[CALCITE-4704] Log plan on rule application using explain formatting
1. Add RuleEventLogger for logging events around rule execution.
2. Centralize logs around rule application and production in
RuleEventLogger and unify output for volcanoPlanner and HepPlanner
3. Use only id and operator name for displaying rule arguments; remove
redundant/not helpful information.
4. Add FULL_PLAN SLF4J marker to conrol display explain/tree logging on
produced expressions.
5. Add FULL_PLAN marker template config in tests.
Close apache/calcite#2469
---
.../apache/calcite/plan/AbstractRelOptPlanner.java | 13 +---
.../org/apache/calcite/plan/RuleEventLogger.java | 70 ++++++++++++++++++++++
.../calcite/plan/volcano/VolcanoRuleCall.java | 16 -----
core/src/test/resources/log4j2-test.xml | 3 +
4 files changed, 74 insertions(+), 28 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 749538f..15d4b97 100644
--- a/core/src/main/java/org/apache/calcite/plan/AbstractRelOptPlanner.java
+++ b/core/src/main/java/org/apache/calcite/plan/AbstractRelOptPlanner.java
@@ -36,7 +36,6 @@ 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;
@@ -114,6 +113,7 @@ public abstract class AbstractRelOptPlanner implements RelOptPlanner {
this.ruleAttemptsListener = new RuleAttemptsListener();
addListener(this.ruleAttemptsListener);
}
+ addListener(new RuleEventLogger());
}
//~ Methods ----------------------------------------------------------------
@@ -324,12 +324,6 @@ public abstract class AbstractRelOptPlanner implements RelOptPlanner {
return;
}
- if (LOGGER.isDebugEnabled()) {
- // Leave this wrapped in a conditional to prevent unnecessarily calling Arrays.toString(...)
- LOGGER.debug("call#{}: Apply rule [{}] to {}",
- ruleCall.id, ruleCall.getRule(), Arrays.toString(ruleCall.rels));
- }
-
if (listener != null) {
RelOptListener.RuleAttemptedEvent event =
new RelOptListener.RuleAttemptedEvent(
@@ -365,11 +359,6 @@ public abstract class AbstractRelOptPlanner implements RelOptPlanner {
RelOptRuleCall ruleCall,
RelNode newRel,
boolean before) {
- if (before && LOGGER.isDebugEnabled()) {
- LOGGER.debug("call#{}: Rule {} arguments {} produced {}",
- ruleCall.id, ruleCall.getRule(), Arrays.toString(ruleCall.rels), newRel);
- }
-
if (listener != null) {
RelOptListener.RuleProductionEvent event =
new RelOptListener.RuleProductionEvent(
diff --git a/core/src/main/java/org/apache/calcite/plan/RuleEventLogger.java b/core/src/main/java/org/apache/calcite/plan/RuleEventLogger.java
new file mode 100644
index 0000000..4842055
--- /dev/null
+++ b/core/src/main/java/org/apache/calcite/plan/RuleEventLogger.java
@@ -0,0 +1,70 @@
+/*
+ * 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.calcite.plan;
+
+import org.apache.calcite.rel.RelNode;
+import org.apache.calcite.util.trace.CalciteTrace;
+
+import org.slf4j.Logger;
+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 = CalciteTrace.getPlannerTracer();
+ private static final Marker FULL = MarkerFactory.getMarker("FULL_PLAN");
+ @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/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoRuleCall.java b/core/src/main/java/org/apache/calcite/plan/volcano/VolcanoRuleCall.java
index c610ca3..8582a0c 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
@@ -117,16 +117,6 @@ public class VolcanoRuleCall extends RelOptRuleCall {
// It's possible that rel is a subset or is already registered.
// Is there still a point in continuing? Yes, because we might
// discover that two sets of expressions are actually equivalent.
-
- if (LOGGER.isTraceEnabled()) {
- // Cannot call RelNode.toString() yet, because rel has not
- // been registered. For now, let's make up something similar.
- String relDesc =
- "rel#" + rel.getId() + ":" + rel.getRelTypeName();
- LOGGER.trace("call#{}: Rule {} arguments {} created {}",
- id, getRule(), Arrays.toString(rels), relDesc);
- }
-
if (volcanoPlanner.getListener() != null) {
RelOptListener.RuleProductionEvent event =
new RelOptListener.RuleProductionEvent(
@@ -214,12 +204,6 @@ public class VolcanoRuleCall extends RelOptRuleCall {
}
}
- if (LOGGER.isDebugEnabled()) {
- LOGGER.debug(
- "call#{}: Apply rule [{}] to {}",
- id, getRule(), Arrays.toString(rels));
- }
-
if (volcanoPlanner.getListener() != null) {
RelOptListener.RuleAttemptedEvent event =
new RelOptListener.RuleAttemptedEvent(
diff --git a/core/src/test/resources/log4j2-test.xml b/core/src/test/resources/log4j2-test.xml
index c620c0f..cd3e76e 100644
--- a/core/src/test/resources/log4j2-test.xml
+++ b/core/src/test/resources/log4j2-test.xml
@@ -37,5 +37,8 @@
<logger name="org.apache.calcite.avatica" level="ERROR"/>
<logger name="org.eclipse.jetty" level="ERROR"/>
<logger name="org.apache.calcite.sql.parser" level="ERROR"/>
+ <logger name="org.apache.calcite.plan.RelOptPlanner" level="ERROR">
+ <MarkerFilter marker="FULL_PLAN" onMatch="DENY" onMismatch="NEUTRAL"/>
+ </logger>
</Loggers>
</Configuration>