IMPALA-13563: Cleanup logging

Cleans up calls to logDebug and a few other locations:
- exit early if producing debug message input is expensive
- use slf4j parameterized logging
- normalize on logDebug handling isDebugEnabled checks

Change-Id: I32e1c62511c292d36aa879c60ae3d91ed4f65697
Reviewed-on: http://gerrit.cloudera.org:8080/22090
Reviewed-by: Michael Smith <michael.smith@cloudera.com>
Tested-by: Impala Public Jenkins <impala-public-jenkins@cloudera.com>

fe/src/main/java/org/apache/impala/analysis/ArithmeticExpr.java

@@ -261,8 +261,8 @@ public class ArithmeticExpr extends Expr {
     fn_ = getBuiltinFunction(analyzer, fnName, collectChildReturnTypes(),
         CompareMode.IS_IDENTICAL);
     if (fn_ == null) {
-      Preconditions.checkState(false, String.format("No match " +
-          "for '%s' with operand types %s and %s", toSql(), t0, t1));
+      Preconditions.checkState(false,
+          "No match for '%s' with operand types %s and %s", toSql(), t0, t1);
     }
     Preconditions.checkState(type_.matchesType(fn_.getReturnType()));
   }

fe/src/main/java/org/apache/impala/analysis/SlotRef.java

