RSS Feed for This PostCurrent Article

Java: Performance Bottleneck at Log4j Checking Log Level?

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.
 void log(Priority priority, Object message, Throwable t) {
   if(repository.isDisabled(priority.level)) {
     forcedLog(FQCN, priority, message, t);

In my application, there are quite a number of log.debug statements.


Obviously something is not right because when I changed them to below, the lock contention is removed.

if (log.isDebugEnabled()) {

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.
    *   */
  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.

Trackback URL

RSS Feed for This Post1 Comment(s)

  1. 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.

RSS Feed for This PostPost a Comment

Refresh Image