Why calling LoggerFactory.getLogger(…) every time

问题:

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?

回答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.

回答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.

回答3:

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.}

回答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.

回答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.

回答6:

Here's one possibility for making it easy to do logging in Java 8 - define an interface to do it for you. For instance:

package logtesting;

import java.util.Arrays;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public interface Loggable { 
    enum LogLevel {
        TRACE, DEBUG, INFO, WARN, ERROR
    }

    LogLevel TRACE = LogLevel.TRACE;
    LogLevel DEBUG = LogLevel.DEBUG;
    LogLevel INFO = LogLevel.INFO;
    LogLevel WARN = LogLevel.WARN;
    LogLevel ERROR = LogLevel.ERROR;

    default void log(Object...args){
        log(DEBUG, args);
    }

    default void log(final LogLevel level, final Object...args){
        Logger logger = LoggerFactory.getLogger(this.getClass());
        switch(level){
        case ERROR:
            if (logger.isErrorEnabled()){
                logger.error(concat(args));
            }
            break;
        case WARN:
            if (logger.isWarnEnabled()){
                logger.warn(concat(args));
            }
            break;          
        case INFO:
            if (logger.isInfoEnabled()){
                logger.info(concat(args));
            }
        case TRACE:
            if (logger.isTraceEnabled()){
                logger.trace(concat(args));
            }
            break;
        default:
            if (logger.isDebugEnabled()){
                logger.debug(concat(args));
            }
            break;
        }
    }

    default String concat(final Object...args){ 
        return Arrays.stream(args).map(o->o.toString()).collect(Collectors.joining());
    }
}

Then all you ever have to do is make sure your classes declare implement Logged, and from any of them, you can do things like:

log(INFO, "This is the first part ","of my string ","and this ","is the last");

The log() function takes care of concatenating your strings, but only after it tests for enabled. It logs to debug by default, and if you want to log to debug, you can omit the LogLevel argument. This is a very simple example. You could do any number of things to improve upon this, such as implementing the individual methods, ie error(), trace(), warn(), etc. You could also simply implement "logger" as a function that returns a logger:

public interface Loggable {
    default Logger logger(){
        return LoggerFactory.getLogger(this.getClass());
    }
}

And then it becomes pretty trivial to use your logger:

logger().debug("This is my message");

You could even make it fully functional by generating delegate methods for all the Logger methods, so that every implementing class is an instance of Logger.

package logtesting;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;

public interface Loggable extends Logger {
    default Logger logger(){
        return LoggerFactory.getLogger(this.getClass());
    }

    default String getName() {
        return logger().getName();
    }

    default boolean isTraceEnabled() {
        return logger().isTraceEnabled();
    }

    default void trace(String msg) {
        logger().trace(msg);
    }

    default void trace(String format, Object arg) {
        logger().trace(format, arg);
    }

    default void trace(String format, Object arg1, Object arg2) {
        logger().trace(format, arg1, arg2);
    }

    default void trace(String format, Object... arguments) {
        logger().trace(format, arguments);
    }

    default void trace(String msg, Throwable t) {
        logger().trace(msg, t);
    }

    default boolean isTraceEnabled(Marker marker) {
        return logger().isTraceEnabled(marker);
    }

    default void trace(Marker marker, String msg) {
        logger().trace(marker, msg);
    }

    default void trace(Marker marker, String format, Object arg) {
        logger().trace(marker, format, arg);
    }

    default void trace(Marker marker, String format, Object arg1, Object arg2) {
        logger().trace(marker, format, arg1, arg2);
    }

    default void trace(Marker marker, String format, Object... argArray) {
        logger().trace(marker, format, argArray);
    }

    default void trace(Marker marker, String msg, Throwable t) {
        logger().trace(marker, msg, t);
    }

    default boolean isDebugEnabled() {
        return logger().isDebugEnabled();
    }

    default void debug(String msg) {
        logger().debug(msg);
    }

    default void debug(String format, Object arg) {
        logger().debug(format, arg);
    }

    default void debug(String format, Object arg1, Object arg2) {
        logger().debug(format, arg1, arg2);
    }

    default void debug(String format, Object... arguments) {
        logger().debug(format, arguments);
    }

    default void debug(String msg, Throwable t) {
        logger().debug(msg, t);
    }

    default boolean isDebugEnabled(Marker marker) {
        return logger().isDebugEnabled(marker);
    }

    default void debug(Marker marker, String msg) {
        logger().debug(marker, msg);
    }

    default void debug(Marker marker, String format, Object arg) {
        logger().debug(marker, format, arg);
    }

    default void debug(Marker marker, String format, Object arg1, Object arg2) {
        logger().debug(marker, format, arg1, arg2);
    }

    default void debug(Marker marker, String format, Object... arguments) {
        logger().debug(marker, format, arguments);
    }

    default void debug(Marker marker, String msg, Throwable t) {
        logger().debug(marker, msg, t);
    }

    default boolean isInfoEnabled() {
        return logger().isInfoEnabled();
    }

    default void info(String msg) {
        logger().info(msg);
    }

    default void info(String format, Object arg) {
        logger().info(format, arg);
    }

    default void info(String format, Object arg1, Object arg2) {
        logger().info(format, arg1, arg2);
    }

    default void info(String format, Object... arguments) {
        logger().info(format, arguments);
    }

    default void info(String msg, Throwable t) {
        logger().info(msg, t);
    }

