commons-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From simon <simon.kitch...@chello.at>
Subject Re: Strange performance issues seen with Log.isDebugEnabled()
Date Wed, 25 Jun 2008 21:34:20 GMT

On Wed, 2008-06-25 at 17:11 -0400, Jean-Philippe Daigle wrote:
> 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...

Wow. Really weird.

I'll try to find some time to stare at the Log class tomorrow. But
you've been so thorough I'm not sure what I might spot that you haven't
already seen.

I presume you've also just tried
  if (Trace.isDebugEnabled()) {
    // do nothing
  }
and that the performance impact is still there?

Log is just an interface, and you say you have put in your own
implementation that returns immediately (presumably you also wrote a
LogFactory implementation that returned an instance of your Log type?).
So in that case
  Trace.isDebugEnabled()
is exactly equivalent to
  private static final SomeClass Trace = new SomeClass();
  ...
  Trace.anyOldEmptyMethod();
and it doesn't make *any* sense that that would affect performance. So
are you *really* sure that your "replacement" class actually got used?

Regards,
Simon


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


Mime
View raw message