EJAPP Top 10 countdown: #10 – Excessive logging

EJAPP Top 10 countdown: #10 – Excessive logging
Posted by Vincent Partington mid-afternoon: February 18th, 2007

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.

Filed under Java, Performance | 5 Comments »

5 Responses to “EJAPP Top 10 countdown: #10 – Excessive logging”

Ceki Gulcu Says:

Posted at: February 19, 2007 at 3:28 pm

The logging idiom proposed by SLF4J executes about ten times faster than the JBoss alternative. In practice, there won’t be any difference when a logging request is disabled. However, when the request is enabled, than the SLF4J version will typically log twice as fast.

Vincent Partington Says:

Posted at: March 1, 2007 at 1:16 pm

Ceki, isn’t it interesting that the JDK 1.5 language features provide performance benefits in such an unexpected area! I don’t fully understand your point though: is the SLF4J logging idiom two times or ten times faster than the JBoss idiom? Have you get a benchmark for this?

Ceki Gulcu Says:

Posted at: March 3, 2007 at 8:56 pm

The way SLF4J handles parameterized logging has nothing to do with JDK 1.5. SLF4J targets JDK 1.3 and above.

The time it takes to build the formatted message in SLF4J, that is parsing

log.debug(”Entered myMethod with arguments {}, {}”, arg0, arg1);

is ten times faster than parsing
log.debug(”Entered myMethod with arguments ${0}, ${1}”, arg0, arg1);

We got the numbers from very simple benchmarks we did.

Xebia France Blog Says:

Posted at: March 5, 2007 at 12:24 am

[...] Plusieurs problèmes dans cette approche: – le logger utilisé porte le nom de la classe. Il doit être configuré comme tel (y compris avec les mécanisme d’héritage). Les noms de classe (et de package) n’ont pas vraiment de sens pour les équipes d’exploitation, ce qui limite souvent leur autonomie sur la configuration des traces. – les messages de debug manquent de consistance, et n’ont de véritable intérêt que pour le développeur au moment de la mise au point de la classe concernée (ce qui, notons-le, n’est pas critique; par nature, les messages de déboguage ne sont pas destinés aux exploitants). – si plusieurs threads exécutent simultanément la méthode, les traces seront entrelacées et il sera difficile de rétablir le séquencement des opérations – le message d’erreur est laconique et la pile d’appel, pour utile qu’elle soit, n’est interprétable que par l’ingénierie. – il n’y a pas de trace intermédiaire entre DEBUG et ERROR, ce qui limite la capacité de diagnostic en exploitation – l’utilisation des API de log tel quel peut poser des problèmes de performance (cf ce billet) [...]

Le top 10 des problèmes de performances des applications J2EE par J2EE, Agilité et SOA : Le blog de Xebia France Says:

Posted at: May 3, 2007 at 2:38 pm

[...] #10 – Logging excessif [...]