    default boolean isInfoEnabled(Marker marker) {
        return logger().isInfoEnabled(marker);
    }

    default void info(Marker marker, String msg) {
        logger().info(marker, msg);
    }

    default void info(Marker marker, String format, Object arg) {
        logger().info(marker, format, arg);
    }

    default void info(Marker marker, String format, Object arg1, Object arg2) {
        logger().info(marker, format, arg1, arg2);
    }

    default void info(Marker marker, String format, Object... arguments) {
        logger().info(marker, format, arguments);
    }

    default void info(Marker marker, String msg, Throwable t) {
        logger().info(marker, msg, t);
    }

    default boolean isWarnEnabled() {
        return logger().isWarnEnabled();
    }

    default void warn(String msg) {
        logger().warn(msg);
    }

    default void warn(String format, Object arg) {
        logger().warn(format, arg);
    }

    default void warn(String format, Object... arguments) {
        logger().warn(format, arguments);
    }

    default void warn(String format, Object arg1, Object arg2) {
        logger().warn(format, arg1, arg2);
    }

    default void warn(String msg, Throwable t) {
        logger().warn(msg, t);
    }

    default boolean isWarnEnabled(Marker marker) {
        return logger().isWarnEnabled(marker);
    }

    default void warn(Marker marker, String msg) {
        logger().warn(marker, msg);
    }

    default void warn(Marker marker, String format, Object arg) {
        logger().warn(marker, format, arg);
    }

    default void warn(Marker marker, String format, Object arg1, Object arg2) {
        logger().warn(marker, format, arg1, arg2);
    }

    default void warn(Marker marker, String format, Object... arguments) {
        logger().warn(marker, format, arguments);
    }

    default void warn(Marker marker, String msg, Throwable t) {
        logger().warn(marker, msg, t);
    }

    default boolean isErrorEnabled() {
        return logger().isErrorEnabled();
    }

    default void error(String msg) {
        logger().error(msg);
    }

    default void error(String format, Object arg) {
        logger().error(format, arg);
    }

    default void error(String format, Object arg1, Object arg2) {
        logger().error(format, arg1, arg2);
    }

    default void error(String format, Object... arguments) {
        logger().error(format, arguments);
    }

    default void error(String msg, Throwable t) {
        logger().error(msg, t);
    }

    default boolean isErrorEnabled(Marker marker) {
        return logger().isErrorEnabled(marker);
    }

    default void error(Marker marker, String msg) {
        logger().error(marker, msg);
    }

    default void error(Marker marker, String format, Object arg) {
        logger().error(marker, format, arg);
    }

    default void error(Marker marker, String format, Object arg1, Object arg2) {
        logger().error(marker, format, arg1, arg2);
    }

    default void error(Marker marker, String format, Object... arguments) {
        logger().error(marker, format, arguments);
    }

    default void error(Marker marker, String msg, Throwable t) {
        logger().error(marker, msg, t);
    }
}

Of course, as mentioned before, this means that every time you log, you'll have to go through the Logger lookup process within your LoggerFactory - unless you override the logger() method... in which case you might as well do it the "recommended" way.

回答7:

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.

回答8:

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

回答9:

As stated here by the SLF4J team you can use MethodLookup() introduced in JDK 1.7.

final static Logger logger = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());

This way you can refer to the class without the need of using the keyword "this".

回答10:

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.

回答11:

There are two reasons why your boss' approach does not achieve what he thinks.

The smaller reason is that the overhead of adding a static logger is negligible. After all, the logger setup is part of this pretty lengthy sequence:

• Locate the class, i.e. walk all the .jars and directories. Java code. Pretty big overhead due to filesystem calls. May create helper objects, e.g. with File.
• Load the bytecode, i.e. copy it into a data structure inside the JVM. Native code.
• Validate the bytecode. Native code.
• Link the bytecode, i.e. iterate through all the class names in the bytecode and replace them with pointers to the referred-to class. Native code.
• Run static initializers. Triggered from native code, the initializers are Java code of course. The Logger gets created here.
• After a while, maybe JIT-compile the class. Native code. Huge overhead (compared to the other operations anyway).

Also, your boss saves nothing.
The first call to LoggerFactor.getLogger will create the logger and place it in a global name-to-Logger HashMap. This will happen even for the isXxxEnabled calls, because to do these you need to construct the Logger object first...
The Class object will carry an extra pointer for the static variable. This is offset by the overhead of passing the clazz parameter - an additional instruction and an additional pointer-sized reference in the bytecode, so you lose at least one byte in class size already.

The code is also going through an extra indirection, LoggerFactory.getLogger(Class) uses Class#getName and delegates to LoggerFactory.getLogger(String).

Now if your boss is not after performance but after the ability to simply copy over the static declaration, he can use a function that inspects the call stack and retrieves the class name. The function should be annotated @CallerSensitive, and it's still something that needs to be tested whenever a new JVM is used - not nice if you do not control the JVM that the user is running the code on.

The least problematic approach would be to have an IDE that checks the logger instantiation. This probably means finding or writing a plugin.

回答12:

I may have missed it in one of the earlier comments, but i didn't see a mention that the logger is static, the call to LoggerFactory is made ONCE (per instantiation of the class) - so the initial concern about multiple calls to create the logger is just wrong.

The other comments regarding all the issues with adding wrapping classes are very important as well.