-----Original Message-----
> From: Jean-Philippe Daigle
[mailto:[EMAIL PROTECTED]
> Sent: Wednesday, June 25, 2008 6:06 PM
> To: Commons Users List
Subject: RE: Strange performance issues seen with Log.isDebugEnabled()
>
>
>
> > -----Original Message-----
> > From: simon [mailto:[EMAIL PROTECTED]
> > Sent: Wednesday, June 25, 2008 5:34 PM
> > To: Commons Users List
> > Subject: Re: Strange performance issues seen with
Log.isDebugEnabled()
> >
> >
> > On Wed, 2008-06-25 at 17:11 -0400, Jean-Philippe Daigle wrote:
> > > [snip]
> >
> > Wow. Really weird.
> >
> Thanks for replying, my thoughts exactly. Looks like gremlins to me.
>
> > 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?
>
> Yes. The 60% throughput degradation is there. If I remove that call to
> isDebugEnabled() the throughput goes back up.
>
>
> >
> > 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?).
>
> Sorry, should have said more about this, but my email was already too
> long! I wrote three files: Log, LogImpl, and LogFactory. Log and
> LogFactory clone the public interface of the equivalent "official"
> versions so I don't need to recompile the whole world, just switch out
a
> jar (but most methods are just empty). LogFactory returns LogImpl
> instances, which print out a debug line to stdout when constructed, to
> make absolutely sure I'm really using my own version and not the
apache
> one. I then remove the official commons-logging-1.1.1.jar file from
the
> classpath, leaving only my version.
>
>
> > 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?
> >
>
> Yes, it *should* be equivalent, but I've also tried defining a Dummy
> class, getting a static instance of it, and calling a dummy method
(that
> won't get optimized away) and it's fast (~80000 WU/s). Going back to
my
> custom isDebugEnabled(), boom, down to ~30000 WU/s. Unless you tell me
> that calling a method on an interface is HUGELY more expensive than a
> direct call (I don't think it is, and it wouldn't explain my
> micro-timings anyways), I have no idea what's going on.
>
> Thanks!
> Jean-Philippe Daigle
>
Ah, so there's one more thing I hadn't tried, which I just did, and
explained a bit of the situation: completely removing the logging block
(don't check isDebugEnabled(), don't call .debug(), etc.
Removing the whole logging block results in getting the same slow
throughput case that I was blaming on isDebugEnabled().
Replacing it with just this assignment (to a public var so it's not
optimized away):
_dbg_str = String.format("appack>>> id=%s res=%s", id, ack_r);
Gives me the fast throughput case. Wow. So apache commons logging is
blameless, what determines whether you get the fast or the slow message
throughput case is actually _slowing down the thread calling the
ackMessage() method_. Slowing down this frequently-called method with
useless String.format() work results in more than double the throughput.
I have no idea why (it's counterintuitive), I suspect I need to get more
visibility into the interactions between threads here.
Thanks to everyone that read this thread, looks like the problem's
somewhere else in my code. (Though if you DO have any suggestions that
could explain what I'm seeing, let me know, even if this is no longer a
logging issue :) )
