Igor Kromin |   Consultant. Coder. Blogger. Tinkerer. Gamer.

NOTE: This article is 3 years or older so its information may no longer be relevant. Read on at your own discretion! Comments for this article have automatically been locked, refer to the FAQ for more details.
I've been going through a fair amount of code that makes excessive use of log4j guard statements like isDebugEnabled() and began mercilessly removing their use. In my mind, these statements make the code messy and are really not necessary in most situations. In terms of performance, a guard statement does not necessarily give you any kind of boost, except in some odd edge cases. To prove my point however, I wrote some code and collected data to graph, here are the results.

What I did was log a message at the DEBUG level while log4j was configured to log at the INFO level. This means nothing should appear in my logs, however the logging code still runs. I logged the same message in a loop 10,000,000 times and repeated this process 100 times to get some significant numbers. Each message was first logged without a guard statement ('No Check' in the graphs), the timing captured, and then it was logged with an if statement using the isDebugEnabled() guard statement ('Check' in the graphs), and the timing captured.

My first round of testing was with a simple log message like this:
 log4j simple message logging
LOG.debug("A log message");


The results are below. It's actually faster when a guard statement is not used. Although it is faster, it varies by a handful of milliseconds over 10 million log messages. I would call that not a significant enough to compare, so using and not using a guard statement for a simple message is identical in terms of performance. The bonus however is that your code becomes at least 2 lines shorter, and easier to read.
 log4j simple message logging
LOG.debug("A log message");
vs
if (LOG.isDebugEnabled()) {
LOG.debug("A log message");
}

log4j_timing1.png




Now my next test case did a little more with the log message. It calculated a value using the loop's increment counter first, then logged the message. This is just an example, but the point I am making is that in some cases you need to do some work to generate a log message i.e. it is not a constant string.
 log4j calculated message logging
LOG.debug("A log message " + Integer.toString(i) + Math.pow(Double.valueOf(i + ""), 1.0));


The results in this case are significantly different. Not using a guard statement will severely impact performance.
log4j_timing2.png


I would call this an edge case because it is rare that it takes so much work to generate a log message or that so much calculation is performed simply for the purpose of logging, in my experience. I have seen a few cases where certain additional processing and logging was done for debug purposes, this spanned many lines of code and in this case a guard statement was completely warranted and encouraged. However, on the most part if you are logging simple messages, there is absolutely no need to check if you should log first, because the logging framework will do that check for you anyway!

Happy logging!

-i

Skip down to comments...
Hope you found this post useful...

...so please read on! I love writing articles that provide beneficial information, tips and examples to my readers. All information on my blog is provided free of charge and I encourage you to share it as you wish. There is a small favour I ask in return however - engage in comments below, provide feedback, and if you see mistakes let me know.

If you want to show additional support and help me pay for web hosting and domain name registration, donations, no matter how small, are always welcome!

Use of any information contained in this blog post/article is subject to this disclaimer.
 
comments powered by Disqus
Other posts you may like...