0 Replies Latest reply on Nov 18, 2010 6:38 AM by demetrio812

    Facelets and the cost of refreshing the pages under heavy load

    demetrio812 Apprentice

      Hello,

      yesterday I had a problem in a project of a client during a day of heavy load: after a while (20-30mins) the server started to slow down a lot and then it stalled. Restarting it always gave us 30 to 60 mins before seeing the same problems.

       

      I've a took 3 thread dumps: one when it was ok, one when is was slowing down and one when it was stalled (I attached them).

      Analyzing the dumps I've noticed tha following: when the system was OK no thread was blocked, when it was slow 88 thread were blocked and when it was stalled there were 132 blocked threads.

       

      All the thread were blocked at the same point:

       

      Thread: http-213.175.203.190-80-1 : priority:5, demon:true, threadId:196, threadState:BLOCKED, lockName:java.lang.Class@1026ca4

       

                      org.apache.xerces.impl.dv.DTDDVFactory.getInstance(Unknown Source)
                      org.apache.xerces.parsers.XML11Configuration.(Unknown Source)
                      org.apache.xerces.parsers.XIncludeAwareParserConfiguration.(Unknown Source)
                      org.apache.xerces.parsers.XIncludeAwareParserConfiguration.(Unknown Source)
                      sun.reflect.GeneratedConstructorAccessor5.newInstance(Unknown Source)
                      sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
                      java.lang.reflect.Constructor.newInstance(Constructor.java:513)
                      java.lang.Class.newInstance0(Class.java:355)
                      java.lang.Class.newInstance(Class.java:308)
                      org.apache.xerces.parsers.ObjectFactory.newInstance(Unknown Source)
                      org.apache.xerces.parsers.ObjectFactory.createObject(Unknown Source)
                      org.apache.xerces.parsers.ObjectFactory.createObject(Unknown Source)
                      org.apache.xerces.parsers.SAXParser.(Unknown Source)
                      org.apache.xerces.parsers.SAXParser.(Unknown Source)
                      org.apache.xerces.jaxp.SAXParserImpl$JAXPSAXParser.(Unknown Source)
                      org.apache.xerces.jaxp.SAXParserImpl.(Unknown Source)
                      org.apache.xerces.jaxp.SAXParserFactoryImpl.newSAXParser(Unknown Source)
                      com.sun.facelets.compiler.SAXCompiler.createSAXParser(SAXCompiler.java:278)
                      com.sun.facelets.compiler.SAXCompiler.doCompile(SAXCompiler.java:231)
                      com.sun.facelets.compiler.Compiler.compile(Compiler.java:105)
                      com.sun.facelets.impl.DefaultFaceletFactory.createFacelet(DefaultFaceletFactory.java:218)
                      com.sun.facelets.impl.DefaultFaceletFactory.getFacelet(DefaultFaceletFactory.java:149)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:293)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:273)
                      com.sun.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:140)
                      com.sun.facelets.tag.ui.IncludeHandler.apply(IncludeHandler.java:65)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.tag.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:47)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.tag.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:47)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:49)
                      com.sun.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:25)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:248)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:294)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:273)
                      com.sun.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:140)
                      com.sun.facelets.tag.ui.IncludeHandler.apply(IncludeHandler.java:65)
                      com.sun.facelets.tag.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:47)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:49)
                      com.sun.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:25)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:248)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:294)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:273)
                      com.sun.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:140)
                      com.sun.facelets.tag.ui.IncludeHandler.apply(IncludeHandler.java:65)
                      com.sun.facelets.tag.jsf.ComponentHandler.applyNextHandler(ComponentHandler.java:314)
                      com.sun.facelets.tag.jsf.ComponentHandler.apply(ComponentHandler.java:169)
                      com.sun.facelets.tag.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:47)
                      com.sun.facelets.tag.jsf.core.ViewHandler.apply(ViewHandler.java:109)
                      com.sun.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:49)
                      com.sun.facelets.tag.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:47)
                      com.sun.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:25)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:248)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:294)
                      com.sun.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:273)
                      com.sun.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:140)
                      com.sun.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:113)
                      com.sun.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:49)
                      com.sun.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:25)
                      com.sun.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:95)
                      com.sun.facelets.FaceletViewHandler.buildView(FaceletViewHandler.java:524)
                      com.sun.facelets.FaceletViewHandler.renderView(FaceletViewHandler.java:567)
                      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)
                      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)

       

      So it was Facelets configured with a refresh time of 0 and in the version 1.1.14 (I'm running JBoss AS 4.2.3) that means that it compile the page every time.

       

      I've found other threads complaining about xerces' DTDDVFactory.getInstance. In the one I linked, their explanation was:

       

      {quote}Out of 100 threads available 72 are blocked there when the server is
      under stress.
      To understand the issue, is useful to remember that when a
      Class.forName is done (like the ObjectFactory class invoked from the
      DTDDVFactory does) it can takes (depending from the dimension of the
      classpath) up to 2-4 seconds which is a huge time if this is invoked
      continuosly.{quote}

       

      and one of the developers of Xerces answered:

       

      {quote}Note that the fact that you hit this issue is likely a sign that your application

      is excessively creating new parser instances.

       

      They are meant to be reused and you will get much better performance if you pool [2] them.{quote}

       

      So anyway I decided the understand the kind of load by profiling the server with and without the refresh=0 param (I've set refresh=-1) and the results are impressive:

       

      difference_of_call_number_after_changing_conf_for_doCompile_and_createSaxParser.png

      difference_of_call_number_after_changing_conf_for_DTDDVFactory.png

       

      For around 20 loaded pages by 2 threads (not a lot but it was just to understand the numbers) the SAXCompiler.doCompile was called 706 times less taking 60557 ms less! And the same reduction (obviously) applied to DTDDVFactory.getInstance().

       

      I would anyway update the Facelets library to 1.1.15 (maybe I'll also test the app with JBoss AS 5.1, any know problems with it and JBoss Seam/RichFaces app so far?).

       

      But my problem is that I couldn't reproduce the problem in my development machine (I've set up a JMeter load test but I need more machine and a bigger network to do this kind of tests), I've got some blocked thread anyway (by lowering the maxThread option and loading the server a lot for a while) but I'm not sure that once I've fixed this Facelets related problem I will not have any other problems during a "heavy day".

       

      What is your experience? What do you think by reading the thread dumps?

       

      Thank you very much in advance.

       

      Demetrio