Which form of slf4j logging construct is best?

Recently I came across this link on the slf4j site. This site suggests that there are significant performance gains using parameterized form of logging. That got me thinking in understanding the relative performance of various scenarios

• Comparison A: Naked logging without a guarding-if-condition vs with a guarding-if-condition
• Comparison B: Parameterized vs Unparameterized Logging
• Comparison C: Parameterized vs unparameterized vs guarding-if-block for objects constructed in-line on the log statement

Testing method

In order to compare different logging strategies I executed each type of log statements for 110,000 (one hundred and ten thousand) times, at once from a single thread. And measured the time consumed for executing last 100,000 statements in each case.

• Warming: First 10,000 statement execution time is ignored in all cases. It is actually used to warm up the program and ignore inconsistencies in comparisons. Execution time of the next 100,000 log statements is considered for performance measurement.
• Number of runs: I completed at least 10 runs of each test and then took the simple average of the measurements.
• Logging enablement and disablement: We did set the log level to error. Hence all

  log.debug()

  statements are used to measure the performance when logging is effectively disabled. Similarly

  log.error()

  statements are used for testing the case when logging is enbled.

• Time measurement: System time is measured before and after the execution of statements, using

  System.currentTimeMillis();

  statement.

• Memeory usage profile of the various alternates are ignored.
• I have used log4j implementation underneath slf4j logging interface.

Code

Please find the code here

Comparison A: Naked logging without a guarding-if-condition vs with a guarding-if-condition

The code snippets that I compared are:

Code snippet 1: Parameterized logging. The logging level is set to error always, so debug logging is disabled. No guarding if statement.

// loggingString is a pre-existing string object in the scope. 
logger.debug("{}", loggingString);

vs

Code snippet 2: Parameterized logging. The logging level is set to error always, so debug logging is disabled. Additional guarding if statement is applied to check if log level is applicable for debug.

// Here the logger.isDebugEnabled() protects the logging statement 
// loggingString is a pre-existing string object in the scope.
if (logger.isDebugEnabled()) {
    logger.debug("{}", loggingString);
}

vs

Code snippet 3: Parameterized logging.The logging level is set to error always, so error logging is effective in this case. No guarding if statement.

// Log level is set to Error. So error should be logged.
logger.error("{}", loggingString);

vs

Code snippet 4: Parameterized logging. The logging level is set to error always, so error logging is effective in this case. Guarding if statement is applied.

// Here the logger.isDebugEnabled() protects the logging statement 
// loggingString is a pre-existing string object in the scope.
if (logger.isErrorEnabled()) {
    logger.error("{}", loggingString);
}

Results

Logging Test Case	Naked logging without a guarding if block	Logging with a guarding if block
Logging Enabled	480 ms	475 ms
Logging Disabled	5 ms	5 ms

Conclusion: We can conclude that there is no percievable performance difference between these two alternate approaches of using a guarding-if-block or not using it when the string to be logged is already available in the scope. That is, when there is no performance cost of creating a new object when logging, using an extra if does not help much. This observation is true irrespective of when logging is enabled or disabled.

Let us now check if unparameterized logging makes any difference.

Comparison B: Parameterized vs Unparameterized Logging with Strings

The code snippets that I was comparing are here:

Code snippet 1: Here we are using unparameterized logging construct. The logging level is set to error always, so debug logging is disabled.

// Log level is set to Error. So debug should not be logged. This is equivalent of logging disabled.
logger.debug("This is logging unparameterized" + loggingString);

vs

Code snippet 2: Here we are using unparameterized logging construct and also making sure that logging happens by using error logging. Logging level is set to debug so error logging will result in actual logging.

// Log level is set to Error. So error should be logged.
logger.error("This is unparameterized with string concatanation" + loggingString);

vs

Code snippet 3: Parameterized logging. The logging level is set to error always, so debug logging is disabled.

// Log level is set to Error. So debug should not be logged. This is equivalent of logging disabled.
logger.debug("{}", loggingString);

Code snippet 4: Parameterized logging.The logging level is set to error always, so error logging is effective in this case.

// Log level is set to Error. So error should be logged.
logger.error("{}", loggingString);

Results

Logging Test Case	Parameterized Static String Logging	Un-Parameterized Logging (String concatanation)
Logging Enabled	480 ms	445 ms
Logging Disabled	5 ms	15 ms

Conclusion: Parameterized logging makes a HUGE difference for the case when logging is disabled. This is because when logging is disabled the string concatanation time is saved in the case of parameterized logging. (Code snippet 1) . This is exactly what is also claimed by the slf4j FAQ site

Logging constructed objects.

Now we will repeat the above two scenarios with a slight modification. In stead of static String which already existed in the scope, we would construct an object, obtain a String representatoin and send it to the logging statement, in-line. Here is an example:

# Unparameterized version
logger.error("Object Error" + (new BigInteger(130, new SecureRandom()).toString(32))); 

# Parameterized version
logger.error("Object Error {} ", (new BigInteger(130, new SecureRandom()).toString(32)));

As you can see, I have created some additional computation load on the logging statement.

Results

Logging Test Case	Unparameterized Object Logging with if if-block	>>Parameterized Object Logging with if-block<<	Unparameterized Object Logging without if if-block	Parameterized Object Logging without if if-block
Logging Enabled	997 ms	998 ms	933 ms	980 ms
Logging Disabled	5 ms	4 ms	433 ms	474 ms

Putting it all together

So considering all the cases above, it is clear that Parameterized logging with a guarding if-block is the best approach with slf4j library. This approach would provide best average performance for both the cases of logger-enabled or logger-disabled. Like below

if (logger.isDebugEnabled()) {               
    logger.debug("Object Debug {}", (new BigInteger(130, new SecureRandom()).toString(32)));
}