10 Replies Latest reply: Apr 14, 2012 9:42 AM by Lars Gråmark RSS

Log4j logger performance in JBoss AS 7

Lars Gråmark Newbie

I recently migrated an application from Tomcat 6 to JBoss 7. The migration went fine except but when we ran comparative performance tests between Tomcat and JBoss we found that

the response times were a lot worse than in Tomcat. When I looked into the problem I found that the overhead was caused by the using log4j over the JBoss logging subsystem.

The fact that the logging subsystem could have a slight overhead is understandable but I find the proportion a bit worrying.

 

I simplified the test in order to recreate it for this forum and it now contains 10 calls to the log4j logger.

When running this with 10 simultaneneous users and each with 100 requests I get approx 23 ms per call.

Now if I compare this with a setup that does NOT use the logging subsystem but uses log4j directly I get approx 2 ms.

Quite a differency.

I havent run this through a profiler yet but I wanted to make a sanity check with you before proceeding with this.

Did I miss anything in the configuration?

 

This is what I did to get the figures for the logging subsystem.

 

  1. I installed a fresh copy of JBoss 7.1.1-final.
  2. I downloaded the latest version of the hellowolrd application from quickstarts.
  3. I added the following dependency to the pom.xml.
    <dependency>
       <groupId>log4j</groupId>      
       <artifactId>log4j</artifactId>
       <version>1.2.16</version>
    </dependency>
  4. Altered the HelloService to this:
    public class HelloService {
       Logger logger = Logger.getLogger(HelloService.class);

       String createHelloMessage(String name) {
           for (int i=0;i<10;i++) {
               logger.warn("Hello world");
           }
           return "Hello " + name + "!";
       }
    }
  5. Added the handler and the logger below to standalone.xml:
    <periodic-rotating-file-handler name="DEMO" autoflush="false">
        <formatter>
            <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
        </formatter>
        <file relative-to="jboss.server.log.dir" path="demo.log"/>
        <suffix value=".yyyy-MM-dd"/>
        <append value="true"/>
    </periodic-rotating-file-handler>
    <logger category="org.jboss.as.quickstarts" use-parent-handlers="false">
        <level name="INFO"/>
        <handlers>
            <handler name="DEMO"/>
        </handlers>
    </logger>
  6. Added the file jboss-deployment-structure.xml to WEB-INF
    <jboss-deployment-structure>
        <deployment>
            <dependencies>
                <module name="org.apache.log4j" />
            </dependencies>
        </deployment>
    </jboss-deployment-structure>
  7. I then used the Apache benchmarking tool to get the numbers.
    ab -n100 -c10 http://127.0.0.1:8080/jboss-as-helloworld/HelloWorld

 

 

This is what I did to get the numbers for log4j without going through the logging subsystem:

 

  1. Replaced the file jboss-deployment-structure.xml in WEB-INF with the following contents:
    <jboss-deployment-structure>
        <deployment>
            <exclusions>
                <module name="org.apache.log4j" />
            </exclusions>
        </deployment>
    </jboss-deployment-structure>
  2. Added the line below to bin/standalone.conf.
    JAVA_OPTS="$JAVA_OPTS -Dlog4j.configuration=file://<path to JBOSS_HOME>/standalone/configuration/log4j.xml"
  3. Added the file log4j.xml in standalone/configuration.
    <?xml version="1.0" encoding="UTF-8"?>
    <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
    <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"     debug="false">
       <appender name="DEMO" class="org.apache.log4j.DailyRollingFileAppender">
          <param name="File" value="${jboss.server.log.dir}/demo_direct.log" />
          <param name="Append" value="true" />
          <param name="DatePattern" value="'.'yyyy-MM-dd" />
          <layout class="org.apache.log4j.PatternLayout">
             <param name="ConversionPattern" value="%d{ABSOLUTE} [%t] %-5p|%5X{id}|%-50.50c| %m%n" />
          </layout>
       </appender>
       <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
          <param name="Target" value="System.out" />
          <param name="Threshold" value="DEBUG" />
          <layout class="org.apache.log4j.PatternLayout">
             <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n" />
          </layout>
       </appender>
       <logger name="org.jboss.as.quickstarts" additivity="false">
          <level value="INFO" />
          <appender-ref ref="DEMO" />
       </logger>
        <root>
          <priority value="INFO" />
          <appender-ref ref="DEMO" />
       </root>
    </log4j:configuration>
  4. Again I used the Apache benchmarking tool to get the numbers.
    ab -n100 -c10 http://127.0.0.1:8080/jboss-as-helloworld/HelloWorld

 

 

Thanks

Lars Gråmark