Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 1 addition & 3 deletions src/main/java/org/apache/sysds/hops/DataOp.java
Original file line number Diff line number Diff line change
Expand Up @@ -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(s + " - " + input);
input.getParent().add(this);

_paramIndexMap.put(s, index);
Expand Down
10 changes: 4 additions & 6 deletions src/main/java/org/apache/sysds/hops/cost/CostEstimator.java
Original file line number Diff line number Diff line change
Expand Up @@ -155,18 +155,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);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The main difference here, is that the LOG.isDebugEnabled() is very cheap, while the string concatenation can be very expensive. Unfortunately to call the LOG.debug java has to resolve the string variable input, and that is the main time used, especially if Logging is disabled.

I do not know if there is a way to avoid the string concatenation, or somehow getting it delayed to after the logging is analysed to be off.

Copy link
Contributor Author

@e-strauss e-strauss Feb 18, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see your point, but isnt it in practice in micro-level noise for these simple concats? i think we might over-engineer here

Why are we sticking to apache commons logging? with the newer SLF4J we would could do stuff like this:

LOG.debug("Begin Function {}", fkey);

also SLF4J might already be used inside apachae commons logging, since it's already in the pom

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This would be cool, but we should not change the logging framework, so we just need to verify.


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);
}
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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[" + cpinst.getOpcode() + " - read] = " + ltime);

//exec time CP instruction
String opcode = (cpinst instanceof FunctionCallCPInstruction) ? InstructionUtils.getOpCode(cpinst.toString()) : cpinst.getOpcode();
Expand All @@ -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[" + cpinst.getOpcode() + " - write] = " + wtime);

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

return time;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -138,10 +138,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 " + sharedInput.getHopID() + " (" + sharedInput.getName() + "), consumers=" + consumerCount);

// Take a defensive copy of consumers before modifying the graph
ArrayList<Hop> consumers = new ArrayList<>(sharedInput.getParent());
Expand All @@ -161,10 +158,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")
Expand Down Expand Up @@ -276,11 +270,7 @@ 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);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -532,13 +532,11 @@ private Pair<MatrixBlock, CompressionStatistics> abortCompression() {
}

private void logInit() {
if(LOG.isDebugEnabled()) {
LOG.debug("--Seed used for comp : " + compSettings.seed);
LOG.debug(String.format("--number columns to compress: %10d", mb.getNumColumns()));
LOG.debug(String.format("--number rows to compress : %10d", mb.getNumRows()));
LOG.debug(String.format("--sparsity : %10.5f", mb.getSparsity()));
LOG.debug(String.format("--nonZeros : %10d", mb.getNonZeros()));
}
LOG.debug("--Seed used for comp : " + compSettings.seed);
LOG.debug("--number columns to compress: " + mb.getNumColumns());
LOG.debug("--number rows to compress : " + mb.getNumRows());
LOG.debug("--sparsity : " + mb.getSparsity());
LOG.debug("--nonZeros : " + mb.getNonZeros());
}

