CPU (threads) at 100%, Tomcat sockets in CLOSE_WAIT
Hello,
I was happily testing our Jboss-hosted app today which is hosted on a Quad-Core IBM x3550 running Fedora Core 6 (2.6.18-1.2798.fc6) with a fairly recent Sun JVM for Linux "Java HotSpot(TM) Server VM (build 1.5.0_10-b03, mixed mode)". We started JBoss 4.2.1GA and I was load testing our site over Tomcat interface http//server:8080 with a browser test tool. After the test completed, I noticed 2 of my 4 cores were stuck at 100% utilization each.
[root@devjb12 log]# top
top - 11:47:31 up 14 days, 19:31, 2 users, load average: 2.10, 2.03, 1.49
Tasks: 90 total, 1 running, 89 sleeping, 0 stopped, 0 zombie
Cpu0 : 0.0%us, 0.0%sy, 0.0%ni,100.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu1 :100.0%us, 0.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu2 : 0.0%us, 0.0%sy, 0.0%ni, 99.3%id, 0.7%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu3 :100.0%us, 0.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 3107224k total, 2783312k used, 323912k free, 220592k buffers
Swap: 2031608k total, 0k used, 2031608k free, 1224688k cached
Correlating "ps" info with Linux thread ID's and the Java thread dump shows me that the threads spinning out of control are:
"http-0.0.0.0-8080-14" daemon prio=1 tid=0x09a33b40 nid=0x5903 runnable [0x58ffd000..0x58ffef30]
"http-0.0.0.0-8080-3" daemon prio=1 tid=0x092958c0 nid=0x46d1 runnable [0x5c6e6000..0x5c6e7db0]
The dump file shows these two (-3 and -14) look very unlike the other http-0.0.0.0-8080-## threads:
"http-0.0.0.0-8080-14" daemon prio=1 tid=0x09a33b40 nid=0x5903 runnable [0x58ffd000..0x58ffef30]
at java.util.HashMap.put(HashMap.java:420)
at com.tracker.web.servlet.SessionCounter.sessionCreated(SessionCounter.java:19)
at org.apache.catalina.session.StandardSession.tellNew(StandardSession.java:397)
at org.apache.catalina.session.StandardSession.setId(StandardSession.java:369)
at org.jboss.web.tomcat.service.session.ClusteredSession.setId(ClusteredSession.java:1040)
at org.jboss.web.tomcat.service.session.JBossCacheManager.createSession(JBossCacheManager.java:609)
at org.apache.catalina.connector.Request.doGetSession(Request.java:2293)
at org.apache.catalina.connector.Request.getSession(Request.java:2066)
at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:833)
at org.apache.tapestry.web.ServletWebRequest.getSession(ServletWebRequest.java:82)
at $WebRequest_11784a0bc35.getSession($WebRequest_11784a0bc35.java)
at $WebRequest_11784a0bbe9.getSession($WebRequest_11784a0bbe9.java)
at org.apache.tapestry.engine.state.SessionScopeManager.getSession(SessionScopeManager.java:48)
at org.apache.tapestry.engine.state.SessionScopeManager.get(SessionScopeManager.java:64)
at $StateObjectPersistenceManager_11784a0bd0f.get($StateObjectPersistenceManager_11784a0bd0f.java)
at org.apache.tapestry.engine.state.StateObjectManagerImpl.get(StateObjectManagerImpl.java:50)
at org.apache.tapestry.engine.state.ApplicationStateManagerImpl.get(ApplicationStateManagerImpl.java:60)
at $ApplicationStateManager_11784a0bbbf.get($ApplicationStateManager_11784a0bbbf.java)
at $ApplicationStateManager_11784a0bbc0.get($ApplicationStateManager_11784a0bbc0.java)
at $PatientInformation_14.getUserSession($PatientInformation_14.java)
at com.tracker.web.action.AuthenticationRequiredPage.pageValidate(AuthenticationRequiredPage.java:34)
at org.apache.tapestry.AbstractPage.firePageValidate(AbstractPage.java:585)
at org.apache.tapestry.AbstractPage.validate(AbstractPage.java:307)
at org.apache.tapestry.engine.RequestCycle.activate(RequestCycle.java:625)
at org.apache.tapestry.engine.DirectService.service(DirectService.java:99)
at $IEngineService_11784a0bc48.service($IEngineService_11784a0bc48.java)
at org.apache.tapestry.services.impl.EngineServiceOuterProxy.service(EngineServiceOuterProxy.java:66)
at org.apache.tapestry.engine.AbstractEngine.service(AbstractEngine.java:248)
at org.apache.tapestry.services.impl.InvokeEngineTerminator.service(InvokeEngineTerminator.java:60)
at $WebRequestServicer_11784a0bc24.service($WebRequestServicer_11784a0bc24.java)
at $WebRequestServicer_11784a0bc20.service($WebRequestServicer_11784a0bc20.java)
at org.apache.tapestry.services.impl.WebRequestServicerPipelineBridge.service(WebRequestServicerPipelineBridge.java:56)
at $ServletRequestServicer_11784a0bc03.service($ServletRequestServicer_11784a0bc03.java)
at org.apache.tapestry.request.DecodedRequestInjector.service(DecodedRequestInjector.java:55)
at $ServletRequestServicerFilter_11784a0bbff.service($ServletRequestServicerFilter_11784a0bbff.java)
at $ServletRequestServicer_11784a0bc05.service($ServletRequestServicer_11784a0bc05.java)
at com.carmanconsulting.tapernate.filter.TapernateFilter.serviceOnce(TapernateFilter.java:110)
at com.carmanconsulting.tapernate.filter.OncePerServletRequestServicerFilter.service(OncePerServletRequestServicerFilter.java:23)
at $ServletRequestServicerFilter_11784a0bbfd.service($ServletRequestServicerFilter_11784a0bbfd.java)
at $ServletRequestServicer_11784a0bc05.service($ServletRequestServicer_11784a0bc05.java)
at org.apache.tapestry.multipart.MultipartDecoderFilter.service(MultipartDecoderFilter.java:52)
at $ServletRequestServicerFilter_11784a0bbfb.service($ServletRequestServicerFilter_11784a0bbfb.java)
at $ServletRequestServicer_11784a0bc05.service($ServletRequestServicer_11784a0bc05.java)
at org.apache.tapestry.services.impl.SetupRequestEncoding.service(SetupRequestEncoding.java:53)
at $ServletRequestServicerFilter_11784a0bc01.service($ServletRequestServicerFilter_11784a0bc01.java)
at $ServletRequestServicer_11784a0bc05.service($ServletRequestServicer_11784a0bc05.java)
at $ServletRequestServicer_11784a0bbf5.service($ServletRequestServicer_11784a0bbf5.java)
at org.apache.tapestry.ApplicationServlet.doService(ApplicationServlet.java:123)
at org.apache.tapestry.ApplicationServlet.doPost(ApplicationServlet.java:168)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.tracker.service.impl.TimeServiceImpl$ResetTimeServiceFilter.doFilterInternal(TimeServiceImpl.java:133)
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.tapestry.RedirectFilter.doFilter(RedirectFilter.java:103)
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:230)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:179)
at org.jboss.web.tomcat.service.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:87)
at org.jboss.web.tomcat.service.session.JvmRouteValve.invoke(JvmRouteValve.java:84)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:433)
at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:241)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:580)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:595)
"http-0.0.0.0-8080-13" daemon prio=1 tid=0x0948cf80 nid=0x5902 in Object.wait() [0x593fa000..0x593faeb0]
at java.lang.Object.wait(Native Method)
- waiting on <0x77cec2b0> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
at java.lang.Object.wait(Object.java:474)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416)
- locked <0x77cec2b0> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442)
at java.lang.Thread.run(Thread.java:595)
"http-0.0.0.0-8080-12" daemon prio=1 tid=0x09691fe0 nid=0x5901 in Object.wait() [0x599fe000..0x599fee30]
at java.lang.Object.wait(Native Method)
- waiting on <0x77cec338> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
at java.lang.Object.wait(Object.java:474)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416)
- locked <0x77cec338> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442)
at java.lang.Thread.run(Thread.java:595)
etc.... One unhappy thread and two "normal" idle threads among others....
Now, I do have two sockets lingering on CLOSE_WAIT (dell420 is the system I launched the browser test client from).
[root@devjb12 ipv4]# lsof|grep webcache
java 8799 javauser 62u IPv4 1416460 TCP *:webcache (LISTEN)
java 8799 javauser 116u IPv4 1490728 TCP devjb12:webcache->dell420:alarm-clock-s (CLOSE_WAIT)
java 8799 javauser 145u IPv4 1490721 TCP devjb12:webcache->dell420:gcmonitor (CLOSE_WAIT)
[root@devjb12 ipv4]# netstat -an | grep :8080
tcp 0 0 0.0.0.0:8080 0.0.0.0:* LISTEN
tcp 1 0 10.20.0.28:8080 10.20.10.66:2667 CLOSE_WAIT
tcp 1 0 10.20.0.28:8080 10.20.10.66:2660 CLOSE_WAIT
My suspicions are that the CLOSE_WAITs are related the CPU to run off. In an hour or so, the /proc/sys/net/ipv4/tcp_keepalive_time of 7200 seconds will pass and the system will forget about the sockets and we'll see if Tomcat and the system as a whole calms down too.
Any ideas? I'll followup as things progress, as I said, I should see calm in another 30 minutes...
Thanks,
-Gary
