Is logback isDebugEnabled() slow on a multi core CPU?

Question

We are currently developing a Scala and Akka Cluster based product for medical archives. In the code there is a lot of

if(logger.isDebugEnabled()) {
    logger.debug(expensiveFunction())
}

In our previous codes with standard SQL/JPA, blocking I/O and lots of threads, this construction was more or less for free. However, today in the era of reactive programming, CPU cache synchronization and memory barriers and locks are considered expensive and should be avoided. Is the Logback isDebugEnabled() resulting in a volatile access and hence a memory barrier. If so, is having a lot of logger.isDebugEnabled() a potential performance killer?

There is an excellent blogpost on the topic of CPU cache synchronization and memory barriers: http://mechanical-sympathy.blogspot.se/2013/02/cpu-cache-flushing-fallacy.html

It is much faster than the alternative which is to not do the check. What are you suggesting as an alternative? — Peter Lawrey, May 22 '14 at 10:57
BTW It is still *much cheaper* than using Scala or passing messages between threads. — Peter Lawrey, May 22 '14 at 10:59
Thanks for the comments. I agree a volatile access is still much cheaper than e.g. posting between threads, but if isDebugEnabled() is imposing a memory barrier, it should probably be avoided in inner loops. The alternative is to be aware of the impact and try to place logging more sparsely and outside of loops. — j.hedin, May 22 '14 at 11:03
Or just cache the value before the loop. I don't know Scala, but in Java: `boolean isDebugEnabled = logger.isDebugEnabled();` ...later... `if(isDebugEnabled) logger.debug(expensiveFunction());` — user253751, May 22 '14 at 11:05
Thanks @immibis. Caching at method entry is probably a good way to handle it. — j.hedin, May 22 '14 at 11:10

Pablo Lozano · Answer 1 · 2014-05-22T13:30:18.913

EDIT: As the OP pointed, this code is from Log4J, not Logback. Logback code can be checked here, which seems a lot much complex to follow (This is just my opinion, but I don't like code wich has method names like filterAndLog_0_Or3Plus)

If you check the source code:

 public boolean isDebugEnabled() {
    if(repository.isDisabled( Level.DEBUG_INT))
      return false;
    return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
  }



 public void debug(Object message) {
    if(repository.isDisabled(Level.DEBUG_INT))
      return;
    if(Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel())) {
      forcedLog(FQCN, Level.DEBUG, message, null);
    }
  }

So no, you should not worry about performance because it is called anyway, so using it before creating strings as log.debug(str1 + obj.toString()) is still a good idea.

I think that source is from Log4j. The getEffectiveLevel() does access a volatile variable. From the Logback source, I was not able to conclude whether a memory barrier was enforced or not. Of course, isDebugEnabled() is much better than not checking, but the question is whether it should be avoided at all because of the cost of volatile variable access. — j.hedin, May 22 '14 at 11:07

score 1 · Answer 2 · edited May 23 '17 at 11:43

The best way to answer this question is to benchmark your program on the target hardware and load, with logging disabled by configuration, once with the field marked volatile, and once when it isn't.

That said, I would be greatly surprised if this had a measurable impact on performance for the following reasons:

Your program will likely spend only a tiny fraction of total execution time in isDebugEnabled().
According to Is volatile expensive?:

Generally speaking, on most modern processors a volatile load is comparable to a normal load. A volatile store is about 1/3 the time of a montior-enter/monitor-exit. This is seen on systems that are cache coherent.

score 1 · Accepted Answer · answered Jun 23 '14 at 09:52

Looking at the logback code there are no locks or volatiles accessed inside isDebugEnabled().

However, for really tight loops I recomend doing something like this:

boolean isDebugEnabled = log.isDebugEnabled();

while(cond) {
    if (isDebugEnabled) {
        log.debug(...);
    }
    doStuff();
}

And if your logic is being called in a tight loop, but the loop is in another class then make isDebugEnabled a final member variable and initialise it in the constructor. This can lead to great performance, as hotspot will see the "if (false)" and just remove the code. The only downside is you can't change the log level on the fly, but that's not a big deal in most systems.

Is logback isDebugEnabled() slow on a multi core CPU?

3 Answers3