private void logPhase() {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -1172,8 +1172,7 @@ protected abstract T readBlobFromStream(OOCStream<IndexedMatrixValue> stream)

// Federated read
protected T readBlobFromFederated(FederationMap fedMap) throws IOException {
if( LOG.isDebugEnabled() ) //common if instructions keep federated outputs
LOG.debug("Pulling data from federated sites");
LOG.debug("Pulling data from federated sites");
MetaDataFormat iimd = (MetaDataFormat) _metaData;
DataCharacteristics dc = iimd.getDataCharacteristics();
return readBlobFromFederated(fedMap, dc.getDims());
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -290,11 +290,9 @@ private static void printStatistics() {
}

private static void logRequests(FederatedRequest request, int nrRequest, int totalRequests) {
if(LOG.isDebugEnabled()) {
LOG.debug("Executing command " + (nrRequest + 1) + "/" + totalRequests + ": " + request.getType().name());
if(LOG.isTraceEnabled())
LOG.trace("full command: " + request.toString());
}
LOG.debug("Executing command " + (nrRequest + 1) + "/" + totalRequests + ": " + request.getType().name());
if(LOG.isTraceEnabled())
LOG.trace("full command: " + request);
}

private FederatedResponse executeCommand(FederatedRequest request, ExecutionContextMap ecm, EventStageModel eventStage)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -203,10 +203,7 @@ protected synchronized void updateGlobalModel(int workerID, ListObject params) {

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

switch(_updateType) {
case BSP: {
Expand Down Expand Up @@ -298,8 +295,7 @@ private void performGlobalGradientUpdate() {
// Broadcast the updated model
broadcastModel(_finishedStates);
resetFinishedStates();
if(LOG.isDebugEnabled())
LOG.debug("Global parameter is broadcasted successfully.");
LOG.debug("Global parameter is broadcasted successfully.");
}

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

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

switch(_updateType) {
Expand Down Expand Up @@ -443,8 +436,7 @@ protected void updateAndBroadcastModel(ListObject new_model, Timing tAgg, boolea
broadcastModel(true);
else
broadcastModel(workerBroadcastMask);
if(LOG.isDebugEnabled())
LOG.debug("Global parameter is broadcasted successfully ");
LOG.debug("Global parameter is broadcasted successfully");
}

protected ListObject weightModels(ListObject params, int numWorkers) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -106,9 +106,7 @@ public void processInstruction(ExecutionContext ec) {
ec.setMatrixOutput(getOutput(0).getName(), data);
ec.setFrameOutput(getOutput(1).getName(), meta);

if(LOG.isDebugEnabled())
// debug the size of the output metadata.
LOG.debug("Memory size of metadata: " + meta.getInMemorySize());
LOG.debug("Memory size of metadata: " + meta.getInMemorySize());
}

@Override
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -423,8 +423,7 @@ public static void federateMatrix(CacheableData<?> output, List<Pair<FederatedRa
try {
int timeout = ConfigurationManager.getDMLConfig()
.getIntValue(DMLConfig.DEFAULT_FEDERATED_INITIALIZATION_TIMEOUT);
if( LOG.isDebugEnabled() )
LOG.debug("Federated Initialization with timeout: " + timeout);
LOG.debug("Federated Initialization with timeout: " + timeout);
for(Pair<FederatedData, Future<FederatedResponse>> idResponse : idResponses) {
// wait for initialization and check dimensions
FederatedResponse re = idResponse.getRight().get(timeout, TimeUnit.SECONDS);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -36,9 +36,7 @@ public static MatrixReader createMatrixReader(FileFormat fmt) {
boolean par = ConfigurationManager.getCompilerConfigFlag(ConfigType.PARALLEL_CP_READ_TEXTFORMATS);
boolean mcsr = MatrixBlock.DEFAULT_SPARSEBLOCK == SparseBlock.Type.MCSR;

if (LOG.isDebugEnabled()){
LOG.debug("reading parallel: " + par + " mcsr: " + mcsr);
}
LOG.debug("reading parallel: " + par + " mcsr: " + mcsr);

switch(fmt) {
case TEXT:
Expand Down Expand Up @@ -95,9 +93,7 @@ public static MatrixReader createMatrixReader( ReadProperties props ) {
boolean par = ConfigurationManager.getCompilerConfigFlag(ConfigType.PARALLEL_CP_READ_TEXTFORMATS);
boolean mcsr = MatrixBlock.DEFAULT_SPARSEBLOCK == SparseBlock.Type.MCSR;

if (LOG.isDebugEnabled()){
LOG.debug("reading parallel: " + par + " mcsr: " + mcsr);
}
LOG.debug("reading parallel: " + par + " mcsr: " + mcsr);

switch(fmt) {
case TEXT:
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -167,8 +167,7 @@ private static ArrayList<Instruction> rewriteTsmmCbind (Instruction curr, Execut
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteTsmmCbind APPLIED");
LOG.debug("LINEAGE REWRITE rewriteTsmmCbind APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);

// cleanup buffer pool
Expand Down Expand Up @@ -209,8 +208,7 @@ private static ArrayList<Instruction> rewriteTsmmCbindOnes (Instruction curr, Ex
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteTsmmCbindOnes APPLIED");
LOG.debug("LINEAGE REWRITE rewriteTsmmCbindOnes APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -254,8 +252,7 @@ private static ArrayList<Instruction> rewriteTsmmRbind (Instruction curr, Execut
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteTsmmRbind APPLIED");
LOG.debug("LINEAGE REWRITE rewriteTsmmRbind APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -318,8 +315,7 @@ private static ArrayList<Instruction> rewriteTsmm2Cbind (Instruction curr, Execu
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteTsmm2Cbind APPLIED");
LOG.debug("LINEAGE REWRITE rewriteTsmm2Cbind APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -389,8 +385,7 @@ private static ArrayList<Instruction> rewriteTsmm2CbindSameLeft (Instruction cur
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteTsmm2CbindSameLeft APPLIED");
LOG.debug("LINEAGE REWRITE rewriteTsmm2CbindSameLeft APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -435,8 +430,7 @@ private static ArrayList<Instruction> rewriteMatMulRbindLeft (Instruction curr,
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteMetMulRbindLeft APPLIED");
LOG.debug("LINEAGE REWRITE rewriteMetMulRbindLeft APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -481,8 +475,7 @@ private static ArrayList<Instruction> rewriteMatMulCbindRight (Instruction curr,
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteMatMulCbindRight APPLIED");
LOG.debug("LINEAGE REWRITE rewriteMatMulCbindRight APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -516,8 +509,7 @@ private static ArrayList<Instruction> rewriteMatMulCbindRightOnes (Instruction c
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteMatMulCbindRightOnes APPLIED");
LOG.debug("LINEAGE REWRITE rewriteMatMulCbindRightOnes APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -573,8 +565,7 @@ private static ArrayList<Instruction> rewriteElementMulRbind (Instruction curr,
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteElementMulRbind APPLIED");
LOG.debug("LINEAGE REWRITE rewriteElementMulRbind APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -630,8 +621,7 @@ private static ArrayList<Instruction> rewriteElementMulCbind (Instruction curr,
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteElementMulCbind APPLIED");
LOG.debug("LINEAGE REWRITE rewriteElementMulCbind APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -687,8 +677,7 @@ private static ArrayList<Instruction> rewriteAggregateCbind (Instruction curr, E
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteElementMulCbind APPLIED");
LOG.debug("LINEAGE REWRITE rewriteElementMulCbind APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down Expand Up @@ -740,8 +729,7 @@ private static ArrayList<Instruction> rewriteIndexingMatMul (Instruction curr, E
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewriteIndexingMatMul APPLIED");
LOG.debug("LINEAGE REWRITE rewriteIndexingMatMul APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
// Keep reuse enabled
_disableReuse = false;
Expand Down Expand Up @@ -801,8 +789,7 @@ private static ArrayList<Instruction> rewritePcaTsmm(Instruction curr, Execution
DataOp lrwWrite = HopRewriteUtils.createTransientWrite(LR_VAR, lrwHop);

// Generate runtime instructions
if (LOG.isDebugEnabled())
LOG.debug("LINEAGE REWRITE rewritePcaTsmm APPLIED");
LOG.debug("LINEAGE REWRITE rewritePcaTsmm APPLIED");
ArrayList<Instruction> inst = genInst(lrwWrite, lrwec);
_disableReuse = true;

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -73,13 +73,10 @@ public MatrixBlock getValue(MatrixBlock blkIn) {

SmallestPriorityQueue spq = getKSmallestHashes(blkIn, k, M);

if(LOG.isDebugEnabled()) {
LOG.debug("M not forced to int size: " + tmp);
LOG.debug("M: " + M);
LOG.debug("M: " + M);
LOG.debug("kth smallest hash:" + spq.peek());
LOG.debug("spq: " + spq);
}
LOG.debug("M not forced to int size: " + tmp);
LOG.debug("M: " + M);
LOG.debug("kth smallest hash: " + spq.peek());
LOG.debug("spq: " + spq);


long res = countDistinctValuesKMV(spq, k, M, D);
Expand Down Expand Up @@ -197,11 +194,9 @@ private long countDistinctValuesKMV(SmallestPriorityQueue spq, int k, int M, lon
double estimate = (k - 1) / U_k;
double ceilEstimate = Math.min(estimate, D);

if(LOG.isDebugEnabled()) {
LOG.debug("U_k : " + U_k);
LOG.debug("Estimate: " + estimate);
LOG.debug("Ceil worst case: " + D);
}
LOG.debug("U_k : " + U_k);
LOG.debug("Estimate: " + estimate);
LOG.debug("Ceil worst case: " + D);
res = Math.round(ceilEstimate);
}

Expand Down
Loading
Loading