better logging

Author: e-strauss

src/main/java/org/apache/sysds/hops/DataOp.java

@@ -19,13 +19,14 @@
 
 package org.apache.sysds.hops;
 
+import static org.apache.sysds.parser.DataExpression.FED_RANGES;
+
 import java.util.HashMap;
 import java.util.Map.Entry;
 
-import org.apache.commons.logging.Log;
-import org.apache.commons.logging.LogFactory;
 import org.apache.sysds.api.DMLScript;
 import org.apache.sysds.common.Types.DataType;
+import org.apache.sysds.common.Types.ExecType;
 import org.apache.sysds.common.Types.FileFormat;
 import org.apache.sysds.common.Types.OpOpData;
 import org.apache.sysds.common.Types.ValueType;
@@ -35,22 +36,21 @@
 import org.apache.sysds.lops.Data;
 import org.apache.sysds.lops.Federated;
 import org.apache.sysds.lops.Lop;
-import org.apache.sysds.common.Types.ExecType;
 import org.apache.sysds.lops.LopsException;
 import org.apache.sysds.lops.Sql;
 import org.apache.sysds.lops.Tee;
 import org.apache.sysds.parser.DataExpression;
-import static org.apache.sysds.parser.DataExpression.FED_RANGES;
 import org.apache.sysds.runtime.controlprogram.caching.MatrixObject.UpdateType;
 import org.apache.sysds.runtime.meta.DataCharacteristics;
 import org.apache.sysds.runtime.util.LocalFileUtils;
