A few days ago, some people in the office were debating the value of our time honored tradition of guarding debug log statements. If you're not sure what I'm talking about, a short code sample should clear things up quickly.

``` java if (log.isDebugEnabled()) { log.debug("Log message number " + 1); } ```

It's generally accepted that guarding your log statements with an if block will improve performance if your log statements involve some kind of string concatenation, such as the example above. But what kind of performance improvement are we really talking about here?

To determine the impact of this log guarding, I wrote a simple program that repeatedly calls log statements with three different logging implementations. See attachment for the actual code.

  1. UnguardedLogger.java has no if block guarding the log statement at all.
  2. IfGuardedLogger.java has the traditional if block surrounding the log statement, just like the example above.
  3. AspectGuardedLogger.java acts just like the UnguardedLogger except that it has an AspectJ aspect guarding it's log statement. The idea here was to allow you to abandoned typing the if block guard while still enjoying its benefits.

All three implementations were asked to log one million statements in three successive batches. Each log statement included a string concatenation of six components. Each batch ran the three implementations in a different order. The results of the test run are shown below.

ImplementationTest 1Test 2Test 3
UnguardedLogger1341ms1783ms1345ms
IfGuardedLogger35ms32ms30ms
AspectGuardedLogger1343ms1612ms1364ms

Broken down by average time per log statement, that's

  • UnguardedLogger - 1.49µs/statement
  • IfGuardedLogger - 0.03µs/statement
  • AspectGuardedLogger - 1.44µs/statement

From these numbers, I've drawn two conclusions

  1. Guarding your log statements is a lot faster (in this case, 50x faster) than not guarding them at all or guarding them using an aspect. Even so, we're still down in the microsecond range here. If you're doing a lot of logging, you may notice a small improvement from guarding your log statements. Otherwise, you may not want to bother.
  2. Guarding your log statements with an around aspect is really no better than not guarding them at all. I'm not familiar with the internals of AspectJ, but my hunch is that even an around aspect will have to do the log statement string concatenation so that it could potentially be exposed as context for an advice. Hence, it ends up being about the same as not guarding the log statements at all.