Log4j 2
  1. Log4j 2
  2. LOG4J2-437

Log4J2 Performs poorly with 500 concurrent users with Jboss 5.1.GA and JDK 6

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta9
    • Fix Version/s: None
    • Component/s: Appenders
    • Labels:
    • Environment:

      JDK : 1.6.0_18
      APP Server : Jboss 5.1.0_GA
      Task : Migrate from Log4J_1.2 to Log4J2
      OS : Linux 5 (Virtual Machine)

      Description

      Environment Details
      ================
      JDK : 1.6.0_18
      APP Server : Jboss 5.1.0_GA
      Task : Migrate from Log4J_1.2 to Log4J2
      OS : Linux 5 (Virtual Machine)

      We are trying to upgrade from Log4J 1.2 to Log4J2 due to performance reasons. In log4j1.2, we saw thread BLOCKING and decided to go to LOG4J2. Before migration, we tested to evaluate and we found performance improvement with LOG4J2.

      After full migration, when application moved to performance testing environment, we started seeing trouble with Log4j2. We saw at least 40 TPS down, with increased response times; in performance. When diagnosed, found that there is increased SWAPPING on linux and with increased IO waits (Some times 15 %).

      For the same given environment and load test; application with LOG4J_1.2 code , does not have any SWAPPING and IO waits. In addition we have BAD performance with LOG4J2.

      Can anyone give us pointers on what we are doing wrong ? Or there are some performance issues with LOG4J2 ?? We are stuck in between releases and if there is no help coming, we may just abandon LOG4J2. So Please I request you to look seriously and give us some pointers.

      Following is the configuration for log4j2.

      <?xml version="1.0" encoding="UTF-8"?>
      <configuration status="trace" verbose="true">
              <appenders>
                      <RollingRandomAccessFile name=“APP_1066_LOG" fileName=“/path/to/log/file-1066.log" filePattern=“/path/to/log/file-1066.log.%i" append="true" immediateFlush="false">
                              <PatternLayout>
                                      <pattern>%d{ISO8601} %-5p [%t]: [%c{1}] %m%n - %X{ElapsedTime}-%X{ByteSize}- %X{uniqueID}-%X{HttpMethod}-%X{Host}-%X{URL}-%X{ClientIP}-%X{NodeID}-%X{NodeUserID}-%X{HttpCode}-%X{ApplicationCode}</pattern>
                              </PatternLayout>
                              <Policies>
                                      <SizeBasedTriggeringPolicy size="250 MB"/>
                              </Policies>
                              <DefaultRolloverStrategy max="10"/>
                      </RollingRandomAccessFile>
      
                      <RollingRandomAccessFile name="hibernateAppender" fileName=“/path/to/log/anotherfile-1066.log" filePattern=“/path/to/log/anotherfile-1066.log.%i" append="true" immediateFlush="false">
                              <PatternLayout>
                                      <pattern>%d{ISO8601} %-5p [%t]: [%c{1}] %m%n - %X{ElapsedTime}-%X{ByteSize}- %X{uniqueID}-%X{HttpMethod}-%X{Host}-%X{URL}-%X{ClientIP}-%X{NodeID}-%X{NodeUserID}-%X{HttpCode}-%X{ApplicationCode}</pattern>
                              </PatternLayout>
                              <Policies>
                                      <SizeBasedTriggeringPolicy size="250 MB"/>
                              </Policies>
                              <DefaultRolloverStrategy max="10"/>
                      </RollingRandomAccessFile>
                      <Async name="ASYNC">
                              <appender-ref ref="hibernateAppender"/>
                              <appender-ref ref=“APP_1066_LOG"/>
                      </Async>
              </appenders>
              <loggers>
                      <root level="INFO">
                              <appender-ref ref="ASYNC"/>
                      </root>
              <!-- ============================== -->
              <!-- Various loggers -->
              <!-- ============================== -->
      
              <logger name="org.hibernate" additivity="false" level="INFO">
                      <appender-ref ref="hibernateAppender" />
              </logger>
      
              <logger name="org.springframework.orm.hibernate3" additivity="false" level="INFO">
                      <appender-ref ref="hibernateAppender" />
              </logger>
      
              <logger name="org.hibernate.SQL" level="INFO">
                      <appender-ref ref="hibernateAppender" />
              </logger>
      
              </loggers>
      </configuration>
      

        Activity

        Hide
        Ralph Goers added a comment -

        Are you running in a 32 bit or 64 bit JVM? If 32 bit is -server set? Can you get a CPU snapshot with YourKit or a similar tool to locate the hotspots?

        I have no idea why any Java application would cause increased swapping on Linux. That kind of implies that the heap size exceeds the amount of real memory in the machine doesn't it?

        Show
        Ralph Goers added a comment - Are you running in a 32 bit or 64 bit JVM? If 32 bit is -server set? Can you get a CPU snapshot with YourKit or a similar tool to locate the hotspots? I have no idea why any Java application would cause increased swapping on Linux. That kind of implies that the heap size exceeds the amount of real memory in the machine doesn't it?
        Hide
        Giri Kosuru added a comment -

        Hi Ralph,

        Thanks for quick response. Yes we have 64 bit JVM with -server flag. I probably have give little more details. The same application with and without LOG4J2 on the same servers has been load tested, while troubleshooting this issue. Under 500 concurrent users (with 4 jboss standalone nodes) we got 308 TPS with LOG4J_1.2.14. On exactly same settings, same application with LOG4J2, we got 240 TPS, with little higher response times and with higher variations on TPS and response times. What we observed was,

        1) Swapping happening only when we run LOG4J2 tests.

        2) Added few more memory to the system ( 6 + 4 GB total) and the swapping has gone.

        3) Observed iowaits upto 2 - 25%. on on average iowait is 12% probably and is consistent, when swapping was occurring. I still have iowait after adding memory, but not as bad, but still considerable, when compared to log4j_1.2.14.

        4) With log4j_1.2.14, we had bufferedIO=true and immediateFLush=false too.

        JVM startup parameters are as follows:

        java -Dprogram.name=run.sh -server -Dorg.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH=true -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/myroot/my/server/mynode/log/run.gc.log -XX:MaxDirectMemorySize=64g -Dcom.tc.productkey.path=/myroot/my/server/terracotta_client/conf/terracotta-license.key -XX:+UseParallelOldGC -XX:+UseCompressedOops -Xms2048m -Xmx2048m -XX:MaxPermSize=512m -Dorg.jboss.resolver.warning=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Dfile.encoding=UTF-8 -Dorg.apache.catalina.STRICT_SERVLET_COMPLIANCE=true -Dorg.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH=true -Dorg.apache.catalina.connector.CoyoteAdapter.ALLOW_BACKSLASH=true-Djava.net.preferIPv4Stack=true -Djava.endorsed.dirs=/opt/myserver/lib/endorsed -classpath /myroot/myserver/bin/run.jar org.jboss.Main -c mynode -b 192.86.67.123

        I saw few other bugs in JIRA and some suggestions for those bugs. Based on those I am thinking I may need to try

        -DAsyncLogger.RingBufferSize=1024 -Dlog4j2.status.entries=1

        Will run the test with those flags and will update. Mean while please suggest your thoughts and will apply them in the test.

        Also I took some thread dumps and saw some threads BLOCKED. It is interesting to see blocks at org.apache.log4j.Category.callAppenders
        Here is the thread dump.

        "ajp-10.31.152.202-8009-230" daemon prio=10 tid=0x00002aab616a2000 nid=0x134e waiting for monitor entry [0x0000000075fe6000]
        java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:201)

        • waiting to lock <0x000000078006acc0> (a org.apache.log4j.spi.RootLogger)
          at org.apache.log4j.Category.forcedLog(Category.java:388)
          at org.apache.log4j.Category.log(Category.java:853)
          at org.apache.cxf.common.logging.Log4jLogger.internalLogFormatted(Log4jLogger.java:114)
          at org.apache.cxf.common.logging.AbstractDelegatingLogger.internalLog(AbstractDelegatingLogger.java:333)
          at org.apache.cxf.common.logging.AbstractDelegatingLogger.doLog(AbstractDelegatingLogger.java:315)
          at org.apache.cxf.common.logging.AbstractDelegatingLogger.info(AbstractDelegatingLogger.java:237)
          at org.apache.cxf.interceptor.LoggingInInterceptor.logging(LoggingInInterceptor.java:208)
          at org.apache.cxf.interceptor.LoggingInInterceptor.handleMessage(LoggingInInterceptor.java:98)
          at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:243)
        • locked <0x00000007d558ece0> (a org.apache.cxf.phase.PhaseInterceptorChain)
          at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:111)
          at org.apache.cxf.transport.servlet.ServletDestination.invoke(ServletDestination.java:99)
          at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:431)
          at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:147)
          at org.apache.cxf.transport.servlet.AbstractCXFServlet.invoke(AbstractCXFServlet.java:148)
          at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:179)
          at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:108)
          at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
          at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:159)
          at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
          at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
          at XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX (Our application specific class and package)
          at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
          at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
          at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
          at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
          at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
          at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
          at org.apache.logging.log4j.core.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:66)
          at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
          at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
          at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
          at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
          at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
          at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
          at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
          at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190)
          at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92)
          at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
          at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
          at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
          at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
          at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:567)
          at org.apache.catalina.valves.RequestDumperValve.invoke(RequestDumperValve.java:151)
          at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
          at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
          at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:436)
          at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:384)
          at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
          at java.lang.Thread.run(Thread.java:619)

        Locked ownable synchronizers:

        • None

        -================================

        "ajp-10.31.152.202-8009-133" daemon prio=10 tid=0x00002aab60d8a800 nid=0x116b waiting for monitor entry [0x000000006840c000]
        java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:201)

        • locked <0x000000078006acc0> (a org.apache.log4j.spi.RootLogger)
          at org.apache.log4j.Category.forcedLog(Category.java:388)
          at org.apache.log4j.Category.log(Category.java:853)
          at org.jboss.logging.log4j.Log4jLoggerPlugin.info(Log4jLoggerPlugin.java:184)
          at org.jboss.logging.Logger.info(Logger.java:296)
          at org.apache.catalina.valves.RequestDumperValve.invoke(RequestDumperValve.java:118)
          at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
          at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
          at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:436)
          at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:384)
          at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
          at java.lang.Thread.run(Thread.java:619)

        Locked ownable synchronizers:

        • None
        Show
        Giri Kosuru added a comment - Hi Ralph, Thanks for quick response. Yes we have 64 bit JVM with -server flag. I probably have give little more details. The same application with and without LOG4J2 on the same servers has been load tested, while troubleshooting this issue. Under 500 concurrent users (with 4 jboss standalone nodes) we got 308 TPS with LOG4J_1.2.14. On exactly same settings, same application with LOG4J2, we got 240 TPS, with little higher response times and with higher variations on TPS and response times. What we observed was, 1) Swapping happening only when we run LOG4J2 tests. 2) Added few more memory to the system ( 6 + 4 GB total) and the swapping has gone. 3) Observed iowaits upto 2 - 25%. on on average iowait is 12% probably and is consistent, when swapping was occurring. I still have iowait after adding memory, but not as bad, but still considerable, when compared to log4j_1.2.14. 4) With log4j_1.2.14, we had bufferedIO=true and immediateFLush=false too. JVM startup parameters are as follows: java -Dprogram.name=run.sh -server -Dorg.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH=true -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/myroot/my/server/mynode/log/run.gc.log -XX:MaxDirectMemorySize=64g -Dcom.tc.productkey.path=/myroot/my/server/terracotta_client/conf/terracotta-license.key -XX:+UseParallelOldGC -XX:+UseCompressedOops -Xms2048m -Xmx2048m -XX:MaxPermSize=512m -Dorg.jboss.resolver.warning=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Dfile.encoding=UTF-8 -Dorg.apache.catalina.STRICT_SERVLET_COMPLIANCE=true -Dorg.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH=true -Dorg.apache.catalina.connector.CoyoteAdapter.ALLOW_BACKSLASH=true-Djava.net.preferIPv4Stack=true -Djava.endorsed.dirs=/opt/myserver/lib/endorsed -classpath /myroot/myserver/bin/run.jar org.jboss.Main -c mynode -b 192.86.67.123 I saw few other bugs in JIRA and some suggestions for those bugs. Based on those I am thinking I may need to try -DAsyncLogger.RingBufferSize=1024 -Dlog4j2.status.entries=1 Will run the test with those flags and will update. Mean while please suggest your thoughts and will apply them in the test. Also I took some thread dumps and saw some threads BLOCKED. It is interesting to see blocks at org.apache.log4j.Category.callAppenders Here is the thread dump. "ajp-10.31.152.202-8009-230" daemon prio=10 tid=0x00002aab616a2000 nid=0x134e waiting for monitor entry [0x0000000075fe6000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.log4j.Category.callAppenders(Category.java:201) waiting to lock <0x000000078006acc0> (a org.apache.log4j.spi.RootLogger) at org.apache.log4j.Category.forcedLog(Category.java:388) at org.apache.log4j.Category.log(Category.java:853) at org.apache.cxf.common.logging.Log4jLogger.internalLogFormatted(Log4jLogger.java:114) at org.apache.cxf.common.logging.AbstractDelegatingLogger.internalLog(AbstractDelegatingLogger.java:333) at org.apache.cxf.common.logging.AbstractDelegatingLogger.doLog(AbstractDelegatingLogger.java:315) at org.apache.cxf.common.logging.AbstractDelegatingLogger.info(AbstractDelegatingLogger.java:237) at org.apache.cxf.interceptor.LoggingInInterceptor.logging(LoggingInInterceptor.java:208) at org.apache.cxf.interceptor.LoggingInInterceptor.handleMessage(LoggingInInterceptor.java:98) at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:243) locked <0x00000007d558ece0> (a org.apache.cxf.phase.PhaseInterceptorChain) at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:111) at org.apache.cxf.transport.servlet.ServletDestination.invoke(ServletDestination.java:99) at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:431) at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:147) at org.apache.cxf.transport.servlet.AbstractCXFServlet.invoke(AbstractCXFServlet.java:148) at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:179) at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:108) at javax.servlet.http.HttpServlet.service(HttpServlet.java:617) at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:159) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX (Our application specific class and package) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.logging.log4j.core.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:66) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:190) at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:92) at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126) at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:567) at org.apache.catalina.valves.RequestDumperValve.invoke(RequestDumperValve.java:151) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330) at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:436) at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:384) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) Locked ownable synchronizers: None -================================ "ajp-10.31.152.202-8009-133" daemon prio=10 tid=0x00002aab60d8a800 nid=0x116b waiting for monitor entry [0x000000006840c000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.log4j.Category.callAppenders(Category.java:201) locked <0x000000078006acc0> (a org.apache.log4j.spi.RootLogger) at org.apache.log4j.Category.forcedLog(Category.java:388) at org.apache.log4j.Category.log(Category.java:853) at org.jboss.logging.log4j.Log4jLoggerPlugin.info(Log4jLoggerPlugin.java:184) at org.jboss.logging.Logger.info(Logger.java:296) at org.apache.catalina.valves.RequestDumperValve.invoke(RequestDumperValve.java:118) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330) at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:436) at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:384) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) Locked ownable synchronizers: None
        Hide
        Remko Popma added a comment -

        Giri, in addition to Ralph's questions, can I exclude some possibilities first:

        • Were there any other changes to the system other than the migration to log4j2? (Unrelated code changes, different memory or GC settings, other system property changes?)
        • You mentioned you are running on a virtual machine (I assume VMWare or KVM or something like that). Are you sharing the box with other applications? Can you exclude the possibility that the poor performance you are seeing is caused by other applications using more CPU/memory on the shared box because they changed recently?

        About the config:

        • Are you using async loggers (for example by setting -DLog4jContextSelector =org.apache.logging.log4j.core.async.AsyncLoggerContextSelector) ?
        • Assuming the answer to the previous question was no, the configuration is to have the root logger sending to an AsyncAppender. The AsyncAppender does not perform as well as Async Loggers, especially in multi-threaded scenarios. Can you give Async Loggers a try?
        • Also in the current config, three named loggers are logging synchronously to the RandomAccessFile Appender. This may cause lock contention if many threads try to add to the same buffer at the same time. They also seem to log to the same file used by the root logger, so you will get the same result as simply logging everything through the root logger. Can we try removing the named loggers? (We can add them back later after the performance issue is resolved.)
        • The current config logs the same information twice: the AsyncAppender logs to both the "APP_1066_LOG" RandomAccessFile Appender and the "hibernateAppender" RandomAccessFile Appender. I could not see any difference in the configuration for these two. Could one of them be removed? That should cut the I/O in half.

        Taking all of the above into account, can you try again with async loggers (set system property -DLog4jContextSelector =org.apache.logging.log4j.core.async.AsyncLoggerContextSelector) and the simplified config below:

        <?xml version="1.0" encoding="UTF-8"?>
        <configuration status="trace" >
          <appenders>
            <RollingRandomAccessFile name="fileAppender" fileName=“/path/to/log/anotherfile-1066.log" filePattern=“/path/to/log/anotherfile-1066.log.%i" append="true" immediateFlush="false">
              <PatternLayout>
                <pattern>%d{ISO8601} %-5p [%t]: [%c{1}] %m%n - %X{ElapsedTime}-%X{ByteSize}- %X{uniqueID}-%X{HttpMethod}-%X{Host}-%X{URL}-%X{ClientIP}-%X{NodeID}-%X{NodeUserID}-%X{HttpCode}-%X{ApplicationCode}</pattern>
              </PatternLayout>
              <Policies>
                <SizeBasedTriggeringPolicy size="250 MB"/>
              </Policies>
              <DefaultRolloverStrategy max="10"/>
            </RollingRandomAccessFile>
          </appenders>
          <loggers>
            <root level="INFO">
              <appender-ref ref="fileAppender"/>
            </root>
          </loggers>
        </configuration>
        
        Show
        Remko Popma added a comment - Giri, in addition to Ralph's questions, can I exclude some possibilities first: Were there any other changes to the system other than the migration to log4j2? (Unrelated code changes, different memory or GC settings, other system property changes?) You mentioned you are running on a virtual machine (I assume VMWare or KVM or something like that). Are you sharing the box with other applications? Can you exclude the possibility that the poor performance you are seeing is caused by other applications using more CPU/memory on the shared box because they changed recently? About the config: Are you using async loggers (for example by setting -DLog4jContextSelector =org.apache.logging.log4j.core.async.AsyncLoggerContextSelector ) ? Assuming the answer to the previous question was no, the configuration is to have the root logger sending to an AsyncAppender. The AsyncAppender does not perform as well as Async Loggers, especially in multi-threaded scenarios. Can you give Async Loggers a try? Also in the current config, three named loggers are logging synchronously to the RandomAccessFile Appender. This may cause lock contention if many threads try to add to the same buffer at the same time. They also seem to log to the same file used by the root logger, so you will get the same result as simply logging everything through the root logger. Can we try removing the named loggers? (We can add them back later after the performance issue is resolved.) The current config logs the same information twice: the AsyncAppender logs to both the "APP_1066_LOG" RandomAccessFile Appender and the "hibernateAppender" RandomAccessFile Appender. I could not see any difference in the configuration for these two. Could one of them be removed? That should cut the I/O in half. Taking all of the above into account, can you try again with async loggers (set system property -DLog4jContextSelector =org.apache.logging.log4j.core.async.AsyncLoggerContextSelector ) and the simplified config below: <?xml version= "1.0" encoding= "UTF-8" ?> <configuration status= "trace" > <appenders> <RollingRandomAccessFile name= "fileAppender" fileName=“/path/to/log/anotherfile-1066.log " filePattern=“/path/to/log/anotherfile-1066.log.%i" append= " true " immediateFlush= " false " > <PatternLayout> <pattern>%d{ISO8601} %-5p [%t]: [%c{1}] %m%n - %X{ElapsedTime}-%X{ByteSize}- %X{uniqueID}-%X{HttpMethod}-%X{Host}-%X{URL}-%X{ClientIP}-%X{NodeID}-%X{NodeUserID}-%X{HttpCode}-%X{ApplicationCode}</pattern> </PatternLayout> <Policies> <SizeBasedTriggeringPolicy size= "250 MB" /> </Policies> <DefaultRolloverStrategy max= "10" /> </RollingRandomAccessFile> </appenders> <loggers> <root level= "INFO" > <appender-ref ref= "fileAppender" /> </root> </loggers> </configuration>
        Hide
        Giri Kosuru added a comment -

        Our project is a CXF,Spring,Hibernate heavy project. CXF has been instructed to use log4j through flag "META-INF/cxf/org.apache.cxf.Logger".

        Show
        Giri Kosuru added a comment - Our project is a CXF,Spring,Hibernate heavy project. CXF has been instructed to use log4j through flag "META-INF/cxf/org.apache.cxf.Logger".
        Hide
        Remko Popma added a comment -

        Giri, looks like my response crossed your reply to Ralph's questions.
        Thanks for posting your system properties. This confirms that with the current config you were not using async loggers yet.
        Also, please use the default ringbuffer size when first trying async loggers. (We can experiment with changing various settings later.)

        Show
        Remko Popma added a comment - Giri, looks like my response crossed your reply to Ralph's questions. Thanks for posting your system properties. This confirms that with the current config you were not using async loggers yet. Also, please use the default ringbuffer size when first trying async loggers. (We can experiment with changing various settings later.)
        Hide
        Remko Popma added a comment -

        Actually, looking at the stack traces, I don't see any log4j version 2.0 classes, only version 1.2...
        There is some classpath misconfiguration; you are using log4j-1.2 at the moment.

        Show
        Remko Popma added a comment - Actually, looking at the stack traces, I don't see any log4j version 2.0 classes, only version 1.2... There is some classpath misconfiguration; you are using log4j-1.2 at the moment.
        Hide
        Giri Kosuru added a comment -

        Remko,

        Great. Thanks for through review of the settings. I am going to put all your suggestions and run the test.

        I have two WAR files deployed to the server. They share one JAR file at parent Class Loader. But to make things simple, I am woking with only one WAR for now, until problem is fixed. The thread dump, i put here probably might taken when those two application were deployed etc ...
        But as per your observation, I will try to make sure we use LOG4J2 jars. (We packed them in WEB-INF/lib). Application server still uses log4j1.2 and obviously it is loaded by App Server and may be parent of our application class loader.

        Will test in the morning and get back to you soon.

        Thanks
        Giri Kosuru

        Show
        Giri Kosuru added a comment - Remko, Great. Thanks for through review of the settings. I am going to put all your suggestions and run the test. I have two WAR files deployed to the server. They share one JAR file at parent Class Loader. But to make things simple, I am woking with only one WAR for now, until problem is fixed. The thread dump, i put here probably might taken when those two application were deployed etc ... But as per your observation, I will try to make sure we use LOG4J2 jars. (We packed them in WEB-INF/lib). Application server still uses log4j1.2 and obviously it is loaded by App Server and may be parent of our application class loader. Will test in the morning and get back to you soon. Thanks Giri Kosuru
        Hide
        Remko Popma added a comment -

        I had a quick look at the CXF documentation but I don't think CXF can use log4j-2.0 (only log4j-1.2 as far as I can see).

        In your configuration you have configuration status="trace". This is convenient: log4j2 will print information to System.out describing which loggers and appenders were configured and any errors that were encountered. Please carefully check that configuration completed successfully.

        (BTW, from tomorrow I'll be travelling for two days and may not have internet connectivity.)

        Show
        Remko Popma added a comment - I had a quick look at the CXF documentation but I don't think CXF can use log4j-2.0 (only log4j-1.2 as far as I can see). In your configuration you have configuration status="trace" . This is convenient: log4j2 will print information to System.out describing which loggers and appenders were configured and any errors that were encountered. Please carefully check that configuration completed successfully. (BTW, from tomorrow I'll be travelling for two days and may not have internet connectivity.)
        Hide
        Remko Popma added a comment -

        Also, in your system properties you have start heap size and max heap size = 2 GB. I don't know the characteristics of your application, but this does not seem very much...

        (EDIT) I just saw that you tried increasing start/max heap size and this solved the swapping problem. Good to hear that.

        Show
        Remko Popma added a comment - Also, in your system properties you have start heap size and max heap size = 2 GB. I don't know the characteristics of your application, but this does not seem very much... (EDIT) I just saw that you tried increasing start/max heap size and this solved the swapping problem. Good to hear that.
        Hide
        Giri Kosuru added a comment -

        Also I have Spring framework version 3.0.1. Looks like it has dependency on "slf4j-log4j12-1.5.8.jar" . Is there any way we can we force spring to use log4j2 ? We use ANT and don't use Maven.

        Show
        Giri Kosuru added a comment - Also I have Spring framework version 3.0.1. Looks like it has dependency on "slf4j-log4j12-1.5.8.jar" . Is there any way we can we force spring to use log4j2 ? We use ANT and don't use Maven.
        Hide
        Remko Popma added a comment -

        If your application uses the SLF4J logging API, you can route the actual logging to log4j2 by including the correct jar files.
        Details are here: http://logging.apache.org/log4j/2.x/faq.html#which_jars

        Show
        Remko Popma added a comment - If your application uses the SLF4J logging API, you can route the actual logging to log4j2 by including the correct jar files. Details are here: http://logging.apache.org/log4j/2.x/faq.html#which_jars
        Hide
        Ralph Goers added a comment - - edited

        If you have a log4j 1.2 jar in the parent class loader then there is no way to prevent CXF from using it unless you put log4j 2 in the parent class loader along with log4j-1.2-api.jar from Log4j 2 and completely remove the log4j 1.2 jar.

        Although I believe Remko has performance test that show that the RandomAccessFileAppender is faster than the RollingFileAppender, you still might want to try using that to determine if the locking Remko mentions is causing any problems for you. However, if you are seeing lots of I/O waits that is more a sign of I/O contention, not lock contention. Still, since you are probably writing to an NFS mount the differences in how these Appenders work might be impacted differently.

        You might also try adjusting the buffer size on the RandomAccessFileAppender. The default buffer size is 256K. RollingFileAppender uses a buffer size of 8K (which is currently not configurable - interestingly it is in a normal FileAppender).

        As for swapping and system memory usage, you would need to look at the output from top to determine what processes are using the memory. If you have processes that in total are being given more memory than the server physically has then you should expect to see swapping based on what each application is doing.

        Show
        Ralph Goers added a comment - - edited If you have a log4j 1.2 jar in the parent class loader then there is no way to prevent CXF from using it unless you put log4j 2 in the parent class loader along with log4j-1.2-api.jar from Log4j 2 and completely remove the log4j 1.2 jar. Although I believe Remko has performance test that show that the RandomAccessFileAppender is faster than the RollingFileAppender, you still might want to try using that to determine if the locking Remko mentions is causing any problems for you. However, if you are seeing lots of I/O waits that is more a sign of I/O contention, not lock contention. Still, since you are probably writing to an NFS mount the differences in how these Appenders work might be impacted differently. You might also try adjusting the buffer size on the RandomAccessFileAppender. The default buffer size is 256K. RollingFileAppender uses a buffer size of 8K (which is currently not configurable - interestingly it is in a normal FileAppender). As for swapping and system memory usage, you would need to look at the output from top to determine what processes are using the memory. If you have processes that in total are being given more memory than the server physically has then you should expect to see swapping based on what each application is doing.
        Hide
        Mark Struberg added a comment -

        you could also do a few kill -3 (forced process dump) quickly after each other and then look at what methods you are stuck in often. That might give you a hint as well.

        Show
        Mark Struberg added a comment - you could also do a few kill -3 (forced process dump) quickly after each other and then look at what methods you are stuck in often. That might give you a hint as well.
        Hide
        Remko Popma added a comment - - edited

        Giri, how did things work out?

        Show
        Remko Popma added a comment - - edited Giri, how did things work out?
        Hide
        Giri Kosuru added a comment -

        Hi Remco,

        Sorry for getting back late. Got little busy with our release schedules and tests. Followed your recommendations and saw good gains in performance numbers (Up to 20 % gain in performance, particularly TPS). Here is what I did as per your suggestion.

        1) Started using Asynchronous Loggers.The following are the system properties used. RingBufferSize of 20480 gave me good performance improvement. Default size didn't give me good performance numbers. Due to time limits I didn't do much playing around with these numbers.

        -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -DAsyncLogger.RingBufferSize=20480 -Dlog4j2.status.entries=1

        2) My log4j2.xml file is as follows.

        <?xml version="1.0" encoding="UTF-8"?>
        <configuration status="trace">
        <appenders>
        <RollingRandomAccessFile name="XXXX_LOG" fileName="/path/to/log/xxxx.log" filePattern="/path/to/log/xxx.log.%i" append="true" immediateFlush="true">
        <PatternLayout>
        <pattern>%d

        {ISO8601}

        %-5p [%t]: [%c

        {1}

        ] %m%n - %X

        {ElapsedTime}

        -%X

        {ByteSize}

        - %X

        {uniqueID}

        -%X

        {HttpMethod}

        -%X

        {Host}

        -%X

        {URL}

        -%X

        {ClientIP}

        -%X

        {NodeID}

        -%X

        {NodeUserID}

        -%X

        {HttpCode}

        -%X

        {xxxxAttribute}

        </pattern>
        </PatternLayout>
        <Policies>
        <SizeBasedTriggeringPolicy size="250 MB"/>
        </Policies>
        <DefaultRolloverStrategy max="10"/>
        </RollingRandomAccessFile>
        </appenders>
        <loggers>
        <root level="debug">
        <appender-ref ref="XXXX_LOG"/>
        </root>
        </loggers>
        </configuration>

        I think those two changes gave me what we need.

        Now coming to the over all experience with LOG4J2, I feel it should have been better. Particularly in an application where we have all these open source components involved (Spring, CXF, Hibernate). I think these components are CORE for any open source, J2EE application. As Ralph pointed out, I am not sure if any of the components are still using Log4j 1 jars, which are loaded by JBoss parent class loader. I, probably not immediately ready, to experiment forcing JBoss to use Log4J2, due to project timelines.

        Is there a way for me to figure out which Log4j (1.2 or 2.0) JARs are used by Spring and CXF with-in my application ?

        I still have few more tests to conduct on our TEST environment. We probably do it tomorrow. I can give you confirmed feed back about the performance gains, after those tests.

        Also, we deploy 2 WAR files to the server and I saw some of the logs are written to other WAR's log files. But I will confirm this behavior once I do more tests.

        Though my experience of migrating to LOG4J2 is little bitter (I ended up rolling back my changes from code repository twice before, due to multiple reasons), the performance numbers, made me feel, it is worth going through the pains.

        Again thanks for all your support and help.

        Show
        Giri Kosuru added a comment - Hi Remco, Sorry for getting back late. Got little busy with our release schedules and tests. Followed your recommendations and saw good gains in performance numbers (Up to 20 % gain in performance, particularly TPS). Here is what I did as per your suggestion. 1) Started using Asynchronous Loggers.The following are the system properties used. RingBufferSize of 20480 gave me good performance improvement. Default size didn't give me good performance numbers. Due to time limits I didn't do much playing around with these numbers. -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector -DAsyncLogger.RingBufferSize=20480 -Dlog4j2.status.entries=1 2) My log4j2.xml file is as follows. <?xml version="1.0" encoding="UTF-8"?> <configuration status="trace"> <appenders> <RollingRandomAccessFile name="XXXX_LOG" fileName="/path/to/log/xxxx.log" filePattern="/path/to/log/xxx.log.%i" append="true" immediateFlush="true"> <PatternLayout> <pattern>%d {ISO8601} %-5p [%t] : [%c {1} ] %m%n - %X {ElapsedTime} -%X {ByteSize} - %X {uniqueID} -%X {HttpMethod} -%X {Host} -%X {URL} -%X {ClientIP} -%X {NodeID} -%X {NodeUserID} -%X {HttpCode} -%X {xxxxAttribute} </pattern> </PatternLayout> <Policies> <SizeBasedTriggeringPolicy size="250 MB"/> </Policies> <DefaultRolloverStrategy max="10"/> </RollingRandomAccessFile> </appenders> <loggers> <root level="debug"> <appender-ref ref="XXXX_LOG"/> </root> </loggers> </configuration> I think those two changes gave me what we need. Now coming to the over all experience with LOG4J2, I feel it should have been better. Particularly in an application where we have all these open source components involved (Spring, CXF, Hibernate). I think these components are CORE for any open source, J2EE application. As Ralph pointed out, I am not sure if any of the components are still using Log4j 1 jars, which are loaded by JBoss parent class loader. I, probably not immediately ready, to experiment forcing JBoss to use Log4J2, due to project timelines. Is there a way for me to figure out which Log4j (1.2 or 2.0) JARs are used by Spring and CXF with-in my application ? I still have few more tests to conduct on our TEST environment. We probably do it tomorrow. I can give you confirmed feed back about the performance gains, after those tests. Also, we deploy 2 WAR files to the server and I saw some of the logs are written to other WAR's log files. But I will confirm this behavior once I do more tests. Though my experience of migrating to LOG4J2 is little bitter (I ended up rolling back my changes from code repository twice before, due to multiple reasons), the performance numbers, made me feel, it is worth going through the pains. Again thanks for all your support and help.
        Hide
        Remko Popma added a comment -

        Giri,
        Thanks for your feedback.
        Based on your comment, I will mark this issue as resolved.
        Please re-open if there is still an unresolved issue, or close if you are ok with the current solution.

        Show
        Remko Popma added a comment - Giri, Thanks for your feedback. Based on your comment, I will mark this issue as resolved. Please re-open if there is still an unresolved issue, or close if you are ok with the current solution.

          People

          • Assignee:
            Unassigned
            Reporter:
            Giri Kosuru
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development