Log4j Implicit String Formatting

Question

I am using log4j v1.2.14 for logging in my project and I am also using Java 7 String.format() to put variables in my output. Currently I am writing

LOGGER.info(String.format("Your var is [%s] and you are [%s]", myVar, myVar1));

Is this really the best way to output strings? I feel that log4j should have this implemented implicitly as below:

LOGGER.info("Your var is [%s] and you are [%s]", myVar, myVar1);

Have I missed something? Further, are there any Java logging frameworks that support this?

Answer 1

slf4j's api provides "parameterized logging", which allows you to do exactly that, although with a slightly different syntax. The example there is:

logger.debug("Value {} was inserted between {} and {}.", newVal, below, above);

For an implementation, you can use Logback which implements slf4j natively, or the slf4j bindings to connect with log4j or other loggers. The User Manual explains that, along with a short example.

Answer 2

Btw, In this scenario there is not much difference between using + to add your variables to the string and String.format - unless you really want to reuse the "Your var is..." in all your logs.

slf4j lets you log as

log.info("Your var is {} and you are {}", myVar, myVar1);

Note the use of {} instead of print formatters. Also this requires Java >= 1.5

Answer 3

Using String.format, +, or a string formatter other than the one provided by your logging system (log4j for example) is considered as a bad practice.

Usually, in the code there are lots of low level logs (debug, info) you don't want to see in production. If you use for example String.format to format the string to log, then you will allocate on the heap and format a new String, which can be very long and consume resources, even if at the end nothing will be logged (for example if the log4j min level is set to warning or error).

By using the logger formatter system (like the one from log4j), you allow your logger to avoid the generation of the formatted string if it doesn't need to be logged.

This may make a great difference in some cases.

Answer 4

Log4j supports internal formatting. I haven't found it documented anywhere, but I saw an example of it here:

https://logging.apache.org/log4j/2.x/manual/markers.html

I tried it out and it works! I'm on log4j 2.11.2.

int i = 42;
String str1 = "the answer";
String str2 = "life, the universe, and everything";
console.info("{} is {} to {}", i, str1, str2);

Looking at the javadoc for Logger, I'd say it was introduced in Lo4j 2, and supports up to 10 parameters.

https://logging.apache.org/log4j/2.x/log4j-api/apidocs/org/apache/logging/log4j/Logger.html

Answer 5

I upvoted the "use logger.debug(format, varargs)" approach first, because it doesn't allocate extra String when it's not needed.

But then it occurred to me that logger.debug(String format, Object... varargs) still allocates an Array for the varargs.

Tried this on https://godbolt.org/noscript/java

class VarargTest {
    static boolean debugging = false;
    static void debug(String format, Object... args) {
       if (debugging) {
           System.out.println(String.format(format, args));
       }
    }

    static void logVarargs(int n) {
        debug("debug message {}", n);
    }

    static void logIf(int n) {
        if (VarargTest.debugging) {
            debug("debug message 2 " + n);
        }
    }
}

and indeed, the resulting debug() call allocates an Array.

So the fastest code should be

if (logger.isDebugEnabled()) {
    logger.debug("format {}", arg);
}

If it's not super performance critical, a more readable and reasonably fast code would be simply

    logger.debug("format {}", arg);