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 Re: Strange performance issues seen with Log.isDebugEnabled()
Date Thu, 26 Jun 2008 01:33:41 GMT
sebb wrote:
> On 26/06/2008, Jean-Philippe Daigle
> <Jean-Philippe.Daigle@solacesystems.com> wrote:
>   
>>> -----Original Message-----
>>>       
>>  > From: Jean-Philippe Daigle
>>  [mailto:Jean-Philippe.Daigle@SolaceSystems.com]
>>  > 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:simon.kitching@chello.at]
>>  > > 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 :) )
>>
>>     
>
> What happens if you simplify the format to remove the ack_r parameter?
> Is it possible that the toString() method on that parameter is having an effect?
>
> Or perhaps try replacing the format call with a short sleep.
>
>   
Removing ack_r wouldn't change the timing IMHO, it's just an enum.

I think replacing it with a sleep wouldn't tell me much for testing - 
this method gets called tens of thousands of times a second, and the 
shortest sleep granularity is something like 16ms. Yielding for 16ms at 
a time would be pretty much like not having this thread run at all, as 
far as the others are concerned.
> Maybe there is some odd thread interaction that is worse when the
> enclosing method runs faster.
>   
Bingo - The "odd thread interaction" conclusion is correct, I think. 
This particular method running faster results in a catastrophe for the 
system as a whole, for a reason I currently don't understand but will 
have to figure out.
> Or perhaps the format code is touching a volatile variable or using a
> lock that allows a shared variable to be published?
>   
Yeah, touching a volatile would force synchronization of the thread's 
memory AFAIK, and could explain some timing weirdness, but since the 
arguments are a long and an enum, I don't think this can be happening.



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


Mime
View raw message