On 09/28/2011 11:35 AM, Mircea Markus wrote: > Hi, > > I'm not aware of any convention on using trace vs log.isTraceEnabled() to guard the trace statements. > > if (trace) log.trace("some request related stuff") > vs > if (log.isTraceEnabled()) log.trace("some request related stuff"); > > The former is more efficient, but cannot be managed at runtime. It seems to be the preferred form, so shall we stick with it? If you're using the jboss-logging API, and your log statement does not do any interpolation, then it is just as fast to do any of the following (with no if): log.trace("blah"); log.tracef("the %s happened to %s", foo, bar); log.tracev("the {0} happened to {1}", foo, bar); In the case where trace logging is disabled, these are exactly as efficient as the if (log.isTraceEnabled()) variants. In the case where it is enabled, it is marginally more efficient (though the trace log itself is substantially more expensive of course). Overall I'd avoid the "if" forms unless you're doing complex interpolation: log.trace("Foo " + bar + " baz " + zap); log.tracef("the %s happened to %s", fooMethod().barMethod(), bar); ...both of which incur the expense of the expression resolution even if the log message is ultimately discarded. -- - DML _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

Bringing this thread up again, is it really true to say that if (trace) log.trace("blah") is as cheap as log.trace("blah") ? In the former, with tracing disabled, nothing happens after the condition check. In the latter, you still construct a String "blah", and even if there is no complex interpolation or message construction, the basic String message is still constructed (and starts to take up PermGen space too, as literals are interned [1]). So the case for the if (trace) pattern still stands IMO. Cheers Manik [1] http://docs.oracle.com/javase/1.4.2/docs/api/java/lang/String.html#intern() "All literal strings and string-valued constant expressions are interned." On 28 Sep 2011, at 17:41, David M. Lloyd wrote: > On 09/28/2011 11:35 AM, Mircea Markus wrote: >> Hi, >> >> I'm not aware of any convention on using trace vs log.isTraceEnabled() to guard the trace statements. >> >> if (trace) log.trace("some request related stuff") >> vs >> if (log.isTraceEnabled()) log.trace("some request related stuff"); >> >> The former is more efficient, but cannot be managed at runtime. It seems to be the preferred form, so shall we stick with it? > > If you're using the jboss-logging API, and your log statement does not > do any interpolation, then it is just as fast to do any of the following > (with no if): > > log.trace("blah"); > log.tracef("the %s happened to %s", foo, bar); > log.tracev("the {0} happened to {1}", foo, bar); > > In the case where trace logging is disabled, these are exactly as > efficient as the if (log.isTraceEnabled()) variants. In the case where > it is enabled, it is marginally more efficient (though the trace log > itself is substantially more expensive of course). > > Overall I'd avoid the "if" forms unless you're doing complex interpolation: > > log.trace("Foo " + bar + " baz " + zap); > log.tracef("the %s happened to %s", fooMethod().barMethod(), bar); > > ...both of which incur the expense of the expression resolution even if > the log message is ultimately discarded. > -- > - DML > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev -- Manik Surtani manik(a)jboss.org twitter.com/maniksurtani Lead, Infinispan http://www.infinispan.org _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

If you use a constant, this is not an issue, but what about: String constant="Error message bla bla"; for(int i=1; i <=10; i++) {    log.trace(constant + "-" + i); } ?

On 12/7/11 12:56 PM, Sanne Grinovero wrote: > On 7 December 2011 11:19, Bela Ban&lt;bban(a)redhat.com&gt;  wrote: >> If you use a constant, this is not an issue, but what about: >> >> String constant="Error message bla bla"; >> for(int i=1; i<=10; i++) { >> Â  Â log.trace(constant + "-" + i); >> } >> >> ? > > That should definitely be rewritten as > > String constant="Error message bla bla"; > if (log.isTraceEnabled()) { >     final String constant="Error message bla bla"; >     for(int i=1; i<=10; i++) { >        log.trace(constant + "-" + i); >     } > } No ! My example was meant to show a loop with *many* statements; one of them being a log.trace() ! E.g. for(......) { ... log.trace(); ... }

Better, but this is awkward code IMO. You have to introduce additional variables before tight loops, hmm... I used to do (in JGroups): public static final boolean trace=true; and #1 if(trace && log.isTraceEnabled()) { #2   log.trace(); #3 } If I wanted to create a version without tracing, I compiled JGroups with trace=false. The compiler would then optimize lines 1-3 away. Turns out this was awkward and I removed it in the next release, as I couldn't change the logging at runtime (e.g. via probe.sh). My current philosophy is that I do use the "if(log.isTraceEnabled() log.trace()" pattern, but I use it wisely, and I try not to use this in tight loops, or frequently traversed code paths.

On 7 December 2011 13:38, Erik Salter (esalter) <esalter(a)cisco.com&gt; wrote: > +1 in trace log consistency. We've noticed this in trying to gather > logs in running down bugs. I'd rather NOT have to restart, since most > of the problems I need trace logs for don't show up until a system has > been running for a while. > > Regards, > > Erik thanks Erik, you make a good point. But those logs which are currently using a constant likely need to stay as they are, as they would otherwise slow down significantly, so while I'm voting for consistency I wouldn't like to go in that direction :) We need an agent, I see no other solution. Sanne _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

On 7 December 2011 16:15, Manik Surtani <manik(a)jboss.org&gt; wrote: > Sanne, > > +1 to consistency. I suggest we > repurpose https://issues.jboss.org/browse/ISPN-1429 to a consistent logging > scheme. My preference is for a static final boolean trace = > log.isTraceEnabled(). > > But I do see Erik's concerns about wanting to switch on tracing on the fly. > > - Manik Not sure if you can wait, but as soon as I have some free time (i.e. christmas?) I'll make a POC of a solution taking the best of two worlds. Need a POC before talking further about it :D

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.

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