Skip to content

Commit 423df5c

Browse files
e-strausse-strauss
committed
better logging
1 parent 3f7b17b commit 423df5c

File tree

16 files changed

+292
-184
lines changed

16 files changed

+292
-184
lines changed

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

Lines changed: 3 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -22,8 +22,6 @@
2222
import java.util.HashMap;
2323
import java.util.Map.Entry;
2424

25-
import org.apache.commons.logging.Log;
26-
import org.apache.commons.logging.LogFactory;
2725
import org.apache.sysds.api.DMLScript;
2826
import org.apache.sysds.common.Types.DataType;
2927
import org.apache.sysds.common.Types.FileFormat;
@@ -44,13 +42,14 @@
4442
import org.apache.sysds.runtime.controlprogram.caching.MatrixObject.UpdateType;
4543
import org.apache.sysds.runtime.meta.DataCharacteristics;
4644
import org.apache.sysds.runtime.util.LocalFileUtils;
45+
import org.apache.sysds.utils.ParameterizedLogger;
4746

4847
/**
4948
* A DataOp can be either a persistent read/write or transient read/write - writes will always have at least one input,
5049
* but all types can have parameters (e.g., for csv literals of delimiter, header, etc).
5150
*/
5251
public class DataOp extends Hop {
53-
private static final Log LOG = LogFactory.getLog(DataOp.class.getName());
52+
private static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(DataOp.class);
5453
private OpOpData _op;
5554
private String _fileName = null;
5655

@@ -130,9 +129,7 @@ public DataOp(String l, DataType dt, ValueType vt,
130129
String s = e.getKey();
131130
Hop input = e.getValue();
132131
getInput().add(input);
133-
if (LOG.isDebugEnabled()){
134-
LOG.debug(String.format("%15s - %s",s,input));
135-
}
132+
LOG.debug("{} - {}", s, input);
136133
input.getParent().add(this);
137134

138135
_paramIndexMap.put(s, index);

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

Lines changed: 6 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -19,8 +19,6 @@
1919

2020
package org.apache.sysds.hops.cost;
2121

22-
import org.apache.commons.logging.Log;
23-
import org.apache.commons.logging.LogFactory;
2422
import org.apache.sysds.common.Opcodes;
2523
import org.apache.sysds.conf.ConfigurationManager;
2624
import org.apache.sysds.hops.OptimizerUtils;
@@ -54,14 +52,15 @@
5452
import org.apache.sysds.runtime.matrix.operators.CMOperator;
5553
import org.apache.sysds.runtime.matrix.operators.CMOperator.AggregateOperationTypes;
5654
import org.apache.sysds.runtime.meta.DataCharacteristics;
55+
import org.apache.sysds.utils.ParameterizedLogger;
5756

5857
import java.util.ArrayList;
5958
import java.util.HashMap;
6059
import java.util.HashSet;
6160

6261
public abstract class CostEstimator
6362
{
64-
protected static final Log LOG = LogFactory.getLog(CostEstimator.class.getName());
63+
protected static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(CostEstimator.class);
6564

6665
private static final int DEFAULT_NUMITER = 15;
6766

@@ -155,18 +154,16 @@ else if( pb instanceof BasicProgramBlock )
155154
//awareness of recursive functions, missing program
156155
if( !memoFunc.contains(fkey) && pb.getProgram()!=null )
157156
{
158-
if(LOG.isDebugEnabled())
159-
LOG.debug("Begin Function "+fkey);
160-
157+
LOG.debug("Begin Function {}", fkey);
158+
161159
memoFunc.add(fkey);
162160
Program prog = pb.getProgram();
163161
FunctionProgramBlock fpb = prog.getFunctionProgramBlock(
164162
finst.getNamespace(), finst.getFunctionName());
165163
ret += rGetTimeEstimate(fpb, stats, memoFunc, recursive);
166164
memoFunc.remove(fkey);
167-
168-
if(LOG.isDebugEnabled())
169-
LOG.debug("End Function "+fkey);
165+
166+
LOG.debug("End Function {}", fkey);
170167
}
171168
}
172169
}

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

Lines changed: 6 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -85,9 +85,8 @@ protected double getCPInstTimeEstimate( Instruction inst, VarStats[] vs, String[
8585
}
8686
vs[1]._inmem = true;
8787
}
88-
if( LOG.isDebugEnabled() && ltime!=0 ) {
89-
LOG.debug("Cost["+cpinst.getOpcode()+" - read] = "+ltime);
90-
}
88+
if(ltime != 0)
89+
LOG.debug("Cost[{} - read] = {}", cpinst.getOpcode(), ltime);
9190

9291
//exec time CP instruction
9392
String opcode = (cpinst instanceof FunctionCallCPInstruction) ? InstructionUtils.getOpCode(cpinst.toString()) : cpinst.getOpcode();
@@ -99,9 +98,8 @@ protected double getCPInstTimeEstimate( Instruction inst, VarStats[] vs, String[
9998
if( inst instanceof VariableCPInstruction && ((VariableCPInstruction)inst).getOpcode().equals(Opcodes.WRITE.toString()) )
10099
wtime += getHDFSWriteTime(vs[2].getRows(), vs[2].getCols(), vs[2].getSparsity(), ((VariableCPInstruction)inst).getInput3().getName() );
101100

102-
if( LOG.isDebugEnabled() && wtime!=0 ) {
103-
LOG.debug("Cost["+cpinst.getOpcode()+" - write] = "+wtime);
104-
}
101+
if(wtime != 0)
102+
LOG.debug("Cost[{} - write] = {}", cpinst.getOpcode(), wtime);
105103

106104
//total costs
107105
double costs = ltime + etime + wtime;
@@ -261,8 +259,8 @@ private static double getInstTimeEstimate( String opcode, boolean inMR, long d1m
261259
double nflops = getNFLOP(opcode, inMR, d1m, d1n, d1s, d2m, d2n, d2s, d3m, d3n, d3s, args);
262260
double time = nflops / DEFAULT_FLOPS;
263261

264-
if( LOG.isDebugEnabled() )
265-
LOG.debug("Cost["+opcode+"] = "+time+"s, "+nflops+" flops ("+d1m+","+d1n+","+d1s+","+d2m+","+d2n+","+d2s+","+d3m+","+d3n+","+d3s+").");
262+
LOG.debug("Cost[{}] = {}s, {} flops ({},{},{},{},{},{},{},{},{}).",
263+
opcode, time, nflops, d1m, d1n, d1s, d2m, d2n, d2s, d3m, d3n, d3s);
266264

267265
return time;
268266
}

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

Lines changed: 6 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@
2626
import org.apache.sysds.hops.Hop;
2727
import org.apache.sysds.hops.ReorgOp;
2828
import org.apache.sysds.parser.StatementBlock;
29+
import org.apache.sysds.utils.ParameterizedLogger;
2930

3031
import java.util.ArrayList;
3132
import java.util.HashMap;
@@ -51,6 +52,7 @@
5152
* {@code TeeOp}, and safely rewire the graph.
5253
*/
5354
public class RewriteInjectOOCTee extends StatementBlockRewriteRule {
55+
private static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(RewriteInjectOOCTee.class);
5456

5557
public static boolean APPLY_ONLY_XtX_PATTERN = false;
5658

@@ -138,10 +140,7 @@ private void applyTopDownTeeRewrite(Hop sharedInput) {
138140
}
139141

140142
int consumerCount = sharedInput.getParent().size();
141-
if (LOG.isDebugEnabled()) {
142-
LOG.debug("Inject tee for hop " + sharedInput.getHopID() + " ("
143-
+ sharedInput.getName() + "), consumers=" + consumerCount);
144-
}
143+
LOG.debug("Inject tee for hop {} ({}), consumers={}", sharedInput.getHopID(), sharedInput.getName(), consumerCount);
145144

146145
// Take a defensive copy of consumers before modifying the graph
147146
ArrayList<Hop> consumers = new ArrayList<>(sharedInput.getParent());
@@ -161,10 +160,7 @@ private void applyTopDownTeeRewrite(Hop sharedInput) {
161160
handledHop.put(sharedInput.getHopID(), teeOp);
162161
rewrittenHops.add(sharedInput.getHopID());
163162

164-
if (LOG.isDebugEnabled()) {
165-
LOG.debug("Created tee hop " + teeOp.getHopID() + " -> "
166-
+ teeOp.getName());
167-
}
163+
LOG.debug("Created tee hop {} -> {}", teeOp.getHopID(), teeOp.getName());
168164
}
169165

170166
@SuppressWarnings("unused")
@@ -276,11 +272,8 @@ private void removeRedundantTeeChains(Hop hop) {
276272
if (HopRewriteUtils.isData(hop, OpOpData.TEE) && hop.getInput().size() == 1) {
277273
Hop teeInput = hop.getInput().get(0);
278274
if (HopRewriteUtils.isData(teeInput, OpOpData.TEE)) {
279-
if (LOG.isDebugEnabled()) {
280-
LOG.debug("Remove redundant tee hop " + hop.getHopID()
281-
+ " (" + hop.getName() + ") -> " + teeInput.getHopID()
282-
+ " (" + teeInput.getName() + ")");
283-
}
275+
LOG.debug("Remove redundant tee hop {} ({}) -> {} ({})",
276+
hop.getHopID(), hop.getName(), teeInput.getHopID(), teeInput.getName());
284277
HopRewriteUtils.rewireAllParentChildReferences(hop, teeInput);
285278
HopRewriteUtils.removeAllChildReferences(hop);
286279
}

‎src/main/java/org/apache/sysds/runtime/compress/CompressedMatrixBlockFactory.java‎

Lines changed: 29 additions & 32 deletions
Original file line numberDiff line numberDiff line change
@@ -27,8 +27,6 @@
2727

2828
import org.apache.commons.lang3.tuple.ImmutablePair;
2929
import org.apache.commons.lang3.tuple.Pair;
30-
import org.apache.commons.logging.Log;
31-
import org.apache.commons.logging.LogFactory;
3230
import org.apache.sysds.runtime.compress.cocode.CoCoderFactory;
3331
import org.apache.sysds.runtime.compress.colgroup.AColGroup;
3432
import org.apache.sysds.runtime.compress.colgroup.AColGroupValue;
@@ -55,14 +53,15 @@
5553
import org.apache.sysds.runtime.matrix.data.MatrixBlock;
5654
import org.apache.sysds.runtime.util.CommonThreadPool;
5755
import org.apache.sysds.utils.DMLCompressionStatistics;
56+
import org.apache.sysds.utils.ParameterizedLogger;
5857
import org.apache.sysds.utils.stats.Timing;
5958

6059
/**
6160
* Factory pattern to compress a Matrix Block into a CompressedMatrixBlock.
6261
*/
6362
public class CompressedMatrixBlockFactory {
6463

65-
private static final Log LOG = LogFactory.getLog(CompressedMatrixBlockFactory.class.getName());
64+
private static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(CompressedMatrixBlockFactory.class);
6665

6766
/** Timing object to measure the time of each phase in the compression */
6867
private final Timing time = new Timing(true);
@@ -336,7 +335,7 @@ else if(mb instanceof CompressedMatrixBlock && ((CompressedMatrixBlock) mb).isOv
336335
if(CompressedMatrixBlock.debug) {
337336
final double afterComp = mb.sum(k).getDouble(0, 0);
338337
final double deltaSum = Math.abs(orgSum - afterComp);
339-
LOG.debug("compression Sum: Before:" + orgSum + " after: " + afterComp + " |delta|: " + deltaSum);
338+
LOG.debug("compression Sum: Before:{} after: {} |delta|: {}", orgSum, afterComp, deltaSum);
340339
}
341340

342341
return new ImmutablePair<>(res, _stats);
@@ -485,8 +484,8 @@ private void finalizePhase() {
485484
LOG.info("--original Cost: " + _stats.originalCost);
486485
LOG.info("--Compressed Cost: " + _stats.compressedCost);
487486
LOG.info("--Cost Ratio: " + _stats.getCostRatio());
488-
LOG.debug("--col groups types " + _stats.getGroupsTypesString());
489-
LOG.debug("--col groups sizes " + _stats.getGroupsSizesString());
487+
LOG.debug("--col groups types {}", _stats.getGroupsTypesString());
488+
LOG.debug("--col groups sizes {}", _stats.getGroupsSizesString());
490489
logLengths();
491490
LOG.info("Abort block compression because cost ratio is less than 1. ");
492491
res = null;
@@ -532,13 +531,11 @@ private Pair<MatrixBlock, CompressionStatistics> abortCompression() {
532531
}
533532

534533
private void logInit() {
535-
if(LOG.isDebugEnabled()) {
536-
LOG.debug("--Seed used for comp : " + compSettings.seed);
537-
LOG.debug(String.format("--number columns to compress: %10d", mb.getNumColumns()));
538-
LOG.debug(String.format("--number rows to compress : %10d", mb.getNumRows()));
539-
LOG.debug(String.format("--sparsity : %10.5f", mb.getSparsity()));
540-
LOG.debug(String.format("--nonZeros : %10d", mb.getNonZeros()));
541-
}
534+
LOG.debug("--Seed used for comp : {}", compSettings.seed);
535+
LOG.debug("--number columns to compress: {}", mb.getNumColumns());
536+
LOG.debug("--number rows to compress : {}", mb.getNumRows());
537+
LOG.debug("--sparsity : {}", mb.getSparsity());
538+
LOG.debug("--nonZeros : {}", mb.getNonZeros());
542539
}
543540

544541
private void logPhase() {
@@ -552,41 +549,41 @@ private void logPhase() {
552549
else {
553550
switch(phase) {
554551
case 0:
555-
LOG.debug("--compression phase " + phase + " Classify : " + getLastTimePhase());
556-
LOG.debug("--Individual Columns Estimated Compression: " + _stats.estimatedSizeCols);
552+
LOG.debug("--compression phase {} Classify : {}", phase, getLastTimePhase());
553+
LOG.debug("--Individual Columns Estimated Compression: {}", _stats.estimatedSizeCols);
557554
if(mb instanceof CompressedMatrixBlock) {
558555
LOG.debug("--Recompressing already compressed MatrixBlock");
559556
}
560557
break;
561558
case 1:
562-
LOG.debug("--compression phase " + phase + " Grouping : " + getLastTimePhase());
563-
LOG.debug("Grouping using: " + compSettings.columnPartitioner);
564-
LOG.debug("Cost Calculated using: " + costEstimator);
565-
LOG.debug("--Cocoded Columns estimated Compression:" + _stats.estimatedSizeCoCoded);
559+
LOG.debug("--compression phase {} Grouping : {}", phase, getLastTimePhase());
560+
LOG.debug("Grouping using: {}", compSettings.columnPartitioner);
561+
LOG.debug("Cost Calculated using: {}", costEstimator);
562+
LOG.debug("--Cocoded Columns estimated Compression:{}", _stats.estimatedSizeCoCoded);
566563
if(compressionGroups.getInfo().size() < 1000) {
567-
LOG.debug("--Cocoded Columns estimated nr distinct:" + compressionGroups.getEstimatedDistinct());
568-
LOG.debug("--Cocoded Columns nr columns :" + compressionGroups.getNrColumnsString());
564+
LOG.debug("--Cocoded Columns estimated nr distinct:{}", compressionGroups.getEstimatedDistinct());
565+
LOG.debug("--Cocoded Columns nr columns :{}", compressionGroups.getNrColumnsString());
569566
}
570567
else {
571568
LOG.debug(
572569
"--CoCoded produce many columns but the first says:\n" + compressionGroups.getInfo().get(0));
573570
}
574571
break;
575572
case 2:
576-
LOG.debug("--compression phase " + phase + " Transpose : " + getLastTimePhase());
577-
LOG.debug("Did transpose: " + compSettings.transposed);
573+
LOG.debug("--compression phase {} Transpose : {}", phase, getLastTimePhase());
574+
LOG.debug("Did transpose: {}", compSettings.transposed);
578575
break;
579576
case 3:
580-
LOG.debug("--compression phase " + phase + " Compress : " + getLastTimePhase());
581-
LOG.debug("--compressed initial actual size:" + _stats.compressedInitialSize);
577+
LOG.debug("--compression phase {} Compress : {}", phase, getLastTimePhase());
578+
LOG.debug("--compressed initial actual size:{}", _stats.compressedInitialSize);
582579
break;
583580
case 4:
584581
default:
585-
LOG.debug("--num col groups: " + res.getColGroups().size());
586-
LOG.debug("--compression phase " + phase + " Cleanup : " + getLastTimePhase());
587-
LOG.debug("--col groups types " + _stats.getGroupsTypesString());
588-
LOG.debug("--col groups sizes " + _stats.getGroupsSizesString());
589-
LOG.debug("--input was compressed " + (mb instanceof CompressedMatrixBlock));
582+
LOG.debug("--num col groups: {}", res.getColGroups().size());
583+
LOG.debug("--compression phase {} Cleanup : {}", phase, getLastTimePhase());
584+
LOG.debug("--col groups types {}", _stats.getGroupsTypesString());
585+
LOG.debug("--col groups sizes {}", _stats.getGroupsSizesString());
586+
LOG.debug("--input was compressed {}", (mb instanceof CompressedMatrixBlock));
590587
LOG.debug(String.format("--dense size: %16d", _stats.denseSize));
591588
LOG.debug(String.format("--sparse size: %16d", _stats.sparseSize));
592589
LOG.debug(String.format("--original size: %16d", _stats.originalSize));
@@ -615,8 +612,8 @@ private void logLengths() {
615612
for(AColGroup colGroup : res.getColGroups())
616613
lengths[i++] = colGroup.getNumValues();
617614

618-
LOG.debug("--compressed colGroup dictionary sizes: " + Arrays.toString(lengths));
619-
LOG.debug("--compressed colGroup nr columns : " + constructNrColumnString(res.getColGroups()));
615+
LOG.debug("--compressed colGroup dictionary sizes: {}", Arrays.toString(lengths));
616+
LOG.debug("--compressed colGroup nr columns : {}", constructNrColumnString(res.getColGroups()));
620617
}
621618
if(LOG.isTraceEnabled()) {
622619
for(AColGroup colGroup : res.getColGroups()) {

‎src/main/java/org/apache/sysds/runtime/controlprogram/caching/CacheableData.java‎

Lines changed: 3 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -28,8 +28,6 @@
2828
import java.util.stream.LongStream;
2929

3030
import org.apache.commons.lang3.mutable.MutableBoolean;
31-
import org.apache.commons.logging.Log;
32-
import org.apache.commons.logging.LogFactory;
3331
import org.apache.hadoop.fs.Path;
3432
import org.apache.sysds.api.DMLScript;
3533
import org.apache.sysds.common.Types.DataType;
@@ -66,6 +64,7 @@
6664
import org.apache.sysds.runtime.util.HDFSTool;
6765
import org.apache.sysds.runtime.util.LocalFileUtils;
6866
import org.apache.sysds.runtime.util.UtilFunctions;
67+
import org.apache.sysds.utils.ParameterizedLogger;
6968
import org.apache.sysds.utils.Statistics;
7069
import org.apache.sysds.utils.stats.InfrastructureAnalyzer;
7170

@@ -85,7 +84,7 @@ public abstract class CacheableData<T extends CacheBlock<?>> extends Data
8584
private static final long serialVersionUID = -413810592207212835L;
8685

8786
/** Global logging instance for all subclasses of CacheableData */
88-
protected static final Log LOG = LogFactory.getLog(CacheableData.class.getName());
87+
protected static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(CacheableData.class);
8988

9089
// global constant configuration parameters
9190
public static final long CACHING_THRESHOLD = (long)Math.max(4*1024, //obj not s.t. caching
@@ -1172,8 +1171,7 @@ protected abstract T readBlobFromStream(OOCStream<IndexedMatrixValue> stream)
11721171

11731172
// Federated read
11741173
protected T readBlobFromFederated(FederationMap fedMap) throws IOException {
1175-
if( LOG.isDebugEnabled() ) //common if instructions keep federated outputs
1176-
LOG.debug("Pulling data from federated sites");
1174+
LOG.debug("Pulling data from federated sites");
11771175
MetaDataFormat iimd = (MetaDataFormat) _metaData;
11781176
DataCharacteristics dc = iimd.getDataCharacteristics();
11791177
return readBlobFromFederated(fedMap, dc.getDims());

‎src/main/java/org/apache/sysds/runtime/controlprogram/federated/FederatedWorkerHandler.java‎

Lines changed: 5 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -27,8 +27,6 @@
2727
import java.util.Arrays;
2828
import java.util.concurrent.CompletableFuture;
2929

30-
import org.apache.commons.logging.Log;
31-
import org.apache.commons.logging.LogFactory;
3230
import org.apache.hadoop.fs.FileSystem;
3331
import org.apache.hadoop.fs.Path;
3432
import org.apache.sysds.api.DMLScript;
@@ -75,6 +73,7 @@
7573
import org.apache.sysds.runtime.meta.MatrixCharacteristics;
7674
import org.apache.sysds.runtime.meta.MetaDataAll;
7775
import org.apache.sysds.runtime.meta.MetaDataFormat;
76+
import org.apache.sysds.utils.ParameterizedLogger;
7877
import org.apache.sysds.utils.Statistics;
7978
import org.apache.sysds.utils.stats.InfrastructureAnalyzer;
8079
import org.apache.sysds.utils.stats.ParamServStatistics;
@@ -90,7 +89,7 @@
9089
* execution contexts at the federated sites too
9190
*/
9291
public class FederatedWorkerHandler extends ChannelInboundHandlerAdapter {
93-
private static final Log LOG = LogFactory.getLog(FederatedWorkerHandler.class.getName());
92+
private static final ParameterizedLogger LOG = ParameterizedLogger.getLogger(FederatedWorkerHandler.class);
9493

9594
/** The Federated Lookup Table of the current Federated Worker. */
9695
private final FederatedLookupTable _flt;
@@ -290,11 +289,9 @@ private static void printStatistics() {
290289
}
291290

292291
private static void logRequests(FederatedRequest request, int nrRequest, int totalRequests) {
293-
if(LOG.isDebugEnabled()) {
294-
LOG.debug("Executing command " + (nrRequest + 1) + "/" + totalRequests + ": " + request.getType().name());
295-
if(LOG.isTraceEnabled())
296-
LOG.trace("full command: " + request.toString());
297-
}
292+
LOG.debug("Executing command {}/{}: {}", nrRequest + 1, totalRequests, request.getType().name());
293+
if(LOG.isTraceEnabled())
294+
LOG.trace("full command: " + request);
298295
}
299296

300297
private FederatedResponse executeCommand(FederatedRequest request, ExecutionContextMap ecm, EventStageModel eventStage)

0 commit comments

Comments
 (0)