[infinispan-dev] trace vs log.isTraceEnabled

[David M. Lloyd]

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