[infinispan-dev] trace vs log.isTraceEnabled

[Sanne Grinovero]

Hi David,
thank you for weighting in, yes I'm absolutely aware that this hot
spot we noticed is a log4j limitation.
I'm glad to hear that the JBoss LogManager does differently!

Sanne

On 7 December 2011 18:10, David M. Lloyd <david.lloyd at redhat.com> wrote:
> On 12/07/2011 11:10 AM, Sanne Grinovero wrote:
>> On 7 December 2011 17:04, Emmanuel Bernard<emmanuel at hibernate.org>  wrote:
>>>
>>> Just to put some perspectives on things.
>>> Yes the code will waste some cycles checking for trace level but I'd rather have you guys invent a better distro or local / tx / lock algorithm that will speed Infinispan by 10x rather than chasing 1/10 of a %. Just saying :)
>>>
>>> Profilers are fun but they tend to make you lose the big picture.
>>
>> Absolutely, it's dangerous to play with profilers :)
>> But in this case it might be a simple solution, and we're speaking
>> about an overall 4% CPU time overall, and benefitting all projects
>> using JBoss Logger not just Infinispan. So that might be worth it..
>> but as mentioned I don't intend to spend "official" time on it because
>> I do fundamentally agree.
>
> Something you should be aware of is that the main time consumer here
> probably isn't JBoss Logging but log4j, which has a comparatively slow
> level check.  It has to recursively traverse log categories which
> includes a loop and many dereferences.
>
> If you use JBoss LogManager instead (like AS 6 and 7 do) then the level
> check is a single volatile int read which is very cheap; the expense of
> level propagation is placed upon the setLevel() caller which is
> obviously done far less frequently.  When I first replaced log4j with
> JBoss LogManager in AS6, server boot time improved by nearly 10%, to
> give you an idea of how big of a difference this can make.
>
> We do use an enum for levels in JBoss Logging, which *should* be "fast"
> though I don't have up-to-date measurements on that.  For log4j, the
> level enum is switched to translate to the log4j level, which then does
> the aforementioned log4j level check.  For JBoss LogManager, the level
> enum is switched to a LogManager Level.  I could probably speed this up
> a little by going right to the integer value though.
>
> I think the best strategy to follow for computation-intensive code
> (especially when you expect that log4j is likely to be used) would be to
> try to only do the trace level check once per "operation", in the event
> that you are doing a lot of trace logging per operation.  This is
> equivalent to Sanne's example code:
>
>> final boolean trace = log.isTraceEnabled();
>> for(int i=1; i<=10; i++) {
>>  ....//other statements
>>    if (trace) log.trace( ...{preferrabily a JBLogger format}... );
>>    ...//other statements
>> }
>
> This will probably give at least a small benefit even if you are using a
> "fast" log backend, because in this case "trace" is a local variable so
> it's highly likely to be available in a cache line.
>
> Note that it's important to check on a per-operation basis so that the
> user can enable and disable trace logging during runtime and have their
> change take effect.
>
> For non-computationally-intensive code, just relying on the per-method
> level checks whenever it is practical to do so is still what I
> recommend, just for simplicity's sake.
>
> Really the best policy is to look at the code, think about what it is
> doing, and make an informed decision as to the best way to handle
> logging on a case-by-case basis; there really isn't one single best
> answer for all situations.
> --
> - DML
> _______________________________________________
> infinispan-dev mailing list
> infinispan-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/infinispan-dev