Mailing-List: contact user-help@commons.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Commons Users List" <user@commons.apache.org>
Received-SPF: pass (athena.apache.org: domain of sebbaz@gmail.com designates
 72.14.220.156 as permitted sender)
DomainKey-Signature: a=rsa-sha1; c=nofws;
        d=gmail.com; s=gamma;
        h=message-id:date:from:to:subject:in-reply-to:mime-version
         :content-type:content-transfer-encoding:content-disposition
         :references;
        b=PLiYyNitDOwlQZrh+NmhsUh4ldY6S55H7XEFLNxPE/h1Sha2O6z7+62ClXdMDE1Z33
         DbQ1hiP+XpnSk/GJqdYyhwji4/OCCigDRXq56yjM9CCUaz7HwyKXSikpu/YWHR/MrDkK
         usYSQV1suAcUkPjKbGXQYf++U6fpDiYpAlILE=
Message-ID: <25aac9fc0806251707g7a01a84dnc11801c8ee11a818@mail.gmail.com>
Date: Thu, 26 Jun 2008 01:07:11 +0100
From: sebb <sebbaz@gmail.com>
To: "Commons Users List" <user@commons.apache.org>
Subject: Re: Strange performance issues seen with Log.isDebugEnabled()
In-Reply-To: 
 <AA8DDA784AAD744CBC20F1DCFA83E2BA508B72@ATL1VEXC009.usdom003.tco.tc>
MIME-Version: 1.0
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: 7bit
Content-Disposition: inline
References: 
 <AA8DDA784AAD744CBC20F1DCFA83E2BA508B12@ATL1VEXC009.usdom003.tco.tc>
	 <1214429660.17270.31.camel@simon-laptop>
	 <AA8DDA784AAD744CBC20F1DCFA83E2BA508B53@ATL1VEXC009.usdom003.tco.tc>
	 <AA8DDA784AAD744CBC20F1DCFA83E2BA508B72@ATL1VEXC009.usdom003.tco.tc>

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.

Maybe there is some odd thread interaction that is worse when the
enclosing method runs faster.

Or perhaps the format code is touching a volatile variable or using a
lock that allows a shared variable to be published?

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

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