Skip to content

Commit 940746b

Browse files
e-strausse-strauss
committed
better logging
1 parent 3f7b17b commit 940746b

15 files changed

Lines changed: 61 additions & 125 deletions

File tree

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

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -130,9 +130,7 @@ public DataOp(String l, DataType dt, ValueType vt,
130130
String s = e.getKey();
131131
Hop input = e.getValue();
132132
getInput().add(input);
133-
if (LOG.isDebugEnabled()){
134-
LOG.debug(String.format("%15s - %s",s,input));
135-
}
133+
LOG.debug(s + " - " + input);
136134
input.getParent().add(this);
137135

138136
_paramIndexMap.put(s, index);

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

Lines changed: 4 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -155,18 +155,16 @@ else if( pb instanceof BasicProgramBlock )
155155
//awareness of recursive functions, missing program
156156
if( !memoFunc.contains(fkey) && pb.getProgram()!=null )
157157
{
158-
if(LOG.isDebugEnabled())
159-
LOG.debug("Begin Function "+fkey);
160-
158+
LOG.debug("Begin Function " + fkey);
159+
161160
memoFunc.add(fkey);
162161
Program prog = pb.getProgram();
163162
FunctionProgramBlock fpb = prog.getFunctionProgramBlock(
164163
finst.getNamespace(), finst.getFunctionName());
165164
ret += rGetTimeEstimate(fpb, stats, memoFunc, recursive);
166165
memoFunc.remove(fkey);
167-
168-
if(LOG.isDebugEnabled())
169-
LOG.debug("End Function "+fkey);
166+
167+
LOG.debug("End Function " + fkey);
170168
}
171169
}
172170
}

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

Lines changed: 5 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[" + cpinst.getOpcode() + " - read] = " + 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[" + cpinst.getOpcode() + " - write] = " + wtime);
105103

106104
//total costs
107105
double costs = ltime + etime + wtime;
@@ -261,8 +259,7 @@ 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[" + opcode + "] = " + time + "s, " + nflops + " flops (" + d1m + "," + d1n + "," + d1s + "," + d2m + "," + d2n + "," + d2s + "," + d3m + "," + d3n + "," + d3s + ").");
266263

267264
return time;
268265
}

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

Lines changed: 3 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -138,10 +138,7 @@ private void applyTopDownTeeRewrite(Hop sharedInput) {
138138
}
139139

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

146143
// Take a defensive copy of consumers before modifying the graph
147144
ArrayList<Hop> consumers = new ArrayList<>(sharedInput.getParent());
@@ -161,10 +158,7 @@ private void applyTopDownTeeRewrite(Hop sharedInput) {
161158
handledHop.put(sharedInput.getHopID(), teeOp);
162159
rewrittenHops.add(sharedInput.getHopID());
163160

164-
if (LOG.isDebugEnabled()) {
165-
LOG.debug("Created tee hop " + teeOp.getHopID() + " -> "
166-
+ teeOp.getName());
167-
}
161+
LOG.debug("Created tee hop " + teeOp.getHopID() + " -> " + teeOp.getName());
168162
}
169163

170164
@SuppressWarnings("unused")
@@ -276,11 +270,7 @@ private void removeRedundantTeeChains(Hop hop) {
276270
if (HopRewriteUtils.isData(hop, OpOpData.TEE) && hop.getInput().size() == 1) {
277271
Hop teeInput = hop.getInput().get(0);
278272
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-
}
273+
LOG.debug("Remove redundant tee hop " + hop.getHopID() + " (" + hop.getName() + ") -> " + teeInput.getHopID() + " (" + teeInput.getName() + ")");
284274
HopRewriteUtils.rewireAllParentChildReferences(hop, teeInput);
285275
HopRewriteUtils.removeAllChildReferences(hop);
286276
}

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

Lines changed: 5 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -532,13 +532,11 @@ private Pair<MatrixBlock, CompressionStatistics> abortCompression() {
532532
}
533533

534534
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-
}
535+
LOG.debug("--Seed used for comp : " + compSettings.seed);
536+
LOG.debug("--number columns to compress: " + mb.getNumColumns());
537+
LOG.debug("--number rows to compress : " + mb.getNumRows());
538+
LOG.debug("--sparsity : " + mb.getSparsity());
539+
LOG.debug("--nonZeros : " + mb.getNonZeros());
542540
}
543541

