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

Question

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?

Solution 1

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.

Solution 2

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 behaviour depends on the logging system behind the facade, it is highly likely that each getLogger entails a lookup in a concurrent or synchronized data structure¹ to look for a pre-existing instance.

If your application makes lots of calls to your MyLoggerWrapper.debug method, this can all add up to a significant performance hit. And in a multi-threaded application, it might be a concurrency bottleneck.

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.
• The code using MyLoggerWrapper will probably be more verbose if you make multiple logger calls. And the verbosity will be in the area where it impacts readability most; i.e. in the methods that do things that need logging.

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

---

^{1 - Apparently it is a Hashtable in Logback and Log4j, and that means that the potential for a concurrency bottleneck definitely exists. Note that this is not a criticism of those logging frameworks. Rather, the getLogger method was not designed/optimized to be used this way.}

Solution 3

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.

Solution 4

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.

Solution 5

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.

View more solutions

Comments

[Benoit Courtine]

Another point: your logging lines become ugly with your boss method, since the correct logging syntax is "MyLoggerWrapper.debug(MyClass.class, "blah blah blah");"

[danirod]

Thanks Benoit, that's what I intended to show but in the rush to post I made a typo. It's just an example but we'd use something like: MyLoggerWrapper.debug(this.getClass(), "blah")

[Guillaume]

but with static import, you have a nice debug(...) :)

[yegor256]

take a look at Logger, which is a ready-made wrapper, you don't need to create your own

[fayndee]

2015 version of the answer: please free your mind with lombok @slf4j.

[Dave Jarvis]

Logging is a cross-cutting concern. Avoid boilerplate code by moving the code into an aspect, instead of littering logging statements throughout the code base.

[matt b]

should point out that including the line number in the logging output is tremendously slow

[danirod]

Ok, he is more like the team lead/lead programmer ;-) The guard clause is already taken care of by using parameterized messages -as explained on your link and other docs I've read- we just implement the required methods in the wrapper as needed. Agree with ugliness of the wrapper log() calls but I'm yet to be convinced by any of the answers here that this is worse than logger instantiation on every class which is a pain in the neck and kinda ugly too.

[matt b]

I'm not sure I agree that one line of code per class to do final static Logger logger = LoggerFactory.getLogger(MyClass.class) is all that ugly. Using your IDE of choice, it's easy to come up with a simple template/macro so that you can add this snippet to the file in just a few keystrokes. However beauty is in the eye of the beholder...

[Noremac]

Also should point out that the class name is passed in as well to identify the logger to be used (in the above example). Thus, your first point is solved.

[Péter Török]

@Noremac, fair enough, the class name will be logged correctly. However, I strongly suspect that the line number will still be wrong.

[Noremac]

I'm with you on that one. You could always pass in the line number, the method name, the stack trace, the environment, your horoscope, the weather, etc. :)

[Hilikus]

in eclipse this is the template i created On context: Java Type Members private static final Logger log = LoggerFactory.getLogger(${enclosing_type}.class); ${:import(org.slf4j.Logger,org.slf4j.LoggerFactory)}${cursor‌​}

[Ali Motevallian]

This is not a bad idea, but if you are using Java 8 with it awesome Closures facility, why do we have to have those guard clauses? In your code every time the log is called the guard if statements and switch statements are going to be called. However, with closures (or even polymorphism in general) you can generate a new logger class in the application startup which has empty methods for log levels under the configure level (via the properties file).

[Steve K]

You can indeed do that. But calls to that method will STILL concatenate all the string arguments if the guard clauses aren't there.... which is the whole point of using object varargs instead of passing in a built-up string message. You could get around that but honestly, calling isErrorEnabled() isn't noticeably less efficient than calling an empty error() method... and the point of the interface is that you never again have to worry about the guard statements. You've written them once and you're rid of worrying about them forever.

[Selwyn]

@Steve K I like this solution I have something similar is there a performance hit for constantly calling getLogger(this.getClass())?