commons-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jean-Philippe Daigle" <Jean-Philippe.Dai...@SolaceSystems.com>
Subject Strange performance issues seen with Log.isDebugEnabled()
Date Wed, 25 Jun 2008 21:11:18 GMT
Hi, I'm seeing some very strange performance issues around the use of
commons logging, and I'm pretty much out of ideas at this point. (Long)
explanation follows...

First, two code samples (they're from a messaging system, the operation
of which shouldn't be terribly important; also, I removed some state
validation at the top of the method that's irrelevant), the only
difference is that A has two lines commented out:


SAMPLE A:
public void ackMessage(JCSMPXMLMessage msg) {
  long id = msg.getMessageIdLong();
  eAppAckResult ack_r = unackedList.applicationAck(id);
//if (Trace.isDebugEnabled()) {
    Trace.debug(String.format("appack>>> id=%s res=%s", id, ack_r));
//}
  // only increment ack stats if we're sending acks (prevent DUP-ack)
  if (ack_r == eAppAckResult.NOT_FOUND || ack_r == eAppAckResult.OK) {
    JCSMPSessionStats sessionStats = session.getSessionStats();
    sessionStats.incStat(StatType.RELIABLE_MSGS_RECVED_ACKED);
    if (msg.getMessageType().equals(MessageType.PERSISTENT)) {
 
sessionStats.incStat(StatType.RELIABLE_PERSISTENT_MSGS_RECVED_ACKED);
    } else if (msg.getMessageType().equals(MessageType.NON_PERSISTENT))
{
 
sessionStats.incStat(StatType.RELIABLE_NONPERSISTENT_MSGS_RECVED_ACKED);
    }
  }
}


SAMPLE B:
public void ackMessage(JCSMPXMLMessage msg) {
  long id = msg.getMessageIdLong();
  eAppAckResult ack_r = unackedList.applicationAck(id);
  if (Trace.isDebugEnabled()) {
    Trace.debug(String.format("appack>>> id=%s res=%s", id, ack_r));
  }
  // only increment ack stats if we're sending acks (prevent DUP-ack)
  if (ack_r == eAppAckResult.NOT_FOUND || ack_r == eAppAckResult.OK) {
    JCSMPSessionStats sessionStats = session.getSessionStats();
    sessionStats.incStat(StatType.RELIABLE_MSGS_RECVED_ACKED);
    if (msg.getMessageType().equals(MessageType.PERSISTENT)) {
 
sessionStats.incStat(StatType.RELIABLE_PERSISTENT_MSGS_RECVED_ACKED);
    } else if (msg.getMessageType().equals(MessageType.NON_PERSISTENT))
{
 
sessionStats.incStat(StatType.RELIABLE_NONPERSISTENT_MSGS_RECVED_ACKED);
    }
  }
}


The only difference between the two samples is whether or not that
"Trace.isDebugEnabled()" method is called (Trace is a
org.apache.commons.logging.Log). Know that in this scenario of course,
that method returns false (that is, debug logging is disabled, because
we care about throughput here).

You'd naturally expect that SAMPLE A would run slower, because it's
paying the cost of a String.format() on every call, and the logging
level will be checked downstream in .debug(...) anyways. And you'd be
right, if you use nanoTime() to time the execution of that whole logging
block, SAMPLE A averages ~4000ns and SAMPLE B averages ~400ns, just as
you'd expect.

But this is where expectations get thrown out of the window: when you
measure the throughput of the whole message reception system, in, let's
call them arbitrary "work units per second", in A you get 80000 WU/s and
in B you get 30000 WU/s. That's right, I didn't flip those around: the
slower A method, which runs on each message reception, yields more than
double the throughput, and I cannot explain why. Commenting out that
line is the only difference between the two libraries.

Pre-emptive Q/A:

Q) What type of Logger is instantiated?
A) Jdk14Logger, but I'm seeing the same results with my own NO-OP logger
(see below). 

Q) Are you sure isDebugEnabled() isn't just ridiculously slow?
A) Yes. Validated by timing the calls, and also running under a
profiler: it uses a negligible amount of time. Also, I completely ripped
out the apache commons logging library and put in my own
"org.apache.commons.logging.Log" implementation in the classpath, where
isDebugEnabled() returns false, and the logging calls such as
.debug(...) are just an empty block. I'm seeing the exact same effect
with my zero-cost methods.

Q) Does isDebugEnabled() acquire any locks?
A) No. Stepped through the whole thing in a debugger, doesn't seem to be
taking any locks. Especially not with my hacked version, which does
nothing.

Q) What is this "Trace" variable?
A) It's a private, static instance of a Logger for the current class:
"private static final Log Trace =
LogFactory.getLog(FlowHandleImpl.class);". Just in case that matters,
I've also tried switching it to a private local instance variable, which
didn't affect the throughput in any way.

Q) How long have you been staring at this?
A) Far. Too. Long. I've narrowed down the difference to THAT ONE LINE.

Q) Anything else?
A) ackMessage() is always called by the same single thread. Also, using
perfmon on Windows shows that when the messaging system with SAMPLE A is
running, it's seeing, globally, 4000 ctx switches/sec. The same
messaging system built with SAMPLE B sees 35000 ctx switches/sec.
Clearly, this is related, but I have no idea why this is happening, and
it's happening even with my hacked Logger implementation that just
consists of "boolean isDebugEnabled() {return false;}".

Conclusion: I'm pretty much out of ideas for explaining this. Clearly
it's not the isDebugEnabled() call itself that's killing us, it's just
having some other weird effect on the system. Which is somehow resulting
in a 60% throughput reduction.

Thanks in advance to anyone that can offer opinions on what's going
on...
Jean-Philippe


---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@commons.apache.org
For additional commands, e-mail: user-help@commons.apache.org


Mime
View raw message