Better strategy for instantiation of Logger instances (static causes problems)

[raycardillo]

I am about to check in a small bit of code that helps provide better TRACE details that are critical to diagnosing client Token validation errors because the information is lost in the various layers otherwise.  However, I wanted to be diligent about making a good contribution, so I was reading through some of the contribution guidelines.

I was surprised to discover that the JBoss process guidelines specifically advise using a private static Logger declaration because that is not the best strategy for Logger instantiation.  I admit that it is not common knowledge for some reason.  I myself was not aware of this until only recently when I started searching for advice on the topic after having a discussion with a colleague about how often static declarations are abused in the name of performance, but can actually have a negative performance impact in multi-threaded code when synchronized upon, etc.

After that discussion, it struck me that most logging code I have seen follows this exact pattern, and probably should not be for those exact reasons.  So I went searching for articles that might be relevant to the conversation in the context of Logger, and found that there are even more concerns that that.  Apparently, it causes so many problems, that some logging libraries use special strategies (ThreadLocal variables, etc) in attempt to workaround this very common style of Logger declaration.

A much better strategy is simply to use a private transient Logger for most cases and use a local variable declaration for any static methods that require logging.  Of course, there are more advanced strategies as well, but that simple strategy is the most effective.  For those of you who are interested in the details directly from the source, please refer to the following reference:  http://wiki.apache.org/commons/Logging/StaticLog

With all that said, I have two questions:

1. How do we get this information to the right people so someone can update the JBoss process guidelines to use this better strategy, or at least allow alternate strategies, and provide the aforementioned reference materials to consult for more details.
   
2. Are any of the key contributors going to have a major problem if I commit a change that uses this strategy for obtaining a Logger?  In this particular case, I'm adding it to a class that does not already have it, so I'm not too worried about stepping on someones work.
   
3. Does anyone agree that there should be an effort to change this throughout?  After reading the reference I provided, I believe there should be an effort to make this change systematically because portions of PicketLink and PicketBox are intended to be used in other environments (not only JBoss) so the problems documented in that reference can (and most likely will) occur if not addressed.
   

[anil.saldhana]

Ray,

  thanks for the post.  I have broached this with the logging gods at JBoss.  Let me see what they say.

I will certainly provide a reply.

[jason.greene]

After that discussion, it struck me that most logging code I have seen follows this exact pattern, and probably should not be for those exact reasons.  So I went searching for articles that might be relevant to the conversation in the context of Logger, and found that there are even more concerns that that.  Apparently, it causes so many problems, that some logging libraries use special strategies (ThreadLocal variables, etc) in attempt to workaround this very common style of Logger declaration.

Whether or not logging is static per class or on an instance says nothing about it's concurrency usage, as an instance can have just as much concurrent activity as a static var  (e.g. servlet). A logging framework could choose not to support concurrent access, but that would be silly because it already has to coordinate concurrent access the underlying stream.

after having a discussion with a colleague about how often static declarations are abused in the name of performance,

There is definitely a very REAL performance overhead in doing this, namely a memory one, and it certainly has had an impact on JBoss in the past.

[anil.saldhana]

The main performance bottlenecks we have seen with logging is when log.debug or log.trace have not been enclosed within a logger.isTraceEnabled() or logger.isDebugEnabled() calls.

[jason.greene]

ANIL SALDHANA wrote:

The main performance bottlenecks we have seen with logging is when log.debug or log.trace have not been enclosed within a logger.isTraceEnabled() or logger.isDebugEnabled() calls.

The main perf issue I was referring to is having several million logger instances hanging around taking up massive amounts of space

The apache article jumps to a strange general conclusion based odd corner cases. It's basically a "user might shoot themselves in the foot, so we must prevent it" argument. It also presupposes that everyone wants per-application logging.

You don't need black and white rules to decide where to put a logger instance, just a little common sense. If you want a framework to support the use of a logger other than the environment one, then design for it.

[raycardillo]

Unless I'm missing something, it looks like this is taking a performance tangent, but the Apache article is mostly about how the expected functionality is different when the same code is running in typical application containers (as opposed to typical application execution environments).  They even provide a brief analysis of how those problems effect various logger implementations.  So after a careful read of their article, I don't think they are jumping to any conclusions, they are actually warning about some problems that are not so obvious at first glance.

So if we set aside the performance issues (which they didn't really address very much at all - that was just my intro into this topic)... are you saying that the information they have provided is incorrect in any way?  Again, the main point they are making is that the various logger implementations will behave differently on different application containers, and they provide a fairly explicit analysis that demonstrates the case.  So that being said, I want to understand what points are being challenged so I can form my own opinion from there.

[raycardillo]

Before I get pounced on, after another read, I do see where the  performance tangent comes into play if you focus on one particular quote (see below), but it's just one comment in a much bigger discussion.

Note that this discussion hasn't talked about "Thread Context ClassLoaders" or other technical points. The problem is not with the details but with the general concept: when the Log object is shared among multiple applications it isn't possible to have per-application configuration and reasonable performance.

The real root cause of this problem is that SHARED data (static members on a class) is being shared across supposedly independent "applications". If no classes are "shared" between applications then the problem does not exist. However it appears that (to my personal frustration) container vendors continue to encourage the use of shared classes, and application developers continue to use it.

The alternative solution is: avoid the use of "static" references to Log objects in any code that might be deployed into a shared classpath.

[dmlloyd]

I'd say that the cited article does not apply anymore under JBoss AS 6 (and AS 7, and probably all subsequent versions).  The only significant negative to static logging comes into play when the logger is defined in a JAR which is shared between two applications or modules which have distinct logging configurations.  The article implies that most of the time you'll have a distinct classloader for each module, however that is not always the case.  Most of the frameworks you use in an application server are shared on a class level, not just a file level (think EJB/JPA, JCA, Servlet, etc.).  This becomes even more true as we move towards Java 7 modules, OSGi, JBoss AS 7 modules, and presumably future EE specs, as well as other similar module architectures which are more modern than the classic flat classpath from earlier Java days, where you'll start to see more classes being shared.

So in these cases having an instance logger does not help unless the framework can accept outside loggers, which they usually cannot.  On the downside, instance loggers can and do destroy performance and possibly even drive up memory overhead depending on the logging API in use.

In AS 6 and AS7, distinct module logging configuration works by identifying the initiating class loader of the class which created the logger, and uses that class loader as the basis for identifying the log context to use and thus the logger configuration.  This does not cascade out to other frameworks though, for the reason I explained above; instance loggers do not fix this either.

So my recommendation remains to always use static loggers unless you have an excellent reason not to.