Skip to main content

Clean code, clean logs: use appropriate tools (1/10)

Many programmers seem to forget how logging application behavior and its current activity is important. When somebody puts:

log.info("!@#$%");


happily somewhere in the code, he probably don't realize the importance of application logs during maintenance, tuning and failure identification. Underestimating the value of good logs is a terrible mistake. I have collected few random advices that I find especially useful when it comes to writing logging routines and I will present them in a series of short articles. First tip (out of ten) is about logging libraries and tools.

In my opinion, SLF4J is the best logging API available, mostly because of a great pattern substitution support:

log.debug("Found {} records matching filter: '{}'", records, filter);


In Log4j you would have to use:

log.debug("Found " + records + " records matching filter: '" + filter + "'");


This is not only longer and less readable, but also inefficient because of extensive use of string concatenation. SLF4J adds nice {} substitution feature. Also, because string concatenation is avoided and toString() is not called if the logging statement is filtered, there is no need for isDebugEnabled() anymore. BTW, have you noticed single quotes around filter string parameter?

SLF4J is just a façade, as an implementation I would recommend Logback framework, already advertised on my blog, instead of well established Log4J. It has many interesting features (some of them will be discussed in future tips) and, in contrary to Log4J, is actively developed.

The last tool to recommend is Perf4J. To quote their motto:

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

I've added Perf4J to one existing application under heavy load and seen it in action in few other. Both administrators and business users were impressed by the nice graphs produced by this simple utility. Also we were able to discover performance flaws in no time. Perf4J itself deserves its own article, but for now just check their Developer Guide.

To summarize, this is the ideal pom.xml excerpt to start with:

<repositories>
<repository>
<id>Version99</id>
<name>Version 99 Does Not Exist Maven repository</name>
<layout>default</layout>
<url>http://no-commons-logging.zapto.org/mvn2</url>
</repository>
</repositories>


<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>1.5.11</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>0.9.20</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jul-to-slf4j</artifactId>
<version>1.5.11</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>log4j-over-slf4j</artifactId>
<version>1.5.11</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jcl-over-slf4j</artifactId>
<version>1.5.11</version>
</dependency>
<dependency>
<groupId>commons-logging</groupId>
<artifactId>commons-logging</artifactId>
<version>99.0-does-not-exist</version>
</dependency>


To test this, try the following code:

SLF4JBridgeHandler.install();

org.apache.log4j.Logger.getLogger("A").info("Log4J");
java.util.logging.Logger.getLogger("B").info("java.util.logging");
org.apache.commons.logging.LogFactory.getLog("C").info("commons-logging");
org.slf4j.LoggerFactory.getLogger("D").info("Logback via SLF4J");


As you can see, no matter which logging framework is used (we don't even have Log4J and Commons-Logging on our CLASSPATH, see 99.0-does-not-exist version!), every logging statement is printed using Logback (see how it works). So even if your favorite libraries stick to Commons-Logging (very bad thing! [1], [2]) or even worse to Log4J, you don't need to include them in your project.


UPDATE: Ceki Gülcü (founder of the Log4J, SLF4J and Logback projects) suggested simplier approach to get rid of commons-logging dependency (see his comment).


Comments

  1. HI Tomasz,

    Good article. Regarding the exclusion of commons-logging in a maven-based project, declaring it in the protected scope is a nice alternative. See the FAQ at http://www.slf4j.org/faq.html#excludingJCL.

    ReplyDelete
  2. Thanks Tomasz.
    Recently I've wrote some tests whether should we use
    if (logger.isDebugEnabled()
    or skip it and always log debug info because the overhead is little.
    I regret the article is in Polish.
    http://zdanek.ostrejezyki.pl/2010/04/16/develop/w-koncu-logowac-z-if-isdebugenabled-czy-nie/

    Best regards.

    ReplyDelete
  3. Thank you Bartek for the reference to Your article. I will try to find some time and perform similar benchmark for SLF4J and Logback duo. Thanks to "{}" pattern substitution feature and faster is*Enabled() implementation, the difference would probably be unnoticeable.

    ReplyDelete
  4. Please drop me a line when you'll write these benchmarks.

    ReplyDelete
  5. string concatenation is avoided? Doesn't the implementation of SLF4J need to parse that string and do fine, replace and therefore, string concatenation anyway?

    ReplyDelete
  6. you could always just use String.format for the log4j calls to avoid the concat...

    ReplyDelete
  7. great post man, indeed quite useful logging tips in java. In my opinion using correct logging level for different message is most important thing to learn and logging has important performance impact (ever found process running in DEBUG mode in production ) and has to be handled efficiently. I have also blogged my tips as 10 tips on logging in Java , let me know how do you find it.

    ReplyDelete
  8. @Henry Ho: maybe it does, maybe not (see below). The point is you don't have to perform these nasty and verbose string concatenations yourself. Also isDebugEnabled() is no longer needed since the concatenation happens only when the logging statement is actually printed.

    @Steven: True, but the official API states: SLF4J's implementation is 10 times faster than that of MessageFormat.

    @Javin Paul: Thanks, I had quick look at your article. I don't agree with everything, but it's a nice resource.

    ReplyDelete
  9. log4j

    log.debug(String.format("Found %s records matching filter: '%s'", records, filter));

    ReplyDelete
  10. This comment has been removed by a blog administrator.

    ReplyDelete
  11. You should update you article - log4j 2.0 does address the readability and much more issues:
    http://logging.apache.org/log4j/2.x/

    For example, it is the only logging solution I know which does lose logging events when it is under reconfiguration in a running system.

    In addition it is freaking easy to extend.

    ReplyDelete
    Replies
    1. Well, there's wasn't much activity in 2.x branch of log4j, and 1.2.x was only bugfixed without new features. I see this version is now in alpha and it will probably take a while until it's production ready. But it would be great to see two good logging frameworks around.

      "which does lose logging events when it is under reconfiguration" - you probably meant: "doesn't"?

      Delete

Post a Comment