CODEWITHSUNDEEP
javaperformanceloggingslf4j
Mark D
Mark D

Reputation: 5648

Even with slf4j, should you guard your logging?

Help me out in a debate here.. :)

The slf4j site here http://www.slf4j.org/faq.html#logging_performance indicates that because of the parameterized logging, logging guards are not necessary. I.e. instead of writing:

if(logger.isDebugEnabled()) {
  logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
}

You can get away with:

Object entry = new SomeObject();
logger.debug("The entry is {}.", entry);

Is this really okay, or does it incur the (albeit lower) cost of creating the static string that's passed to the trace method..?

Upvotes: 49

Views: 38221

Answers (6)

Orlando Miramontes
Orlando Miramontes

Reputation: 31

Another alternative to logger.isDebug() is to use "lazy logging" or passing a lambda expression [link]:

logger.trace("The user {} has {} dollars available", 
    () -> person.id(), 
    () -> remoteService.getBalance(person));

Upvotes: 3

fglez
fglez

Reputation: 8552

I'll try to put my two cents from another perspective

What is exactly the benefit of parametrized logging?

You just defer toString() invocation and string concatenation until really needed, which is when you really have to log the message. This optimizes performance when that particular logging operation is disabled. Check source code for SLF4J if not sure.

Does parametrized logging makes guards useless in all cases?

No.

In which cases would logging guards be of use?

When there are other potential expensive operations.

For example (in the case this particular logging operation is disabled), if we have no logging guard

logger.debug("User name: {}", getUserService().getCurrentUser());
  1. We would pay the cost from obj = getUserService().getCurrentUser()
  2. We would save the cost from "User name: " + obj.toString()

If we use logging guard:

if (logger.isDebugEnabled()) {
    logger.debug("User: {}", getUserService().getCurrentUser());
}
  1. We would pay the cost of logger.isDebugEnabled()
  2. We would save the cost from obj = getUserService().getCurrentUser()
  3. We would save the cost from "User name: " + obj.toString()

In the later case, we would save both costs at the price of checking isDebugEnabled() twice when this particular logging operation is enabled.

NOTE: This is just an example, not trying to debate good/bad practices here.

Upvotes: 77

Jeff Foster
Jeff Foster

Reputation: 44696

Please don't use the if statement, because every time I look at code like this

if (logger.isDebug()) {
   logger.debug("Of course it's debug {}", sadFace);
}

I cry.

I hope that the cost of creating the static string is so low as to be insignificant for 99% of users.

Upvotes: 4

wallenborn
wallenborn

Reputation: 4273

The guard is not used because of the string creation.

Instead, it is typically used to avoid a potentially expensive argument expression, something like entry[i].retrieveExtendedDebugInformation().formatNicely(). For that, logback makes sure the argument is evaluated only when the log message is actually printed, while log4j always evaluates the argument before calling debug().

Here the only candidate is String.valueOf(entry[i]), which is not very expensive either, so you can make an argument that this guard is unneccessary altogether.

Upvotes: 8

Jesper
Jesper

Reputation: 206776

The problem with a logging statement like this:

logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));

is that it will do a lot of work to concatenate values into a String, which is then never used if debug logging is off. So in that case, it is beneficial to check if debug logging is on before executing this line. When you're just passing parameters:

logger.debug("The entry is {}.", entry);

then it does not unnecessarily need to build a String that is never used, and the check is not necessary; just passing arguments to a method does not have a very high overhead.

Note that if you have relatively expensive expressions for the arguments in a logging statement, it might still be beneficial to check the logging level first.

Upvotes: 4

Aaron Digulla
Aaron Digulla

Reputation: 328536

Writing and reading all those if(logger.isDebugEnabled()) {} will probably cost as much time as they save you.

Of course, calling the log method isn't free but the same is true for calling isDebugEnabled(). So you're paying more for each log statement that is active if you use this pattern (because the logging framework will check the level twice).

It also clutters the code.

In practice, I haven't found the performance penalty to be big enough to bother.

If logging is too slow for you, write an non-blocking appender that pushes the log events into a queue without only a few checks and use a background thread to process them.

Background: The standard appenders are all synchronized so logging in a multi-threaded application can cause lots of small pauses where all threads wait for a log message to be written to a file.

Upvotes: 21

Related Questions