Java: Performance Bottleneck at Log4j Checking Log Level?
By admin on Jul 4, 2008 in Java, Programming
Here is a eprof capture of my application when I run my load test using Apache JMeter.
I am running 120 threads concurrently in JMeter using 2 notebooks against a 8 CPUs, 10 GB RAM Unix server.
Looking at the methods with most lock delay show that the bottleneck is at org.apache.log4j.Category.Log method.
The source code of this method is as shown below.
/**
This generic form is intended to be used by wrappers.
*/
public
void log(Priority priority, Object message, Throwable t) {
if(repository.isDisabled(priority.level)) {
return;
}
if(priority.isGreaterOrEqual(this.getEffectiveLevel()))
forcedLog(FQCN, priority, message, t);
}
In my application, there are quite a number of log.debug statements.
log.debug("xxx");
Obviously something is not right because when I changed them to below, the lock contention is removed.
if (log.isDebugEnabled()) {
log.debug("xxx");
}
The source code of isDebugEnabled.
/**
* Check whether this category is enabled for the <code>DEBUG</code>
* Level.
*
* <p> This function is intended to lessen the computational cost of
* disabled log debug statements.
*
* <p> For some <code>cat</code> Category object, when you write,
* <pre>
* cat.debug("This is entry number: " + i );
* </pre>
*
* <p>You incur the cost constructing the message, concatenatiion in
* this case, regardless of whether the message is logged or not.
*
* <p>If you are worried about speed, then you should write
* <pre>
* if(cat.isDebugEnabled()) {
* cat.debug("This is entry number: " + i );
* }
* </pre>
*
* <p>This way you will not incur the cost of parameter
* construction if debugging is disabled for <code>cat</code>. On
* the other hand, if the <code>cat</code> is debug enabled, you
* will incur the cost of evaluating whether the category is debug
* enabled twice. Once in <code>isDebugEnabled</code> and once in
* the <code>debug</code>. This is an insignificant overhead
* since evaluating a category takes about 1%% of the time it
* takes to actually log.
*
* @return boolean - <code>true</code> if this category is debug
* enabled, <code>false</code> otherwise.
* */
public
boolean isDebugEnabled() {
if(repository.isDisabled( Level.DEBUG_INT))
return false;
return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
}
I have written a post before this to show that why we need to use “log.isDebugEnabled”. Some objected to this idea saying that it is cluttering the code. Obviously I think we should not avoid it. Rule of thumb is if your production server is on INFO mode, then you should check for the DEBUG level every time before printing the debug information. For INFO level and above, you can skip it.
someone | Aug 20, 2010 | Reply
Always check your level before using it. You turn off info when those nice-to-knows are less useful. Errors get turned off under high load. Fatals get turned off as a last ditch.
“Skipping it”, the check, is really REALLY bad advice.