29

Our team has the policy of doing logging like

if (LOGGER.isDebugEnabled()) {  
  LOGGER.debug("model[" + model + "]");
}

instead of simply calling the logging method like this:

LOGGER.debug("model[" + model + "]");

This practice is capable of leading to some performance improvement, but on the other hand it makes the codebase more complex. Our application has no performance problems, probably never will, the argument for the introduction of the policy was simply that it's a good practice, so it shall be used every time we are doing logging.

Do you think it's a good policy?

7 Answers 7

30

You should use SLF4J and make log4j your implementation. With SLF4J, you can eliminate isDebugEnabled() altogether by using parameterized messages.

See the section about logging performance in the slf4j FAQ

The following two lines will yield the exact same output. However, the second form will outperform the first form by a factor of at least 30, in case of a disabled logging statement.

logger.debug("The new entry is " + entry + ".");

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

1
  • 10
    String formatting does not help when a parameter building entry is costly. E.g. consider some logger.debug("The new entry is {}.", getEntry()); and you do not know how costly getEntry() is.
    – xmedeko
    Commented Aug 27, 2017 at 12:44
19

It's a good policy for those occasions where the log string you're building up is actually going to affect performance significantly. This could be for two reasons:

  • A lot of work needs to go into building the string (e.g. it's got to do lookups, or build a very large string from lots of very small pieces)
  • It's in a loop which isn't doing much other work (but is called very often), so the proportion of the time spent building up even a simple log string is higher

It shouldn't be a blanket rule, and I'd expect both of these situations to be relatively rare.

Of course, what we really want is to be able to say, "Call the debug method, passing in an argument which isn't the debug string itself, but is something which knows how to build the debug string, if and only if it's necessary." This would be ugly in Java without concise closures. (Even in a language with closures in the form of lambda expressions, capturing the relevant variables could be significant in some situations, depending on how the language handles the capture.)

2
  • 2
    Doesn't SLF have string formatting options in it's log methods?
    – matt b
    Commented Mar 17, 2009 at 13:20
  • I always advocate to use this rule always, because developer does not need to think about the costs of building the string (parameters). Sometimes, it's necessary to build extra parameters for debug logging, like getEntryDebugString(). Better to have a few more lines and error prone code than to be sorry by rare problems.
    – xmedeko
    Commented Aug 27, 2017 at 12:51
9

I agree with the famous quote of Michael A. Jackson:

The First Rule of Program Optimization: Don't do it.

The Second Rule of Program Optimization – For experts only: Don't do it yet.

I think that in the majority of cases it's not worth making the codebase more complex without being sure that the performance gain will be noticable / significant.

I'm aware of the performance improvement, but I think it shall be the responsibility of the individual programmer to decide whether it's worth to add those extra lines of code in a particular case. In most cases the extra lines are just adding complexity without any noticable gain on the performance side.

3
  • 2
    It is obvious that if the author has asked this question then it is a call for him to perform optimization. I.e. when you are asked to optimize a piece of code, you don't reply with the above two quotes. Understand where you are coming from but it doesn't help in this situation.
    – HJW
    Commented Jun 28, 2011 at 9:13
  • -1 from me. i hate this "do not do optimization" mantra. It is seriously flawed - if your optimization will yield results (even trivally) and it is almost free to so (as this is, if statements are trivial) and it isn't complicated (and wrapping a log statement in an if is just the most trivial) then just go ahead and do it.
    – bharal
    Commented Jun 28, 2013 at 9:45
  • 1
    Disagree, this is in the vein of a checklist activity to avoid trouble, that can easily be communicated to a junior developer, so that they won't introduce a mistake by accident that some one has to spend time debugging later.
    – ammianus
    Commented Jul 27, 2015 at 21:16
2

I cannot find the reference online (perhaps I read it in a book) but there was an example of some BIOS call that wrote a String to the screen.

The code the wrote the string to the screen checked to make sure that the String wasn't going to go off of the screen and then called a function to write out a char to the screen.

The function that wrote the char to the screen checked to make sure that the character would not be written off of the screen.

Removing the checking code from the function that wrote the character to the screen resulted in a massive speed boost. The was because printing each character happened very often. They also provided a method that did the check for the cases when the screen position was not checked before the call.

So, if you can check at a high level and avoid the checks at the low level you can speed things up significantly.

In the case you provide, if the code is in a loop or if there are a lot of logging statements then there would be a clear benefit since you would:

  • remove the string creation (and the associated GC)
  • reduce the number of if statements (though hotspote very likely optimizes them out).

I would say that, in general, you should not add anything that is known to be costly if there is an easy work around. This clearly falls into that case - the addition of the if statement is not hard to do, it is a pain to put in later, and it provides a definite speed/memory improvement.

I think the difference between this and premature optimization is that this is known to be always costly,so the issue comes down to is it a cumulative cost you want to add to the program or not? The cost is pretty much constant and it is known at the point of writing the code.

2

I think it makes sence to put the isDebugEnabled() call before you write your log message. Than you easily can update your log message later. We use the following code to make the log messages more flexible.

if (LOGGER.isDebugEnabled()) {  
  String msg = "A Message {0} you can put {1} differet Objects in {2}"; //$NON-NLS-1$
  Object[] args = new Object[] {file1.toString(),new Integer(23),anObject};
  LOGGER.debug(MessageFormat.format(msg,args));
}

When you would not have the if statement you would lose time. Remember... your project becomes bigger and your log messages too.

Log messages should not slow down your code!

1
0

If "model" is already known, just logging it is not so expensive. But, if the "model" should be fetched just for logging as below, simplicity can be compromised.

LOGGER.debug("model[" + proxy.getModel() + "]");
0

I set the logger settings to INFO level, and ran the following test:

@Test
void loggerTest() {
    System.out.println("START " + LocalDateTime.now());

    System.out.println("TRACE: " + LocalDateTime.now());
    log.trace("{}", sleepAndReturnString(5000L, "TRACE PRINT"));
    System.out.println("DEBUG: " + LocalDateTime.now());
    log.debug("{}", sleepAndReturnString(5000L, "DEBUG PRINT"));
    System.out.println("INFO: " + LocalDateTime.now());
    log.info("{}", sleepAndReturnString(5000L, "INFO PRINT"));
    System.out.println("WARN: " + LocalDateTime.now());
    log.warn("{}", sleepAndReturnString(5000L, "WARN PRINT"));
    System.out.println("ERROR: " + LocalDateTime.now());
    log.error("{}", sleepAndReturnString(5000L, "ERROR PRINT"));

    System.out.println("END " + LocalDateTime.now());
}

public static String sleepAndReturnString(long millis, String message) {
    try {
        Thread.sleep(millis);
    } catch (InterruptedException e) {
        log.error("", e);
    }
    return message;
}

logback.xml file:

<configuration>

<property name="MY__PATTERN"
          value="%d{yyyy-MM-dd HH:mm:ss.SSS} | %highlight(%-5level) | %message%n%rEx"/>

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <outputPatternAsHeader>true</outputPatternAsHeader>
        <pattern>${MY__PATTERN}</pattern>
    </encoder>
</appender>

<root level="info">
    <appender-ref ref="CONSOLE"/>
</root>
Here is what was printed in the console:
START 2023-01-20T11:17:57.255
TRACE: 2023-01-20T11:17:57.255
DEBUG: 2023-01-20T11:18:02.256
INFO: 2023-01-20T11:18:07.262
2023-01-20 11:18:12.267 | INFO  | INFO PRINT
WARN: 2023-01-20T11:18:12.283
2023-01-20 11:18:17.285 | WARN  | WARN PRINT
ERROR: 2023-01-20T11:18:17.285
2023-01-20 11:18:22.287 | ERROR | ERROR PRINT
END 2023-01-20T11:18:22.287

As we can see, each time the thread fell asleep for 5 seconds, although the TRACE and DEBUG messages were not printed to the console. This suggests that the use of isLevelEnabled is justified, and increases performance.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.