Built-in string formatting vs string concatenation as logging parameter

Naxos84 picture Naxos84 · Feb 22, 2017 · Viewed 29.3k times · Source

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

luso picture luso · Feb 22, 2017

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.