544542
private void logPhase() {

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

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1172,8 +1172,7 @@ protected abstract T readBlobFromStream(OOCStream<IndexedMatrixValue> stream)
11721172

11731173
// Federated read
11741174
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");
1175+
LOG.debug("Pulling data from federated sites");
11771176
MetaDataFormat iimd = (MetaDataFormat) _metaData;
11781177
DataCharacteristics dc = iimd.getDataCharacteristics();
11791178
return readBlobFromFederated(fedMap, dc.getDims());

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

Lines changed: 3 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -290,11 +290,9 @@ private static void printStatistics() {
290290
}
291291

292292
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-
}
293+
LOG.debug("Executing command " + (nrRequest + 1) + "/" + totalRequests + ": " + request.getType().name());
294+
if(LOG.isTraceEnabled())
295+
LOG.trace("full command: " + request);
298296
}
299297

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

‎src/main/java/org/apache/sysds/runtime/controlprogram/paramserv/ParamServer.java‎

Lines changed: 4 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -203,10 +203,7 @@ protected synchronized void updateGlobalModel(int workerID, ListObject params) {
203203

204204
protected synchronized void updateGlobalGradients(int workerID, ListObject gradients) {
205205
try {
206-
if(LOG.isDebugEnabled()) {
207-
LOG.debug(String.format("Successfully pulled the gradients [size:%d kb] of worker_%d.",
208-
gradients.getDataSize() / 1024, workerID));
209-
}
206+
LOG.debug("Successfully pulled the gradients [size:" + gradients.getDataSize() / 1024 + " kb] of worker_" + workerID + ".");
210207

211208
switch(_updateType) {
212209
case BSP: {
@@ -298,8 +295,7 @@ private void performGlobalGradientUpdate() {
298295
// Broadcast the updated model
299296
broadcastModel(_finishedStates);
300297
resetFinishedStates();
301-
if(LOG.isDebugEnabled())
302-
LOG.debug("Global parameter is broadcasted successfully.");
298+
LOG.debug("Global parameter is broadcasted successfully.");
303299
}
304300

305301
private void tagStragglers() {
@@ -353,10 +349,7 @@ protected ListObject updateLocalModel(ExecutionContext ec, ListObject gradients,
353349

354350
protected synchronized void updateAverageModel(int workerID, ListObject model) {
355351
try {
356-
if(LOG.isDebugEnabled()) {
357-
LOG.debug(String.format("Successfully pulled the models [size:%d kb] of worker_%d.",
358-
model.getDataSize() / 1024, workerID));
359-
}
352+
LOG.debug("Successfully pulled the models [size:" + model.getDataSize() / 1024 + " kb] of worker_" + workerID + ".");
360353
Timing tAgg = DMLScript.STATISTICS ? new Timing(true) : null;
361354

362355
switch(_updateType) {
@@ -443,8 +436,7 @@ protected void updateAndBroadcastModel(ListObject new_model, Timing tAgg, boolea
443436
broadcastModel(true);
444437
else
445438
broadcastModel(workerBroadcastMask);
446-
if(LOG.isDebugEnabled())
447-
LOG.debug("Global parameter is broadcasted successfully ");
439+
LOG.debug("Global parameter is broadcasted successfully");
448440
}
449441

450442
protected ListObject weightModels(ListObject params, int numWorkers) {

‎src/main/java/org/apache/sysds/runtime/instructions/cp/MultiReturnParameterizedBuiltinCPInstruction.java‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -106,9 +106,7 @@ public void processInstruction(ExecutionContext ec) {
106106
ec.setMatrixOutput(getOutput(0).getName(), data);
107107
ec.setFrameOutput(getOutput(1).getName(), meta);
108108

109-
if(LOG.isDebugEnabled())
110-
// debug the size of the output metadata.
111-
LOG.debug("Memory size of metadata: " + meta.getInMemorySize());
109+
LOG.debug("Memory size of metadata: " + meta.getInMemorySize());
112110
}
113111

114112
@Override

‎src/main/java/org/apache/sysds/runtime/instructions/fed/InitFEDInstruction.java‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -423,8 +423,7 @@ public static void federateMatrix(CacheableData<?> output, List<Pair<FederatedRa
423423
try {
424424
int timeout = ConfigurationManager.getDMLConfig()
425425
.getIntValue(DMLConfig.DEFAULT_FEDERATED_INITIALIZATION_TIMEOUT);
426-
if( LOG.isDebugEnabled() )
427-
LOG.debug("Federated Initialization with timeout: " + timeout);
426+
LOG.debug("Federated Initialization with timeout: " + timeout);
428427
for(Pair<FederatedData, Future<FederatedResponse>> idResponse : idResponses) {
429428
// wait for initialization and check dimensions
430429
FederatedResponse re = idResponse.getRight().get(timeout, TimeUnit.SECONDS);

0 commit comments

Comments
 (0)