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 13:04:21 GMT
simon.kitching@chello.at wrote:
> Jörg Schaible schrieb:
>> Jean-Philippe Daigle wrote:
>> [snip]
>>  
>>> 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 :) )
>>>     
>>
>> Can you stip it down to detect the real call that is responsible for 
>> the speed-up?
>>
>> 1/ _dbg_str = ack_r.toString();
>>
>>  or
>> 2/ _dbg_str = String.valueOf(id);
>>
>>  or even
>>
>> 3/ ack_r.toString();
>>
>> alone?
>>
>> What's implemented with ack_r.toString() ? What kind of 
>> implementation is ack_r ? A proxy ?
>>   
>
> Yes, good point. I missed that ack_r.toString will be triggered.
>
> I wonder what happens if you replace the String.format call with just 
> this:
>  synchronized(this) {
>    ++dummy;
>  }
> where dummy is a public int member, just so the synchronized block 
> isn't optimised away. The synchronization operation will have a number 
> of side-effects, including entering the OS kernel, flushing CPU caches 
> and allowing the OS scheduler to run.
>
> Regards,
> Simon
>
Thanks, good idea, I'll give that a shot today and see if it gives me 
more info. I'll be interested in seeing how forcing anything to happen 
in a synchronized block will affect the timing, but as some have 
mentioned, this is probably going to end up an OS/VM specific issue so 
it's going to be very hard to tune for.

To clarify, since ack_r is an instance of a simple java enum, toString() 
just returns the enum's name, which definitely doesn't need any 
synchronization and is trivially cheap.

To clarify another point that I've seen made,
> simon>> I wasn't too surprised to hear that your custom Log 
> implementation was causing a difference when it was doing IO (writing 
> the message out). Any IO operation requires a call into the operating 
> system kernel which can then trigger a context switch.
>
> But the fact that you see a difference just when calling String.format 
> is rather surprising. [...]
The point of the custom logger was to have no cost of its own, so it 
doesn't do any I/O of course (except when first instantiated, to prove 
it's really in use), its logging methods are empty. The speed 
differences were traced entirely to the String.format().


Jean-Philippe Daigle


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


Mime
View raw message