[infinispan-dev] trace vs log.isTraceEnabled

[Erik Salter (esalter)]

+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

-----Original Message-----
From: infinispan-dev-bounces at lists.jboss.org
[mailto:infinispan-dev-bounces at lists.jboss.org] On Behalf Of Sanne
Grinovero
Sent: Wednesday, December 07, 2011 6:54 AM
To: infinispan -Dev List
Subject: Re: [infinispan-dev] trace vs log.isTraceEnabled

I'd expect string interning to happen anyway, and it's part of the
class definition so it shouldn't affect runtime performance.

Still I agree with your conclusion as checking for the current log
level is a significant cost, so if you can check only once and keep
the result of isTraceEnabled in a trace boolean that's the better
approach.

I've spent some time profiling these details; there was one specific
method in Hibernate Core which has something along "
log.trace("entering this method");" , since this method was invoked
very frequently as a general purpose helper, just removing the trace
statement improved overall CPU performance of 2,5% as it was spending
a significant amount of time in log4j to check if trace was enabled or
not (and it wasn't).

I've also noticed that the check for log level will happen *twice* if
the tracing level is not disabled, as JBoss Logger checks first, then
if it returns true it will proceed formatting the message and then
invoke the delegated logger framework at the specified log level,
which will check for log level again.
This is not to be worried much about of course as if you have trace
level enabled, performance will suck anyway; it might be worth
polishing in future versions of JBoss Logger especially for higher
logging levels which are likely to be not disabled [info...fatal] but
I'm not sure it's worth the added complexity, and these methods are
relatively rare so I wouldn't expect a performance improvement of the
overall platform.

One proposal I have for Infinispan: we sometimes cache the result in a
static final boolean "trace", sometimes we don't at all, in some other
cases it's cached as a final field at the instance level, even for
long lived services; this makes log reconfiguration at runtime rather
unpredictable.
I'd rather see some consistency on this.

Shall we make all "trace" level logging a static constant? That would
be of course a limitation in the sense that people won't be able to
reconfigure the logger without restarting, but it's certainly better
than removing log methods because they slow down or apply this
strategy in a non-consistent way.
As a user, I would consider it acceptable as long as it's properly
documented, and am not suggesting to apply it to other log levels.

Sanne
_______________________________________________
infinispan-dev mailing list
infinispan-dev at lists.jboss.org
https://lists.jboss.org/mailman/listinfo/infinispan-dev