Application logging is a critical but often misunderstood part of a system. Our latest JCP partner, Tomasz Nurkiewicz, has submitted a number of posts describing the basic principles of proper application logging. I decided to aggregate them in a more compact format and present them to you. Check out his suggestions for clean and helpful logs at the following URL:

JavaCodeGeeks: 10 Tips for Proper Application Logging

For crying out aloud can we please move beyond talking back to ourselves in a mirroring log. We need to think more in terms of events (structured type messages) that need not necessarily be "logged" in their original form but instead enhanced, augmented and aggregated at multiple layers by agents and event rules.

If you event/logging call can be easily replaced with a System.out.print() call then you are probably doing it wrong.

For crying out aloud can we please move beyond talking back to ourselves in a mirroring log. We need to think more in terms of events (structured type messages) that need not necessarily be "logged" in their original form but instead enhanced, augmented and aggregated at multiple layers by agents and event rules.

If you event/logging call can be easily replaced with a System.out.print() call then you are probably doing it wrong.

Can give a few examples of what you mean? I.e. traditionally applications log their life history, events and non-events. Errors are almost always application events, debug/trace are almost never application events. Logging framework enhances the message with extra attributes like timestamp, thread name, logger name, etc. Sometimes MDC goes on top of that.

The resulting track record is an input to both troubleshooting and high-level analysis.

What would be the better approach?

One minor nit to pick:

"This is not only longer and less readable, but also inefficient because of extensive use of string concatenation."

This seems to be a perpuation of the myth that concatenation with + is slow in Java.  It was back in version 1.1  but this hasn't been the case for years.  + will be compiled into StringBuilder calls in the example you give. I could also quibble over whether the the substitution version is more readable.  I find it to be less readable.

So in fact, the calls to toString on the substitution argument could be quite costly while the concatenation of those results will are very unlikely to be expensive.  So you aren't wrong.  But referring to String concatenation is as 'inefficienct' is at best extremely outdated information.  I would wager that the replacement is a good bit more expensive than the concatenation.

String concatenation IS expensive, especially when it's not necessary at all.

The difference between:

log.debug("This is my message: " + message);

and

log.debug("This is my message: {}", message);

can be dramatic.

Specifically, in the former, the concatenation happens no matter what, whereas in the latter, it will only happen IF the "debug" level is set in your logger. Now arguably, if both are to be called, the latter is slower simply because it has to parse the message format string first, then do the concatenation, so it does more than simple concatenation.

However, I'd argue that the latter is better at a general code quality level than:

if(log.debugEnabled()) { log.debug("This is my message: " + message); }

String concatenation IS expensive, especially when it's not necessary at all.

The difference between:

log.debug("This is my message: " + message);

and

log.debug("This is my message: {}", message);

can be dramatic.

If message is a (reasonably sized) string and you actually tested that one concatenation you'd find you have to run it thousands of times before you can measure a significant difference.  Now if message is some other type of object, it could be significant.  It's not the concatenation, though, it's the toString() method that may be costly (if it does a lot of concatenation for example.)

Specifically, in the former, the concatenation happens no matter what, whereas in the latter, it will only happen IF the "debug" level is set in your logger. Now arguably, if both are to be called, the latter is slower simply because it has to parse the message format string first, then do the concatenation, so it does more than simple concatenation.

Yes, this was my point.  Please understand, I'm not criticizing the substitution approach, I'm just asking that people stop repeating that "concatenation using the + operator in Java is slow.  It's no slower than using a StringBuilder because it is in fact using a StringBuilder unless it's actually concatenating literals as compile time in which case it's actually infinitely fast at runtime.

I'm so sick of finding code written by our 'expert' consultants using StringBuffer or StringBuilder to concatenate literals.

If message is a (reasonably sized) string and you actually tested that one concatenation you'd find you have to run it thousands of times before you can measure a significant difference.  

This is incorrect because you are making the assumption that debug logging is enabled. Most of the time it won't be and the cost of doing the string concatenation will still be incurred while it won't be where substitution is used. Logging systems optimize based on NOT doing any actual logging so as to incur minimal overhead when nothing is being written. When debug logging is enabled the cost of actually writing the log events somewhere will greatly outweigh the cost of string concatenation vs substitution, so even discussing it in that context is pointless.

If message is a (reasonably sized) string and you actually tested that one concatenation you'd find you have to run it thousands of times before you can measure a significant difference.  

This is incorrect because you are making the assumption that debug logging is enabled.

No, I'm really not.  You need to read what I wrote and forget your assumptions.

Most of the time it won't be and the cost of doing the string concatenation will still be incurred while it won't be where substitution is used.

I know but it has nothing to do with my point.

In what version of Java did string contcatenation automatically compile to StringBuilder? And is that a standard jvm feature implemented by other vendors?

In what version of Java did string contcatenation automatically compile to StringBuilder?

It was either in version 1.2 or 1.3 that it started automatically converting to StringBuffer.  In 1.5 it started compiling to StringBuilder.  So if you use + instead of StringBuffer, prior to 1.5, you automatically got a performance enhancement when moving to 1.5.

And is that a standard jvm feature implemented by other vendors?

It's a compiler feature so the JVM shouldn't matter.  I suppose if you use an odd compiler you might not get this feature.  You can easily check using javap -c or using a bytecoder view such as the one bundled in Eclipse.

Note that even if your compiler doesn't automatically use StringBuilder, you are still better off concatenating literals with + because they will be concatenated at compile time.  I'm 99% sure that's in the java language spec.  And even for non-literal concats, a single concat using String.concat() should acutally be faster than StringBuilder: you only create one new Object (the concatenated String) instead of two (a builder and a new String).  For concatting 3 Strings, it's the same number of Objects being created.  You have to concatenate more that 4 Strings before start saving on Object instantiations.

Use StringBuilder in loops.  For single line concatenations, use +.

One minor nit to pick:

"This is not only longer and less readable, but also inefficient because of extensive use of string concatenation."

This seems to be a perpuation of the myth that concatenation with + is slow in Java.

With all due respect James, string + string is much better than it was but it can still cause significant performance problems. I have seen logging in more than 1 application be the primary bottleneck with string + string being responsible for mroe than 50% of all objects being created in the system and/or (as an aside) be a synchronization bottleneck. In short I'm not very happy with these 10 tidbits... I do wish I understood what William was saying because I have the feeling that I agree with him.

Regards,

Kirk

Let's just call this article what it really is: marketing for SLF4J, which I only use when forced to.

SLF4J has the http://slf4j.org/license.html, so what is the problem? This is exactly how Free Software gets promoted.