Understanding slf4j parameterized messages

Question

I am trying to evaluate using slf4j + log4j2 for our application. I read in documents like these about the parameterized messages feature in slf4j: https://www.slf4j.org/faq.html#logging_performance

To understand this feature I tried this code:

int a = 10;
logger.trace("test: " + a++);
logger.error("value of a: " + a);
logger.trace("test {}", a++);
logger.error("value of a " + a);

Logging level is set to ERROR. With that, I was assuming that in the first trace log 'a' will get incremented since it's the old inefficient way of logging. But in the second trace log since I am using parameterized logging and trace level is not enabled, then the 'a++' will also not get evaluated. But looks like it is getting evaluated. I see value as 11 and 12 in the 2 error logs.

Can you please help me understand the slf4j parameterized messages looking at this behavior.

I am using slf4j 1.6.4 and log4j2.7

Answer 1

Look at it this way: will the a variable be incremented in this code?

someObject.someMethod(a++);

The answer is, yes it will.

There's no magic in the Log4j2 or slf4j APIs. In the above example, if you only want to increase the a variable when the message is actually logged you need to do:

if (logger.isTraceEnabled()) {
    logger.trace("test {}", a++);
}

The story is slightly different when you're logging Objects. With the parameterized logging style, the logging library can first check the log level before formatting the message string. If the log level is not enabled, we can avoid calling toString() on the parameter object.

For example:

// always calls toString() on the parameter
logger.trace("a time: " + LocalTime.now());

// only calls toString() if trace is enabled 
logger.trace("a time: {}", LocalTime.now());

---

Actually, I lied a little. The slf4j API may not have any magic, but the Log4j2 API does! :-)

Using the Log4j2 API on Java 8, you can have this code:

logger.trace("test {}", () -> a++);

This is a lambda expression that is only evaluated if trace logging is enabled. So you can write in one line what previously required 3 lines.

This is one of the reasons to consider programming to the Log4j2 API instead of the slf4j API.