Performance of Guarding Debug Log Statements
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.
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.
- UnguardedLogger.java has no if block guarding the log statement at all.
- IfGuardedLogger.java has the traditional if block surrounding the log statement, just like the example above.
- 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.
| Implementation | Test 1 | Test 2 | Test 3 |
|---|---|---|---|
| UnguardedLogger | 1341ms | 1783ms | 1345ms |
| IfGuardedLogger | 35ms | 32ms | 30ms |
| AspectGuardedLogger | 1343ms | 1612ms | 1364ms |
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
- 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.
- 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.
2 Comments
Leave a comment
0 TrackBacks
Listed below are links to blogs that reference this entry: Performance of Guarding Debug Log Statements.
TrackBack URL for this entry: http://www.nearinfinity.com/mt/mt-tb.cgi/491
We wrote a class called FormattingLog which basically parametrizes the log strings and uses java.text.MessageFormat to insert the values. Internally it still guards the log statements but doesn't pollute your code with if statements all over the place, which leads to Checkstyle getting mad at you because it thinks you have nested your if statements too deeply. :-)
So your example from above would look like this:
log.debug("Log message number {0}", 1);
With Java 5 and varargs it is very easy to do this. We felt the performance would still be acceptable, though we didn't write actual tests and perhaps should have, since there is no string concatenation taking place. I think Andrew is writing some tests even as I write this.
Inside the FormattingLog's debug method we still do the guard, so you still incur one more method call than if you just embed the if guard statement directly in code but that shouldn't really kill performance too much. Plus the code goes back to being much cleaner looking :-)
I've run the performance tests that you provided with the addition of the FormattingLog that Scott mentions above. I think the slight hit in performance is well worth the decrease in lines of code and the increase in readability
I'm including the results for the guarded and unguarded since this is being run on a different machine.
Unguarded: 1250ms, 1281ms, 1204ms
IfGuarded: 31ms, 47ms, 31ms
Formatting: 125ms, 109ms, 125ms
Here's what the log statement looks like in my implementation of Logger.
log.debug("First argument = {0}, second argument = {1}, third argument = {2}", arg1, arg2, arg3);