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?

Preceptive

Look at slf4j, which I think implements this approach – Dishevel

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.

Dishevel

Just for additional information (maybe this has changed in the meantime): The plain log4j API supports this as well. The same code as you already wrote can be used. – Uncle

Answer 2

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.

Yhvh

"is considered as a bad practice" ?? – Contradictory

Please elaborate on why that's bad practice. Also, a followup question (and I think the OP's actual question), what is the string formatter provided by log4j? Does one exist? – Goodspeed

This went a bit off-topic with what was asked but it is exactly what I was searching for (why the log4j parameters are better than using String.format). Thanks. Extra resource: slf4j.org/faq.html#logging_performance – V1

I guess calling varargs function still implicitly allocates an Array. In this case, surrounding the log line with log.isDebugEnabled() should reduce the overhead even further. – Insignia

Answer 3

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

Goodspeed

Answer 4

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

Inflexion

Besides my personal preference, it is recommended best practice to use String.format(), usually because it is easier to read and modify: #925923 – Preceptive

+ will allocate as many Strings as there are + sings minus 1. format() will only allocate one String and one Array. – Insignia

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);

Insignia

Many loggers (logback, log4j2, etc) implement non variadic versions of the parametric logging functions up to 3 arguments to prevent this array allocation overhead for simple use cases, some implement it up to 9. – Wharton