Seam app hangs under heavy load (InUseConnectionCount goes very high)
demetrio812 Jan 16, 2011 8:26 PMHello,
I've just add a bad day with an app under load: it worked normally but at a certain point (after 2-30 mins) the InUseConnectionCount raise from 10 to 150 and more and the application hangs.
The thread dump shows a lot of threads BLOCKED:
Thread: http-213.175.203.190-80-106 : priority:5, demon:true, threadId:185, threadState:BLOCKED, lockName:java.util.WeakHashMap@1a0247f org.jboss.resource.connectionmanager.CachedConnectionManager.unregisterConnection(CachedConnectionManager.java:318) org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener.connectionClosed(TxConnectionManager.java:637) org.jboss.resource.adapter.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:363) org.jboss.resource.adapter.jdbc.WrappedConnection.close(WrappedConnection.java:155) org.hibernate.connection.DatasourceConnectionProvider.closeConnection(DatasourceConnectionProvider.java:97) org.hibernate.jdbc.ConnectionManager.closeConnection(ConnectionManager.java:474) org.hibernate.jdbc.ConnectionManager.aggressiveRelease(ConnectionManager.java:429) org.hibernate.jdbc.ConnectionManager.afterStatement(ConnectionManager.java:304) org.hibernate.jdbc.AbstractBatcher.closePreparedStatement(AbstractBatcher.java:572) org.hibernate.jdbc.AbstractBatcher.closeStatement(AbstractBatcher.java:291) org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:307) org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:234) org.hibernate.loader.Loader.doQuery(Loader.java:749) org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259) org.hibernate.loader.Loader.doList(Loader.java:2228) org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2125) org.hibernate.loader.Loader.list(Loader.java:2120) org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:401) org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:361) org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196) org.hibernate.impl.SessionImpl.list(SessionImpl.java:1148) org.hibernate.impl.QueryImpl.list(QueryImpl.java:102) org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:67) it.novaware.sn.core.modules.privateMessage.PrivateMessagesListHelper.getConversationRecipientList(PrivateMessagesListHelper.java:188) sun.reflect.GeneratedMethodAccessor1152.invoke(Unknown Source) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) java.lang.reflect.Method.invoke(Method.java:597) org.jboss.seam.util.Reflections.invoke(Reflections.java:22) org.jboss.seam.intercept.RootInvocationContext.proceed(RootInvocationContext.java:32) org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:56) org.jboss.seam.transaction.RollbackInterceptor.aroundInvoke(RollbackInterceptor.java:28) org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) org.jboss.seam.core.BijectionInterceptor.aroundInvoke(BijectionInterceptor.java:77) org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) org.jboss.seam.core.MethodContextInterceptor.aroundInvoke(MethodContextInterceptor.java:44) org.jboss.seam.intercept.SeamInvocationContext.proceed(SeamInvocationContext.java:68) org.jboss.seam.intercept.RootInterceptor.invoke(RootInterceptor.java:107) org.jboss.seam.intercept.JavaBeanInterceptor.interceptInvocation(JavaBeanInterceptor.java:185) org.jboss.seam.intercept.JavaBeanInterceptor.invoke(JavaBeanInterceptor.java:103) it.novaware.sn.core.modules.privateMessage.PrivateMessagesListHelper_$$_javassist_seam_53.getConversationRecipientList(PrivateMessagesListHelper_$$_javassist_seam_53.java) sun.reflect.GeneratedMethodAccessor1151.invoke(Unknown Source) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) java.lang.reflect.Method.invoke(Method.java:597) org.jboss.el.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:335) org.jboss.el.util.ReflectionUtil.invokeMethod(ReflectionUtil.java:280) org.jboss.el.parser.AstMethodSuffix.getValue(AstMethodSuffix.java:59) org.jboss.el.parser.AstValue.getValue(AstValue.java:67) org.jboss.el.parser.AstEqual.getValue(AstEqual.java:21) org.jboss.el.parser.AstChoice.getValue(AstChoice.java:27) org.jboss.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:186) com.sun.facelets.el.TagValueExpression.getValue(TagValueExpression.java:71) org.richfaces.component.html.HtmlColumn.getWidth(HtmlColumn.java:808) sun.reflect.GeneratedMethodAccessor1162.invoke(Unknown Source) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) java.lang.reflect.Method.invoke(Method.java:597) javax.faces.component.UIComponentBase$AttributesMap.get(UIComponentBase.java:1585) org.ajax4jsf.renderkit.RendererUtils.encodePassThruAttribute(RendererUtils.java:397) org.ajax4jsf.renderkit.RendererUtils.encodeAttributesFromArray(RendererUtils.java:417) org.richfaces.renderkit.CellRenderer.doEncodeBegin(CellRenderer.java:80) org.ajax4jsf.renderkit.RendererBase.encodeBegin(RendererBase.java:100) javax.faces.component.UIComponentBase.encodeBegin(UIComponentBase.java:813) org.ajax4jsf.renderkit.RendererBase.renderChild(RendererBase.java:275) org.richfaces.renderkit.AbstractRowsRenderer.encodeCellChildren(AbstractRowsRenderer.java:288) org.richfaces.renderkit.AbstractTableRenderer.encodeOneRow(AbstractTableRenderer.java:391) org.richfaces.renderkit.AbstractRowsRenderer.process(AbstractRowsRenderer.java:83) org.ajax4jsf.model.SequenceDataModel.walk(SequenceDataModel.java:101) org.ajax4jsf.component.UIDataAdaptorBase.walk(UIDataAdaptorBase.java:1156) org.richfaces.renderkit.AbstractRowsRenderer.encodeRows(AbstractRowsRenderer.java:104) org.richfaces.renderkit.AbstractRowsRenderer.encodeRows(AbstractRowsRenderer.java:88) org.richfaces.renderkit.AbstractTableRenderer.encodeTBody(AbstractTableRenderer.java:90) org.richfaces.renderkit.AbstractTableRenderer.encodeChildren(AbstractTableRenderer.java:97) javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:837) javax.faces.component.UIComponent.encodeAll(UIComponent.java:936) javax.faces.render.Renderer.encodeChildren(Renderer.java:148) javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:837) org.ajax4jsf.renderkit.RendererBase.renderChild(RendererBase.java:277) org.ajax4jsf.renderkit.RendererBase.renderChildren(RendererBase.java:258) org.ajax4jsf.renderkit.RendererBase.renderChild(RendererBase.java:279) org.ajax4jsf.renderkit.RendererBase.renderChildren(RendererBase.java:258) org.richfaces.renderkit.TabRendererBase.encodeChildren(TabRendererBase.java:149) javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:837) org.ajax4jsf.renderkit.RendererBase.renderChild(RendererBase.java:277) org.ajax4jsf.renderkit.RendererBase.renderChildren(RendererBase.java:258) org.richfaces.renderkit.html.TabPanelRenderer.doEncodeChildren(TabPanelRenderer.java:266) org.richfaces.renderkit.html.TabPanelRenderer.doEncodeChildren(TabPanelRenderer.java:261) org.ajax4jsf.renderkit.RendererBase.encodeChildren(RendererBase.java:120) javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:837) javax.faces.component.UIComponent.encodeAll(UIComponent.java:936) javax.faces.component.UIComponent.encodeAll(UIComponent.java:942) javax.faces.component.UIComponent.encodeAll(UIComponent.java:942) javax.faces.component.UIComponent.encodeAll(UIComponent.java:942) javax.faces.component.UIComponent.encodeAll(UIComponent.java:942) com.sun.facelets.FaceletViewHandler.renderView(FaceletViewHandler.java:594) org.ajax4jsf.application.ViewHandlerWrapper.renderView(ViewHandlerWrapper.java:100) org.ajax4jsf.application.AjaxViewHandler.renderView(AjaxViewHandler.java:176) com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:109) com.sun.faces.lifecycle.Phase.doPhase(Phase.java:100) com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:139) javax.faces.webapp.FacesServlet.service(FacesServlet.java:266) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:654) org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:445) org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:379) org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:292) org.jboss.seam.web.RewriteFilter.process(RewriteFilter.java:98) org.jboss.seam.web.RewriteFilter.doFilter(RewriteFilter.java:57) org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) org.jboss.seam.web.IdentityFilter.doFilter(IdentityFilter.java:40) org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) org.jboss.seam.web.MultipartFilter.doFilter(MultipartFilter.java:90) org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) org.jboss.seam.web.ExceptionFilter.doFilter(ExceptionFilter.java:64) org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) org.jboss.seam.web.RedirectFilter.doFilter(RedirectFilter.java:45) org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:206) org.ajax4jsf.webapp.BaseFilter.handleRequest(BaseFilter.java:290) org.ajax4jsf.webapp.BaseFilter.processUploadsAndHandleRequest(BaseFilter.java:388) org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:515) org.jboss.seam.web.Ajax4jsfFilter.doFilter(Ajax4jsfFilter.java:56) org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) org.jboss.seam.web.LoggingFilter.doFilter(LoggingFilter.java:60) org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) it.novaware.sn.core.sessionIdFilter.SessionIdFilter.doFilter(SessionIdFilter.java:77) org.jboss.seam.servlet.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69) org.jboss.seam.servlet.SeamFilter.doFilter(SeamFilter.java:158) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230) org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175) org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:182) org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:432) org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84) org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:262) org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844) org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:446) java.lang.Thread.run(Thread.java:662)
It's not related to my bane's method as every thread is BLOCKED from different methods (but all in the same point, CachedConnectionManager.unregisterConnection(CachedConnectionManager.java:318)) so I'm trying to figure out how to understand who generates all these connections...
Is there a way to track it?
I cannot reproduce in local even if I run a JMeter test (maybe it's something originated by a javascript attached method)...
Here there is the screen shot of what happened:
1. normally (during the load) it was like this: http://blog.brightwide.com/normal.png
(I still don't understand the peaks)
2. when it was completed blocked that's the graph: http://blog.brightwide.com/blocked.png
Any hint could be useful...
Thanks
Demetrio