Blog

EJAPP Top 10 countdown: #10 – Excessive logging

18 Feb, 2007
Xebia Background Header Wave

At J-Fall in October 2006 I gave a presentation on the top 10 performance problems encountered by me and my colleagues at Xebia. The list was created by brainstorming with a group of people and was based on the experiences we all had with performance in our own projects and projects where we were called in to remove performance bottlenecks.
Of course that is a very unscientific way to make such a list. 😉

Science requires me to perform proper experiments with proper control. In this case that means writing benchmarks. However, that is impossible to do in practice for a number of reasons:

  • These problems were observed in the context of an Enterprise Java application. Stripped down to a simple benchmark the behaviour will undoubtedly be very different.
  • These problems were encountered under all kinds of JDK versions, application server products and versions, database servers, and so forth. For a complete picture I’d have to include them all!

So, instead of a doing this the scientific way I’ve decided to follow the statistical road. To get a better top 10, I’ll be writing a blog entry roughly once a week. Every blog entry will cover another item in the Enterprise Java Application Performance Problems Top 10. I’m hoping people in the Enterprise Java community will chime in with their performance experiences (even better if they have numbers!), help me analyse the issues, and add their own performance solutions and tips. All for the final goal to have a top 10 list that can work as an awareness tool (for other developers and IT managers) and as a quick checklist when working on performance problems.
So, without further ado, let’s start at the bottom: number 10.
Excessive logging is a performance bottleneck because two things happen when you log. First a number of String manipulations are performed (by the invoking code to gather information and by the logging framework to generate a log line) and then the resulting String is written to a file. When your code writes a lot of logging info, a lot of that stuff is going to be happening!
The String manipulations especially are very expensive because it causes objects to be allocated (and garbage collected later), while the performance hit of the I/O depends on the medium being written to and whether the log output is buffered.
Some particularly nasty things encountered are:

  • Invoking the log.debug() method when the log level does not include debug info. All string manipulations done (usually quite a lot in debugging statements) are for nothing.
  • Logging way too much stuff like complete (nested) stacktraces.
  • Logging to System.out or, even worse, System.err. There’s no way to turn it off and System.err is not even buffered!

Fortunately it’s very easy to address this problem.
First and foremost, always use a logging framework like Log4J or JDK logging, or a meta framework like Commons Logging or SLF4J. And then keep the following practices in mind:

  • Use the following idiom to prevent unnecessary String manipulations: if(log.isDebugEnabled()) log.debug(...) On the EJAPP top 10 wiki, Barend Garvelink pointed out that you don’t need to do this when using JBoss Seam with JDK 1.5 because it has a lovely little logging idiom that allows you to write code like log.debug("Entered myMethod with arguments ${0}, ${1}", arg0, arg1);
  • Log to a buffered writer or, even better, asynchronously.
  • Use separate logging configurations for your development and production environments.

Of course, everybody already does this. It’s only other developers that get this wrong. 😉

Questions?

Get in touch with us to learn more about the subject and related solutions

Explore related posts