[
https://issues.apache.org/jira/browse/LOG4J2-437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13806028#comment-13806028
]
Giri Kosuru commented on LOG4J2-437:
------------------------------------
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
> Log4J2 Performs poorly with 500 concurrent users with Jboss 5.1.GA and JDK 6
> ----------------------------------------------------------------------------
>
> Key: LOG4J2-437
> URL: https://issues.apache.org/jira/browse/LOG4J2-437
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.0-beta9
> 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)
> Reporter: Giri Kosuru
> Priority: Critical
> Labels: Performance
>
> 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.
> {code}
> <?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>
> {code}
--
This message was sent by Atlassian JIRA
(v6.1#6144)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
