Built-in string formatting vs string concatenation as logging parameter

Question

I'm using SonarLint that shows me an issue in the following line.

LOGGER.debug("Comparing objects: " + object1 + " and " + object2);

Side-note: The method that contains this line might get called quite often.

The description for this issue is

"Preconditions" and logging arguments should not require evaluation (squid:S2629)

Passing message arguments that require further evaluation into a Guava com.google.common.base.Preconditions check can result in a performance penalty. That's because whether or not they're needed, each argument must be resolved before the method is actually called.

Similarly, passing concatenated strings into a logging method can also incur a needless performance hit because the concatenation will be performed every time the method is called, whether or not the log level is low enough to show the message.

Instead, you should structure your code to pass static or pre-computed values into Preconditions conditions check and logging calls.

Specifically, the built-in string formatting should be used instead of string concatenation, and if the message is the result of a method call, then Preconditions should be skipped altoghether, and the relevant exception should be conditionally thrown instead.

Noncompliant Code Example

logger.log(Level.DEBUG, "Something went wrong: " + message);  // Noncompliant; string concatenation performed even when log level too high to show DEBUG messages

LOG.error("Unable to open file " + csvPath, e);  // Noncompliant

Preconditions.checkState(a > 0, "Arg must be positive, but got " + a); // Noncompliant. String concatenation performed even when a > 0

Preconditions.checkState(condition, formatMessage());  //Noncompliant. formatMessage() invoked regardless of condition

Preconditions.checkState(condition, "message: %s", formatMessage()); // Noncompliant

Compliant Solution

logger.log(Level.SEVERE, "Something went wrong: %s", message);  // String formatting only applied if needed

logger.log(Level.SEVERE, () -> "Something went wrong: " + message); //since Java 8, we can use Supplier , which will be evaluated lazily

LOG.error("Unable to open file {}", csvPath, e);

if (LOG.isDebugEnabled() {   LOG.debug("Unable to open file " + csvPath, e);  // this is compliant, because it will not evaluate if log level is above debug. }

Preconditions.checkState(arg > 0, "Arg must be positive, but got %d", a);  // String formatting only applied if needed

if (!condition) {   throw new IllegalStateException(formatMessage()); // formatMessage() only invoked conditionally }

if (!condition) {   throw new IllegalStateException("message: " + formatMessage()); }

I'm not 100% sure whether i understand this right. So why is this really an issue. Especially the part about the performance hit when using string concatenation. Because I often read that string concatenation is faster than formatting it.

EDIT: Maybe someone can explain me the difference between

LOGGER.debug("Comparing objects: " + object1 + " and " + object2);

AND

LOGGER.debug("Comparing objects: {} and {}",object1, object2);

is in the background. Because I think the String will get created before it is passed to the method. Right? So for me there is no difference. But obviously I'm wrong because SonarLint is complaining about it

Answer 1

I believe you have your answer there.

Concatenation is calculated beforehand the condition check. So if you call your logging framework 10K times conditionally and all of them evaluates to false, you will be concatenating 10K times with no reason.

Also check this topic. And check Icaro's answer's comments.

Take a look to StringBuilder too.

Answer 2

String concatenation means LOGGER.info("The program started at " + new Date());

Built in formatting of logger means
LOGGER.info("The program started at {}", new Date());

very good article to understand the difference http://dba-presents.com/index.php/jvm/java/120-use-the-built-in-formatting-to-construct-this-argument

Answer 3

Consider the below logging statement :

LOGGER.debug("Comparing objects: " + object1 + " and " + object2);

what is this 'debug' ?

This is the level of logging statement and not level of the LOGGER. See, there are 2 levels :

a) one of the logging statement (which is debug here) :

"Comparing objects: " + object1 + " and " + object2

b) One is level of the LOGGER. So, what is the level of LOGGER object : This also must be defined in the code or in some xml , else it takes level from it's ancestor .

Now why am I telling all this ?

Now the logging statement will be printed (or in more technical term send to its 'appender') if and only if :

Level of logging statement >= Level of LOGGER defined/obtained from somewhere in the code

Possible values of a Level can be

DEBUG < INFO <  WARN < ERROR

(There can be few more depending on logging framework)

Now lets come back to question :

"Comparing objects: " + object1 + " and " + object2

will always lead to creation of string even if we find that 'level rule' explained above fails.

However,

LOGGER.debug("Comparing objects: {} and {}",object1, object2);

will only result in string formation if 'level rule explained above' satisfies.

So which is more smarter ?

Consult this url.

Answer 4

First let's understand the problem, then talk about solutions.

We can make it simple, assume the following example

LOGGER.debug("User name is " + userName + " and his email is " + email );

The above logging message string consists of 4 parts
And will require 3 String concatenations to be constructed.

Now, let's go to what is the issue of this logging statement.

Assume our logging level is OFF, which means that we don't interested in logging now.

We can imagine that the String concatenations (slow operation) will be ALWAYS applied and will not consider the logging level.

Wow, after understanding the performance issue, let's talk about the best practice.

Solution 1 (NOT optimal)
Instead of using String concatenations, we can use String Builder

StringBuilder loggingMsgStringBuilder = new StringBuilder();
loggingMsgStringBuilder.append("User name is ");
loggingMsgStringBuilder.append(userName);
loggingMsgStringBuilder.append(" and his email is ");
loggingMsgStringBuilder.append(email );
LOGGER.debug(loggingMsgStringBuilder.toString());

Solution 2 (optimal)
We don't need to construct the logging message before check the debugging level.
So we can pass logging message format and all parts as parameters to the LOGGING engine, then delegate String concatenations operations to it, and according to the logging level, the engine will decide to concatenate or not.

So, It's recommended to use parameterized logging as the following example

LOGGER.debug("User name is {} and his email is {}", userName, email);