10 Replies Latest reply on Apr 14, 2012 9:42 AM by gramark

    Log4j logger performance in JBoss AS 7

    gramark

      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

        • 1. Re: Log4j logger performance in JBoss AS 7
          jamezp

          There is some overhead in booting up any subsystem including logging. My guess is the extra time comes from booting up the subsystem. Also note that when using log4j with the logging subsystem you are going through an abstraction layer between the JBoss Log Manager and log4j. While the time to do this is probably insignificant it could add a slight performance decrease. If you were to use JBoss Logging rather than log4j even without the subsystem I would imagine the results are the same if not better than log4j.

           

          In the end we're talking about 21ms difference. Likely just a one time 19-20ms difference too because of the subsystem booting up. When you use the subsystem you get the ability to change your logging configuration in real-time rather than having to redeploy your application for every logging change. In my opinion that's definitely worth losing 20ms and really it's probably only a one time 20ms.

          • 2. Re: Log4j logger performance in JBoss AS 7
            gramark

            Thanks for your response.

            The boot up time was been taken into account when I ran the tests. The system has been running for a while and I've run the test several times to give JIT a chance to warm up.

            Unfortunately, a difference of 20 ms is actually a bit too much for us to keep using the subsystem. The reason is that this is an application that will have a huge amount of requests and the delay will be noticed by end users.

            The real time configuration is really a great feature but I need to solve the performance "problem" before I can use this.

            • 3. Re: Log4j logger performance in JBoss AS 7
              jamezp

              Taking a second look at your configuration with the subsystem it appears the messages might be getting logged twice if you're using log4j or possibly not at all really. You're excluding the log4j library in the jboss-deployment-structure.xml, but using the configuration in standalone.xml. That doesn't seem right.

              • 4. Re: Log4j logger performance in JBoss AS 7
                gramark

                I have to admit that the example perhaps wasn't that great. But it actually works as expected. When I exclude the log4j module from jboss-deployment-structure.xml, the log message does not seem to reach the subsystem and it writes to the file I specified in log4j.xml but not to the file I provided in standalone.xml.

                The result is exactly the same if I clear out the entries in standalone.xml for the second test.

                • 5. Re: Log4j logger performance in JBoss AS 7
                  dmlloyd

                  20ms per message is definitely indicating some major problem.  Our log4j integration should actually outperform plain log4j by a pretty decent margin, based on previous performance testing.  If log messages are taking this long, something must have gotten screwed up in the integration.

                  • 6. Re: Log4j logger performance in JBoss AS 7
                    dmlloyd

                    Looks like this might be the issue solved in https://issues.jboss.org/browse/LOGMGR-38, so it should be fixed upstream soon.

                    1 of 1 people found this helpful
                    • 7. Re: Log4j logger performance in JBoss AS 7
                      jamezp

                      Just to add, one way to speed it up would be to remove the date format from the pattern. Not sure that's desirable, but it would work.

                      • 8. Re: Log4j logger performance in JBoss AS 7
                        gramark

                        Synchronization sounds like a plausible cause. Looking forward to try it out as soon as its available.

                        Thank you both for your time and help.

                        • 9. Re: Log4j logger performance in JBoss AS 7
                          haroonfoad

                          Under which tag in standalone.xml you added

                          JAVA_OPTS="$JAVA_OPTS -Dlog4j.configuration=file:///usr/local/jboss-as-web-7.0.2.Final/standalone/configuration/log4j.xml"

                           

                          ?

                          • 10. Re: Log4j logger performance in JBoss AS 7
                            gramark

                            Thats bin/standalone.conf. Not standalone.xml.