@@ -330,7 +330,8 @@ public class SlotRef extends Expr {
     // we shouldn't be sending exprs over non-materialized slots
     Preconditions.checkState(desc_.isMaterialized(),
         "Illegal reference to non-materialized slot: %s", this);
-    Preconditions.checkState(desc_.getByteOffset() >= 0);
+    Preconditions.checkState(desc_.getByteOffset() >= 0,
+        "computeMemLayout not done for slot: %s", this);
     // check that the tuples associated with this slot are executable
     desc_.getParent().checkIsExecutable();
     if (desc_.getItemTupleDesc() != null) desc_.getItemTupleDesc().checkIsExecutable();

fe/src/main/java/org/apache/impala/analysis/TupleDescriptor.java

@@ -292,12 +292,12 @@ public class TupleDescriptor {
    * is not executable, i.e., if one of those conditions is not met.
    */
   public void checkIsExecutable() {
-    Preconditions.checkState(isMaterialized_, String.format(
+    Preconditions.checkState(isMaterialized_,
         "Illegal reference to non-materialized tuple: debugname=%s alias=%s tid=%s",
-        debugName_, StringUtils.defaultIfEmpty(getAlias(), "n/a"), id_));
-    Preconditions.checkState(hasMemLayout_, String.format(
+        debugName_, StringUtils.defaultIfEmpty(getAlias(), "n/a"), id_);
+    Preconditions.checkState(hasMemLayout_,
         "Missing memory layout for tuple: debugname=%s alias=%s tid=%s",
-        debugName_, StringUtils.defaultIfEmpty(getAlias(), "n/a"), id_));
+        debugName_, StringUtils.defaultIfEmpty(getAlias(), "n/a"), id_);
   }
 
   /**

fe/src/main/java/org/apache/impala/catalog/metastore/CatalogMetastoreServiceHandler.java

@@ -1331,10 +1331,10 @@ public class CatalogMetastoreServiceHandler extends MetastoreServiceHandler {
             MetastoreEventsProcessor.getNextMetastoreEventsInBatchesForTable(catalog_,
                 currentEventId, newTable.getDbName(), newTable.getTableName(),
                 MetastoreEvents.AlterTableEvent.EVENT_TYPE);
-        Preconditions.checkState(events.size() == 1, String.format("For table %s.%s, "
+        Preconditions.checkState(events.size() == 1, "For table %s.%s, "
             + "from event id: %s, expected ALTER_TABLE events size to be 1 but is %s",
             newTable.getDbName(), newTable.getTableName(), currentEventId,
-            events.size()));
+            events.size());
 
         MetastoreEvents.MetastoreEvent event = metastoreEventFactory_.get(events.get(0),
             metastoreEventsMetrics_);

java/calcite-planner/src/main/java/org/apache/impala/calcite/service/CalciteJniFrontend.java

@@ -199,9 +199,7 @@ public class CalciteJniFrontend extends JniFrontend {
       QueryContext queryCtx, String stepMessage) {
     LOG.info(stepMessage);
     queryCtx.getTimeline().markEvent(stepMessage);
-    if (LOG.isDebugEnabled()) {
-      compilerStep.logDebug(stepResult);
-    }
+    compilerStep.logDebug(stepResult);
   }
 
   private static void loadCalciteImpalaFunctions() {

java/calcite-planner/src/main/java/org/apache/impala/calcite/service/CalciteMetadataHandler.java

@@ -354,9 +354,10 @@ public class CalciteMetadataHandler implements CompilerStep {
 
   @Override
   public void logDebug(Object resultObject) {
-    LOG.debug("Loaded tables: " + stmtTableCache_.tables.values().stream()
+    if (!LOG.isDebugEnabled()) return;
+    String allTables = stmtTableCache_.tables.values().stream()
         .map(feTable -> feTable.getName().toString())
-        .collect(Collectors.joining( ", " )));
+        .collect(Collectors.joining( ", " ));
+    LOG.debug("Loaded tables: {}", allTables);
   }
 }
-

java/calcite-planner/src/main/java/org/apache/impala/calcite/service/CalcitePhysPlanCreator.java

@@ -88,9 +88,9 @@ public class CalcitePhysPlanCreator implements CompilerStep {
   @Override
   public void logDebug(Object resultObject) {
     if (!(resultObject instanceof NodeWithExprs)) {
-      LOG.debug("Finished physical plan step, but unknown result: " + resultObject);
+      LOG.debug("Finished physical plan step, but unknown result: {}", resultObject);
       return;
     }
-    LOG.debug("Physical Plan: " + resultObject);
+    LOG.debug("Physical Plan: {}", resultObject);
   }
 }

java/calcite-planner/src/main/java/org/apache/impala/calcite/service/CalciteQueryParser.java

@@ -65,9 +65,9 @@ public class CalciteQueryParser implements CompilerStep {
 
   public void logDebug(Object resultObject) {
     if (!(resultObject instanceof SqlNode)) {
-      LOG.debug("Parser produced an unknown output: " + resultObject);
+      LOG.debug("Parser produced an unknown output: {}", resultObject);
       return;
     }
-    LOG.debug("Parsed node: " + resultObject);
+    LOG.debug("Parsed node: {}", resultObject);
   }
 }

java/calcite-planner/src/main/java/org/apache/impala/calcite/service/CalciteValidator.java

@@ -93,9 +93,9 @@ public class CalciteValidator implements CompilerStep {
   @Override
   public void logDebug(Object resultObject) {
     if (!(resultObject instanceof SqlNode)) {
-      LOG.debug("Finished validator step, but unknown result: " + resultObject);
+      LOG.debug("Finished validator step, but unknown result: {}", resultObject);
       return;
     }
-    LOG.debug("Validated node: " + resultObject);
+    LOG.debug("Validated node: {}", resultObject);
   }
 }

java/calcite-planner/src/main/java/org/apache/impala/calcite/service/ExecRequestCreator.java

@@ -427,8 +427,8 @@ public class ExecRequestCreator implements CompilerStep {
   @Override
   public void logDebug(Object resultObject) {
     if (!(resultObject instanceof TExecRequest)) {
-      LOG.debug("Finished create exec request step, but unknown result: " + resultObject);
+      LOG.debug("Finished exec request step, but unknown result: {}", resultObject);
     }
-    LOG.debug("Exec request: " + resultObject);
+    LOG.debug("Exec request: {}", resultObject);
   }
 }