Re: [infinispan-dev] trace vs log.isTraceEnabled

On 12/07/2011 11:10 AM, Sanne Grinovero wrote: > On 7 December 2011 17:04, Emmanuel Bernard&lt;emmanuel(a)hibernate.org&gt;  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(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev