Saturday, December 10, 2011

... not using isDebugEnabled() or isInfoEnabled()

The log4j API and other ones provide the methods isDebugEnabled(), isInfoEnabled() or isTraceEnabled() to determine if this log level is enabled (see also: http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/Logger.html).

Most of the developers know about this feature of course, but anyway I have often seen code where it would have also made sense to make use of them. If you do debug logging for statements which are called very often and have expensive implementations of toString() methods you can loose performance if you log without the corresponding is...Enabled() methods.

In the following test I run the code which calls a method 1.000.000 times and logs a message with isDebugEnabled() and without it - I turned the log level to info - so no output is produced.

Using isDebugEnabled() took 25 ms without using it. It took 2.5 seconds - which is a factor of 100.

The reason of that is of course simple - if you do not use isDebugEnabled() the String argument of the log.debug() has to be created. Sometimes like in this example the log statements are "hidden" inside a bean - and maybe you don't think about how often the method will be called afterwards.

Btw the isDebugEnabled() statement also consumes time - 20 ms in this case. Without logging the code would have taken 5 ms.

Another option - to make the code more readable - would be to use SLF4J: http://www.slf4j.org/faq.html#logging_performance


package org.kix;


import org.apache.commons.lang3.builder.ToStringBuilder;
import org.apache.commons.lang3.time.StopWatch;
import org.apache.log4j.Logger;


public class SomeBean {
private static Logger log = Logger.getLogger(SomeBean.class);
private int id;
private String text;

public static void main(String[] args) {
StopWatch sw = new StopWatch();
sw.start();
for (int i=0; i<1000000; i++) {
new SomeBean(i).doSth();
}
sw.stop();

log.info(sw);
}



public SomeBean(int id) {
super();
this.id = id;
this.text = "TEXT";
}

public void doSth() {
if (log.isDebugEnabled()) 
                    log.debug("doSth() "+this);
}


@Override
public String toString() {
return new ToStringBuilder(this)
.append("id", id)
.append("text",text)
.toString();
}
}

No comments:

Post a Comment