log4j

log4j This tests are done using log4j version 1.2.9, and java version: 1.4.2_05.

Refer to the results in org.apache.log4j.performance.Logging for other tests

Introduction

If you are reading log4j docs for example log4j.PatternLayout you already noticed statements like this:

        WARNING Generating the caller class information is slow.
                       Thus, it's use should be avoided unless execution speed is not an issue.

So I decided to measure how slow it is and also I'm suggesting the way to make it faster. Since for me execution speed is an issue and I'd like to see caller information.

LocationInfo Tests

Looking at current log4j code you will see that the function call LoggingEvent.getLocationInformation(); is the common way to receive the location information. Lest get the numbers for this calls assuming it the really expensive function. 

    public interface PseudoLogger {
        public abstract LocationInfo getLocationInfo();
    }

    public class Log4jWay implements PseudoLogger {

        protected final String fqnOfCategoryClass = this.getClass().getName();

        public LocationInfo getLocationInfo() {
        	return new LocationInfo(new Throwable(), fqnOfCategoryClass);
    	}
    }

    public class Java14Way implements PseudoLogger {

        protected final String fqnOfCategoryClass = this.getClass().getName();

        public LocationInfo getLocationInfo() {
        	return new Java14LocationInfo(new Throwable(), fqnOfCategoryClass);
    	}
    }

    /**
     * The test in nutshell
     */
    public double measureLog(PseudoLogger aLog) throws Exception {
        // Timer start
        for (int i = 0; i < 1000; ++ i) {
            li = aLog.getLocationInfo();
            li.getFileName();
            li.getLineNumber();
            li.getClassName();
            li.getMethodName();
        }
        // Timer end
        return time / 1000
    }

The class LocationInfoPerformance is used to measure the speed of this method. You could see the full code in CVS

Java1.4Way it based on Java14LocationInfo (extends LocationInfo) and gets the stack using java 1.4 Throwable.getStackTrace()

Experimental results average duration of call returned by measureLog are listed below in units of milliseconds. Accuracy 10%. java version: 1.4.2_05.

SystemOSStackSizeLog4jWayJava1.4Way
AMD Athlon 1.2 GHzXP-sp250.1380.060
--150.3000.130
--250.5000.200
Intel P4 2.6 GHz Hyper-ThreadingXP-sp250.0980.038
--150.2100.073
--250.3700.120

So class Java14LocationInfo proves to be two times faster

Lets get to real tests.

File appender Tests

Experimental results average duration of calls to log.debug listed below in units of milliseconds. Accuracy 10%. java version: 1.4.2_05.

This test use: org.apache.log4j.RollingFileAppender

StackSize ~10

1) ConversionPattern1 "%d \t %m \n"

2) ConversionPattern2 "%d \t %L %m \n"

    //FileAppenderNoLI.xml
    <appender name="file-appender" class="org.apache.log4j.RollingFileAppender">
      	<param name="File" value="clientTests_NoLI.log"/>
	    <param name="Append" value="true"/>
      	<layout class="org.apache.log4j.PatternLayout">
	        <param name="ConversionPattern" value="NoLI %d \t %m \n" />
        </layout>
    </appender>

    //FileAppenderLI.xml
    <appender name="file-appender" class="org.apache.log4j.RollingFileAppender">
      	<param name="File" value="clientTests_LI.log"/>
	    <param name="Append" value="true"/>
      	<layout class="org.apache.log4j.PatternLayout">
	        <param name="ConversionPattern" value="LI %d \t %L %m \n" />
        </layout>
    </appender>

3) The last test is actually a hack. I just changed the log4j.spi.LoggingEvent class to see how it goes. 

  public LocationInfo getLocationInformation() {
    if(locationInfo == null) {
      //locationInfo = new LocationInfo(new Throwable(), fqnOfCategoryClass);
      locationInfo = new net.sf.jour.log4j.Java14LocationInfo(new Throwable(), fqnOfCategoryClass);
    }
    return locationInfo;
  }

SystemOS1) No caller location2) Include caller location3) Include caller location use Java1.4
AMD Athlon 1.2 GHzXP-sp20.0200.4400.191
Intel P4 2.6 GHz Hyper-ThreadingXP-sp20.0190.3200.130

So again class Java14LocationInfo proves to be two times faster.

Testing Real application in debug mode

This is numbers for J2EE application Weblogic + JRun running on Intel P4 2.6 GHz M$ Windows XP. DB is remote

In one of the tests Log4j patch has been applied LoggingEvent and LocationInfo.

When I have priority value="info" the application runs 10% faster.

If PatternLayout does not include location information the performance is nearly the same as debug OFF.

For Java 1.4 version of LocationInfo all the difference I could see is 1-2% but this could be described by the accuracy of the test. Definitely more performance tests should be done to prove that changes to LocationInfo should be done.

Conclusion

It would be nice to extend next version for log4j 1.3.0 with support for java 1.4. Or allow to customize LocationInfo class.

Classes WrapedLocationInfo and Java14LocationInfo are just the examples. They allow log4j to run on JVM before 1.4.

Converting LocationInfo to the Interface and using different implementation would be excellent.

Another way to improve performance is to make StackSize smaller. This is to call new Throwable() in constructor of LoggingEvent when it is know that this event will need LocationInformation. And build LocationInfo base on this Throwable later on when really required. 

  public LoggingEvent(....) {
    ....
    if (level.isGreaterOrEqual(Level.DEBUG)) {
        this.throwableInfo = new ThrowableInformation(throwable);
    }
  }

  public LocationInfo getLocationInformation() {
    if(locationInfo == null) {
        // vlads test patch.
        if (level.isGreaterOrEqual(Level.DEBUG)) {
            locationInfo = new LocationInfo(this.throwable, fqnOfCategoryClass);
            //locationInfo = new net.sf.jour.log4j.Java14LocationInfo(this.throwable, fqnOfCategoryClass);
        } else {
            locationInfo = new LocationInfo(new Throwable(), fqnOfCategoryClass);
            //locationInfo = new net.sf.jour.log4j.Java14LocationInfo(new Throwable(), fqnOfCategoryClass);

        }
    }
    return locationInfo;
  }
spi.LoggingEvent are just the examples.

May be this could some special flag like this... 
            <logger name="co.myproject.hot">
                <level value="DEBUG" />
                <getLocationInformationForDebug value = "true"/>
                <appender-ref ref="file-appender"/>
            </logger>

            <root>
       	        <getLocationInformationForDebug value = "true"/>
       	     ..
       	    </root>

This modification1) No caller location2) Include caller location3) Include caller location use Java1.4
before0.0200.4400.191
after0.0300.2600.121