Why calling LoggerFactory.getLogger(...) every time is not recommended?

Question

Hi all,

I've read tons of posts and documents (on this site and elsewhere) pointing that the recommended pattern for SFL4J logging is:

public class MyClass {
    final static Logger logger = LoggerFactory.getLogger(MyClass.class);

    public void myMethod() {
        //do some stuff
        logger.debug("blah blah blah");
    }
}

My boss prefers we just use a wrapper to intercept log calls and avoid boiler plate code for declaring the logger on every class:

public class MyLoggerWrapper {
    public static void debug(Class clazz, String msg){
        LoggerFactory.getLogger(clazz).debug(msg));
    }
}

and simply using it like this:

public class MyClass {

    public void myMethod() {
        //do some stuff
        MyLoggerWrapper.debug(this.getClass(), "blah blah blah");
    }
}

I presume instantiating a logger every time we log is somewhat expensive but I've been unable to find any document backing that assumption. Besides he says surely the framework (LogBack or Log4J we're still deciding) will "cache" the loggers and also that in any case the servers are running very much below their capacity so it is not an issue.

Any help pointing out potential problems with this approach?

Answer 1

No. Not other than it messes up the call stack. That disrupts the methods that allow you to see the method name and class of the code doing the log.

You may consider having a look at the Jetty web container which contains their own abstraction which builds on top of slf4j. Very nice.

Answer 2

The logger objects are surely reused, so no extra instantation is going to happen either way. The bigger problem I see is that your file/line number info will be useless, since the logger will always faithfully log that each message was issued from class LoggerWrapper, line 12 :-(

OTOH SLF4J is already a wrapper facade to hide the specific logging framework used, allowing you to freely change between different logging implementations. Therefore I see absolutely no point in hiding that behind yet another wrapper.

Answer 3

Here is one obvious problem with this approach: the String messages will be constructed on each call to debug(), there is no obvious way to use a guard clause with your wrapper.

The standard idiom with log4j/commons-logging/slf4j is to use a guard clause such as:

if (log.isDebugEnabled()) log.debug("blah blah blah");

With the purpose being that if the DEBUG level is not enabled for the logger, the compiler can avoid concatenating together any longer strings you may send it:

if (log.isDebugEnabled()) log.debug("the result of method foo is " + bar 
     + ", and the length is " + blah.length());

See "What is the fastest way of (not) logging?" in the SLF4J or log4j FAQ.

I would recommend against the "wrapper" your boss suggests. A library like slf4j or commons-logging is already a facade around the actual underlying logging implementation used. In addition, each invocation of the logger becomes much lengthier - compare the above with

 MyLoggerWrapper.debug(Foo.class, "some message");

This is the type of trivial and unimportant "wrapping" and obfuscation that serves no real purpose other than adding layers of indirection and ugly-fying your code. I think your boss can find more important issues to obsess over.

Answer 4

Repeated calls to LoggerFactory.getLogger(clazz) should not result in a new Logger object each time. But that does not mean that the calls are free. While the actual behavior depends on the logging system behind the facade, it is highly likely that each getLogger entails a hash table lookup to look for a pre-existing. If your application makes lots of calls to your MyLoggerWrapper.debug method, this can all add up to a significant performance hit.

Other issues mentioned by other answers are also important:

• Your application can no longer use logger.isDebugEnabled() to minimize the overheads when debugging is disabled.
• The MyLoggerWrapper class obscures the class names and line numbers of your application's debug calls.

Finally, this is just "not the way that it is done".

But ... this isn't probably worth getting into a raging argument with your boss / lead programmer.

Answer 5

I just have to say that the recommended pattern is easiest to read and implement. I see no reason for straying from it. Especially no benefit.

However, my main point is about the guards mentioned previously. I would not recommend explicitly guarding your logs as this is already done internally by log4j and is a duplication of effort.

Download the source for log4j and have a look at the Logger and Category classes to see for yourself.

Answer 6

To add to the reasons already mentioned, your boss's suggestion is bad because:

• It forces you to repeatedly type something that has nothing to with logging, every time you want to log something: this.getClass()
• Creates a non-uniform interface between static and non-static contexts (because there is no this in a static context)
• The additional unnecessary parameters creates room for error, makes it possible for statements in the same class to go to different loggers (think careless copy pasting)
• While it saves 74 characters of logger declaration, it adds 27 extra characters to each logging call. This means if a class uses the logger more than 2 times, you're increasing boilerplate code in terms of character count.

Answer 7

When using something like: MyLoggerWrapper.debug(this.getClass(), "blah") You will get wrong classnames when using AOP frameworks or code-injection tools. The classnames are not like the origin, but a generated classname. And another drawback of using the wrapper: For every log statement, you must include additional code "MyClass.class".

The 'caching' of the loggers depends on the used frameworks. But even when it does, it must still look up the desired logger for every log statement you make. So having 3 statements in a method, it must look it up 3 times. Using it as a static variable it must only look it up once!

And said before: you lose the ability to use if( log.isXXXEnabled() ){} for a set of statements.

What has your boss against the "community default accepted and recommended way"? Introducing the wrapper is not adding more efficiency. Instead you must use the classname for every log statement. After a while you want to "improve" that, so you add another variable, or another wrapper making it more difficult for yourself.