Details
Description
In order to apply this update to the 1.5 branch, I've broken this issue off from
it's original home inICE-992.
The problem typically only occurs under heavy load but can be generated
synthetically by putting a long (20 sec) sleep in the correct location of the
PersistentFacesServlet.
A live thread dump + stack trace showing the deadlock from a clustered JBoss
instance (jboss2) running the ICEfaces.org site.
Found one Java-level deadlock:
=============================
"TP-Processor2326":
waiting to lock monitor 0x089e5c34 (object 0x3565e8d8, a java.lang.String),
which is held by "TP-Processor2603"
"TP-Processor2603":
waiting to lock monitor 0x0839bd14 (object 0x332218e0, a
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager),
which is held by "TP-Processor2326"
Java stack information for the threads listed above:
===================================================
"TP-Processor2326":
at
com.icesoft.faces.webapp.xmlhttp.BlockingResponseState.<init>(BlockingResponseState.java:84)
- waiting to lock <0x3565e8d8> (a java.lang.String)
at
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager.createState(ResponseStateManager.java:120)
at
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager.getState(ResponseStateManager.java:136)
- locked <0x332218e0> (a
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager)
at
com.icesoft.faces.webapp.xmlhttp.BlockingServlet.service(BlockingServlet.java:175)
- locked <0x332f66a8> (a com.icesoft.faces.webapp.xmlhttp.BlockingServlet)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at
org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:175)
at
org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:74)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:199)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:282)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:754)
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:684)
at
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
"TP-Processor2603":
at
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager.getState(ResponseStateManager.java:131)
- waiting to lock <0x332218e0> (a
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager)
at
com.icesoft.faces.webapp.xmlhttp.PersistentFacesServlet.service(PersistentFacesServlet.java:402)
- locked <0x3565e8d8> (a java.lang.String)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at
org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:175)
at
org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:74)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:199)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:282)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:754)
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:684)
at
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
Found 1 deadlock.
it's original home in
The problem typically only occurs under heavy load but can be generated
synthetically by putting a long (20 sec) sleep in the correct location of the
PersistentFacesServlet.
A live thread dump + stack trace showing the deadlock from a clustered JBoss
instance (jboss2) running the ICEfaces.org site.
Found one Java-level deadlock:
=============================
"TP-Processor2326":
waiting to lock monitor 0x089e5c34 (object 0x3565e8d8, a java.lang.String),
which is held by "TP-Processor2603"
"TP-Processor2603":
waiting to lock monitor 0x0839bd14 (object 0x332218e0, a
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager),
which is held by "TP-Processor2326"
Java stack information for the threads listed above:
===================================================
"TP-Processor2326":
at
com.icesoft.faces.webapp.xmlhttp.BlockingResponseState.<init>(BlockingResponseState.java:84)
- waiting to lock <0x3565e8d8> (a java.lang.String)
at
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager.createState(ResponseStateManager.java:120)
at
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager.getState(ResponseStateManager.java:136)
- locked <0x332218e0> (a
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager)
at
com.icesoft.faces.webapp.xmlhttp.BlockingServlet.service(BlockingServlet.java:175)
- locked <0x332f66a8> (a com.icesoft.faces.webapp.xmlhttp.BlockingServlet)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at
org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:175)
at
org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:74)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:199)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:282)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:754)
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:684)
at
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
"TP-Processor2603":
at
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager.getState(ResponseStateManager.java:131)
- waiting to lock <0x332218e0> (a
com.icesoft.faces.webapp.xmlhttp.ResponseStateManager)
at
com.icesoft.faces.webapp.xmlhttp.PersistentFacesServlet.service(PersistentFacesServlet.java:402)
- locked <0x3565e8d8> (a java.lang.String)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at
org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:175)
at
org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:74)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:199)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:282)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:754)
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:684)
at
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)
Found 1 deadlock.
So was I finally able to reproduce the deadlock synthetically by putting a long
sleep in the PersistentFacesServlet between when the execute and render
lifecycles are fired and when the "state" is put into the session.
What was happening is that when the initial request was made to the
PersistentFacesServlet, it was writing back the complete response before
creating the new state and putting it into the session. Under certain high load
conditions, the BlockingServlet would get invoked and request the state before
the PersistentFacesServlet could get around to it.
To avoid this, I've moved the following chunk of code so that it is executed
before the lifecycle methods are called. That way the state is ready for the
BlockingServlet.
String viewNumberString = String.valueOf(viewNumber);
ResponseState state = stateManager.getState(session, viewNumberString);
state.setFocusID(request.getParameter("focus"));
session.setAttribute(viewNumberString + "/" + ResponseState.STATE, state);
Coupled with Ted's changes, this should help us with performance under load.
Marking as FIXED but only real world load testing will fully validate it. This
change has already been applied to the HEAD of the repository:
------------------------------------------------------------------------
r12489 | deryks | 2006-11-30 14:37:27 -0700 (Thu, 30 Nov 2006) | 1 line
ICE-992: Moved logic for putting state into session ahead of lifecycle execution.I have also applied it to the 1.5 branch:
------------------------------------------------------------------------
r12504 | deryks | 2006-11-30 16:37:59 -0700 (Thu, 30 Nov 2006) | 1 line
ICE-1039: Moved logic for putting state into session ahead of lifecycle execution.Marking as FIXED.