+import org.apache.sysds.utils.ParameterizedLogger;
 
 /**
  *  A DataOp can be either a persistent read/write or transient read/write - writes will always have at least one input,
  *  but all types can have parameters (e.g., for csv literals of delimiter, header, etc).
  */
 public class DataOp extends Hop {
-	private static final Log LOG =  LogFactory.getLog(DataOp.class.getName());
+	private static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(DataOp.class);
 	private OpOpData _op;
 	private String _fileName = null;
 
@@ -130,9 +130,7 @@ public DataOp(String l, DataType dt, ValueType vt,
 			String s = e.getKey();
 			Hop input = e.getValue();
 			getInput().add(input);
-			if (LOG.isDebugEnabled()){
-				LOG.debug(String.format("%15s - %s",s,input));
-			}
+			LOG.debug("{%15s} - {%s}", s, input);
 			input.getParent().add(this);
 
 			_paramIndexMap.put(s, index);

src/main/java/org/apache/sysds/hops/cost/CostEstimator.java

@@ -19,8 +19,6 @@
 
 package org.apache.sysds.hops.cost;
 
-import org.apache.commons.logging.Log;
-import org.apache.commons.logging.LogFactory;
 import org.apache.sysds.common.Opcodes;
 import org.apache.sysds.conf.ConfigurationManager;
 import org.apache.sysds.hops.OptimizerUtils;
@@ -54,14 +52,15 @@
 import org.apache.sysds.runtime.matrix.operators.CMOperator;
 import org.apache.sysds.runtime.matrix.operators.CMOperator.AggregateOperationTypes;
 import org.apache.sysds.runtime.meta.DataCharacteristics;
+import org.apache.sysds.utils.ParameterizedLogger;
 
 import java.util.ArrayList;
 import java.util.HashMap;
 import java.util.HashSet;
 
 public abstract class CostEstimator
 {
-	protected static final Log LOG = LogFactory.getLog(CostEstimator.class.getName());
+	protected static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(CostEstimator.class);
 
 	private static final int DEFAULT_NUMITER = 15;
 
@@ -155,18 +154,16 @@ else if( pb instanceof BasicProgramBlock )
 						//awareness of recursive functions, missing program
 						if( !memoFunc.contains(fkey) && pb.getProgram()!=null ) 
 						{
-							if(LOG.isDebugEnabled())
-								LOG.debug("Begin Function "+fkey);
-							
+							LOG.debug("Begin Function {}", fkey);
+
 							memoFunc.add(fkey);
 							Program prog = pb.getProgram();
 							FunctionProgramBlock fpb = prog.getFunctionProgramBlock(
 								finst.getNamespace(), finst.getFunctionName());
 							ret += rGetTimeEstimate(fpb, stats, memoFunc, recursive);
 							memoFunc.remove(fkey);
-							
-							if(LOG.isDebugEnabled())
-								LOG.debug("End Function "+fkey);
+
+							LOG.debug("End Function {}", fkey);
 						}
 					}
 				}

src/main/java/org/apache/sysds/hops/cost/CostEstimatorStaticRuntime.java

@@ -85,9 +85,8 @@ protected double getCPInstTimeEstimate( Instruction inst, VarStats[] vs, String[
 			}
 			vs[1]._inmem = true;
 		}
-		if( LOG.isDebugEnabled() && ltime!=0 ) {
-			LOG.debug("Cost["+cpinst.getOpcode()+" - read] = "+ltime);
-		}		
+		if(ltime != 0)
+			LOG.debug("Cost[{} - read] = {}", cpinst.getOpcode(), ltime);
 
 		//exec time CP instruction
 		String opcode = (cpinst instanceof FunctionCallCPInstruction) ? InstructionUtils.getOpCode(cpinst.toString()) : cpinst.getOpcode();
@@ -99,9 +98,8 @@ protected double getCPInstTimeEstimate( Instruction inst, VarStats[] vs, String[
 		if( inst instanceof VariableCPInstruction && ((VariableCPInstruction)inst).getOpcode().equals(Opcodes.WRITE.toString()) )
 			wtime += getHDFSWriteTime(vs[2].getRows(), vs[2].getCols(), vs[2].getSparsity(), ((VariableCPInstruction)inst).getInput3().getName() );
 
-		if( LOG.isDebugEnabled() && wtime!=0 ) {
-			LOG.debug("Cost["+cpinst.getOpcode()+" - write] = "+wtime);
-		}
+		if(wtime != 0)
+			LOG.debug("Cost[{} - write] = {}", cpinst.getOpcode(), wtime);
 
 		//total costs
 		double costs = ltime + etime + wtime;
@@ -261,8 +259,8 @@ private static double getInstTimeEstimate( String opcode, boolean inMR, long d1m
 		double nflops = getNFLOP(opcode, inMR, d1m, d1n, d1s, d2m, d2n, d2s, d3m, d3n, d3s, args);
 		double time = nflops / DEFAULT_FLOPS;
 
-		if( LOG.isDebugEnabled() )
-			LOG.debug("Cost["+opcode+"] = "+time+"s, "+nflops+" flops ("+d1m+","+d1n+","+d1s+","+d2m+","+d2n+","+d2s+","+d3m+","+d3n+","+d3s+").");
+		LOG.debug("Cost[{}] = {}s, {} flops ({},{},{},{},{},{},{},{},{}).",
+			opcode, time, nflops, d1m, d1n, d1s, d2m, d2n, d2s, d3m, d3n, d3s);
 
 		return time;
 	}

src/main/java/org/apache/sysds/hops/rewrite/RewriteInjectOOCTee.java

@@ -26,6 +26,7 @@
 import org.apache.sysds.hops.Hop;
 import org.apache.sysds.hops.ReorgOp;
 import org.apache.sysds.parser.StatementBlock;
+import org.apache.sysds.utils.ParameterizedLogger;
 
 import java.util.ArrayList;
 import java.util.HashMap;
@@ -51,6 +52,7 @@
  * {@code TeeOp}, and safely rewire the graph.
  */
 public class RewriteInjectOOCTee extends StatementBlockRewriteRule {
+	private static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(RewriteInjectOOCTee.class);
 
 	public static boolean APPLY_ONLY_XtX_PATTERN = false;
 
@@ -138,10 +140,7 @@ private void applyTopDownTeeRewrite(Hop sharedInput) {
 		}
 
 		int consumerCount = sharedInput.getParent().size();
-		if (LOG.isDebugEnabled()) {
-			LOG.debug("Inject tee for hop " + sharedInput.getHopID() + " ("
-				+ sharedInput.getName() + "), consumers=" + consumerCount);
-		}
+		LOG.debug("Inject tee for hop {} ({}), consumers={}", sharedInput.getHopID(), sharedInput.getName(), consumerCount);
 
 		// Take a defensive copy of consumers before modifying the graph
 		ArrayList<Hop> consumers = new ArrayList<>(sharedInput.getParent());
@@ -161,10 +160,7 @@ private void applyTopDownTeeRewrite(Hop sharedInput) {
 		handledHop.put(sharedInput.getHopID(), teeOp);
 		rewrittenHops.add(sharedInput.getHopID());
 
-		if (LOG.isDebugEnabled()) {
-			LOG.debug("Created tee hop " + teeOp.getHopID() + " -> "
-				+ teeOp.getName());
-		}
+		LOG.debug("Created tee hop {} -> {}", teeOp.getHopID(), teeOp.getName());
 	}
 
 	@SuppressWarnings("unused")
@@ -276,11 +272,8 @@ private void removeRedundantTeeChains(Hop hop) {
 		if (HopRewriteUtils.isData(hop, OpOpData.TEE) && hop.getInput().size() == 1) {
 			Hop teeInput = hop.getInput().get(0);
 			if (HopRewriteUtils.isData(teeInput, OpOpData.TEE)) {
-				if (LOG.isDebugEnabled()) {
-					LOG.debug("Remove redundant tee hop " + hop.getHopID()
-						+ " (" + hop.getName() + ") -> " + teeInput.getHopID()
-						+ " (" + teeInput.getName() + ")");
-				}
+				LOG.debug("Remove redundant tee hop {} ({}) -> {} ({})",
+					hop.getHopID(), hop.getName(), teeInput.getHopID(), teeInput.getName());
 				HopRewriteUtils.rewireAllParentChildReferences(hop, teeInput);
 				HopRewriteUtils.removeAllChildReferences(hop);
 			}