Use the built-in formatting to construct this argument.

The title of this article comes from a Sonar's rule message. You will see it, when you use string concatenation when logging with slf4j for example like this:

LOGGER.info("Some text " + value);

What is wrong with such usage?

Full logging example

This is a simple example for which Sonar reports a rule violation.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.util.Date;

public class Application {
    private static final Logger LOGGER = LoggerFactory.getLogger(Application.class);

    public static void main(String[] args) {
        LOGGER.info("The program started at " + new Date());
    }
}

When the program starts and the INFO logging level enabled, the start date is logged:

22:47:45.151 [main] INFO com.dbapresents.Application - The program started at Sun Mar 12 22:47:45 CET 2017

But when the INFO logging level is disabled, the date is not logged. It is intuitive so far. Let's stop here for a moment. If the INFO logging level is disabled, isn't LOGGER.info method executed? Of course it is because there is no IF statement before. So who/what decides whether to log or not to log the message? The answer is - something inside the LOGGER.info method which means that the method is executed all the same but one of two execution paths is chosen based on the logging level.

When the string concatenation really takes place?

Let me rephrase it. The only value passed to the LOGGER.info method is a String. But instead of one value, there are two values (the constant and the Date object) that are concatenated. When the concatenation is done?

To answer that question, let me change the code a little bit. The plus operator for string concatenation can be replaced with a method execution.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.util.Date;

public class Application {
    private static final Logger LOGGER = LoggerFactory.getLogger(Application.class);

    public static void main(String[] args) {
        LOGGER.info(concatenate("The program started at ", new Date()));
    }

    private static String concatenate(String value1, Date value2) {
        System.out.println("concatenation");
        return value1 + value2;
    }
}

When the concatenate method is executed, concatenation text is printed to the standard output. When the info logging level is enabled the output contains two lines:

concatenation
21:06:52.142 [main] INFO com.dbapresents.reservations.Application - The program started at Sat Mar 18 21:06:52 CET 2017

It means that the concatenation was done before execution of LOGGER.info.

When the info logging is disabled (through a setting appropriate for the logger), only one line is printed:

concatenation

The message about starting the program is not there because the logger checked the logging level. But even that no logging was needed, the concatenation had to be done. There is the root of the potential performance issue reported by Sonar.

Use the built-in formatting to construct this argument

Which means ...? Slf4j does not have only one log method but a few more.

There are some that can format a text. The correct usage is this:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.util.Date;

public class Application {
    private static final Logger LOGGER = LoggerFactory.getLogger(Application.class);

    public static void main(String[] args) {
        LOGGER.info("The program started at {}", new Date());
    }

}

Logging this way, you avoid performance overhead for strings concatenation when nothing should be actually logged.