I wrote an article to help developers write a clearer logging statements. This method is somewhat tricky but has been employed by several open source projects (so this over bloating log statements doesn’t disturb me only!).
It’s not without catch as the commentators wrote as the comment of the article. What I don’t know is how far this affects the overall benchmark of an application. So I tested all possibility and showed you the result in this article.
My template for the test is including a loop that do nothing. The code is as follow:
import java.util.logging.Logger;
public class Array0 {
public static Logger log;
static class Foo {
String bar = "test";
public String getBar() {
return bar;
}
}
public static void main(String[] args) {
log = Logger.getLogger(Array0.class.getName());
long st = System.currentTimeMillis();
for (int i = 0; i < 10000000; i++) {
}
System.out.println(System.currentTimeMillis() - st);
}
}
Now I add a logging statement inside the loop as follow:
import java.util.logging.Logger;
public class Array3 {
public static Logger log;
static class Foo {
String bar = "test";
public String getBar() {
return bar;
}
}
public static void main(String[] args) {
log = Logger.getLogger(Array3.class.getName());
Foo foo = new Foo();
long st = System.currentTimeMillis();
for (int i = 0; i < 10000000; i++) {
log.finest("FOO: " + foo + ", BAR: " + foo.getBar());
}
System.out.println(System.currentTimeMillis() - st);
}
}
My next step is to guard the log statement. My code is now look like:
import java.util.logging.Level;
import java.util.logging.Logger;
public class Array {
public static Logger log;
static class Foo {
String bar = "test";
public String getBar() {
return bar;
}
}
public static void main(String[] args) {
log = Logger.getLogger(Array.class.getName());
Foo foo = new Foo();
long st = System.currentTimeMillis();
for (int i = 0; i < 10000000; i++) {
if (log.isLoggable(Level.FINEST)) {
log.finest("FOO: " + foo + ", BAR: " + foo.getBar());
}
}
System.out.println(System.currentTimeMillis() - st);
}
}
After that, I employ my method described in the previous article:
import java.util.logging.Level;
import java.util.logging.Logger;
public class Array4 {
public static Logger log;
static class Foo {
String bar = "test";
public String getBar() {
return bar;
}
}
public static void main(String[] args) {
log = Logger.getLogger(Array4.class.getName());
Foo foo = new Foo();
long st = System.currentTimeMillis();
for (int i = 0; i < 10000000; i++) {
finest("FOO: ", foo, ", BAR: ", foo.getBar());
}
System.out.println(System.currentTimeMillis() - st);
}
public static void finest(Object... msgs) {
if (log.isLoggable(Level.FINEST)) {
StringBuilder m = new StringBuilder();
for (Object o : msgs) {
m.append(o);
}
log.finest(m.toString());
}
}
}
And I try what if I don’t create the array but providing a method with the given number of parameters.
import java.util.logging.Level;
import java.util.logging.Logger;
public class Array2 {
public static Logger log;
static class Foo {
String bar = "test";
public String getBar() {
return bar;
}
}
public static void main(String[] args) {
log = Logger.getLogger(Array2.class.getName());
Foo foo = new Foo();
long st = System.currentTimeMillis();
for (int i = 0; i < 10000000; i++) {
finest("FOO: ", foo, ", BAR: ", foo.getBar());
}
System.out.println(System.currentTimeMillis() - st);
}
public static void finest(Object msg1, Object msg2, Object msg3, Object msg4) {
if (log.isLoggable(Level.FINEST)) {
finest1(msg1, msg2, msg3, msg4);
}
}
public static void finest1(Object... msgs) {
StringBuilder m = new StringBuilder();
for (Object o : msgs) {
m.append(o);
}
log.finest(m.toString());
}
}
I run these code 10 times, and this is the result I got:
So as you can see, if you are using the log and disable the log, the best practice is still the (ummm…) the best. Without code guard is just simply bad, the result of the graph doesn’t correctly show it, but the value should be 27000(!). The use of varargs, IMO, is still the best balance of over-bloated code and performance-oriented code.
What do you think?
Related posts:
When you consider the 10-90 rule (10% of code is executed 90% of the time) using the varargs concept will not have much impact on the overall execution time.
Once you have identified the hotspots of your program (see Effective Java 2nd edition, Item 55: Optimize judiciously), using code guards may have a positive effect on the programs performance. But I suggest a slightly different implementation:
private static final Logger LOG = …;
private static final boolean IS_DEBUG_ENABLED = LOG.isDebugEnabled();
private static final boolean IS_…
@lonny: I agree that we should optimize judiciously, but in case of Logging, I’d prefer to use varargs as common solution (it doesn’t add work, after all) and use the code guards whenever we’ve encountered major problem with the performance later.
Thanks for the comment!
I think the loop will be optimized out in the first call since you neither use i later or do anything with it in the loop except increment it.
@Caligula: How will it be optimized, exactly?
“How will it be optimized, exactly?” it will not be run at all (“jit”-ed away)
see this funny example:
http://www.javaperformancetuning.com/news/qotm028.shtml
also beware of microbenchmarks,
cheers
@milicevic: thanks, that’s new for me. But I think since I don’t use ‘-server’ parameter, it won’t be optimized then. Am I wrong?
Hi Nanda,
I believe behavior changed in JVM 6, so, if you are running JDK 6, than it will be optimized even if you are not using -server flag. You can easily test it by using that 10 000 billion loop. I just did and it runs in 0 seconds, without -server flag, so, yes it gets optimized.
There are some nice articles around about this topic, unfortunately I don’t have any bookmarks, but you can try to search for hotspot and dead code elimination (DCE), one of the links that is interesting is this one:
http://www.infoq.com/articles/java-threading-optimizations-p2
hth,
cheers
m
Any benchmark for heap size difference?
Between
1. log.isFinest() { log.fine(..)}
and
2. finest(…)
Can you please try with foo.getBar() as a resource-intensive method?
If you use the standard 3-liner:
if (log.isLoggable(Level.FINEST)) {
log.finest(“FOO: ” + foo + “, BAR: ” + foo.getBar());
}
…then foo.getBar() won’t be called if this log level isn’t enabled.
However – using your way will have foo.getBar() called every time.
On a related note, I love Scala’s “by-name parameters”. Here’s an example:
(p. 206/207 from Programming In Scala (PDF))
def byNameAssert(predicate: => Boolean) =
if (assertionsEnabled && !predicate)
throw new AssertionError
In the above case, “predicate” won’t be evaluated if assertionsEnabled is false.
So, you could call it like this:
byNameAssert(x / 0 == 0)
…and if assertionsEnabled is false, you won’t get a “divide by zero” exception.
However, if you defined your function in the usual way:
def boolAssert(predicate: Boolean) =
if (assertionsEnabled && !predicate)
throw new AssertionError
…you will always get a java.lang.ArithmeticException, regardless of what assertionsEnabled is set to.
So, now imagine this applied to your problem:
assertionsEnabled becomes log.isLoggable(Level.FINEST)
Scala does, however, now seem to have the limitation of having repeated by-name parameters:
http://www.nabble.com/repeated-by-name-parameters-tt22686527.html
…so we need to bundle the arguments into an array. (I might just blog about this).
Happy coding
@Milicevic: Thank you for the information, I’ll keep this fact for the future.
@opyate: I do have the same comment as what you’ve suggested (using resource-intensive method in the log) in the original article: http://satukubik.com/2009/08/05/java-tips-simplify-logging/ and yes, you’re correct, it will make my try to improve the situation unusable.
And you know what, I just yesterday thought that an assertion-like debug will be useful for Java. I’m thinking specifically for debug, but something like what Scala offers will be just great!
Thank you for commenting.