4 Replies Latest reply on Jun 5, 2007 10:07 AM by Chris Lowe

    DOCTYPE definition on *pages.xml performance warning/improve

    Chris Lowe Apprentice

      Hello,

      I have a couple of suggestions regarding the handling of the *page.xml files.

      Seam-Gen adds an XML doctype to every instance of *page.xml:

      <!DOCTYPE page PUBLIC
       "-//JBoss/Seam Pages Configuration DTD 1.2//EN"
       "http://jboss.com/products/seam/pages-1.2.dtd">
      
      <page>
      </page>


      And in all of my apps I have dutifully mimicked this across all of my pages. Now, I noticed that this has been upgraded in the forthcoming 1.3 version in CVS to:

      <!DOCTYPE page PUBLIC
       "-//JBoss/Seam Pages Configuration DTD 1.3//EN"
       "http://jboss.com/products/seam/pages-1.3.dtd">


      The DTD for 1.3 is present in the jboss-seam.jar but 1.2/1.1/etc are not. I also checked an older application that was upgraded from 1.1 to 1.2, and I saw there was a similar story there (trying to access DTD for 1.1, not finding it and resoving via the web).

      When parsing the pages.xml when the pages-1.x.dtd is not present in the Seam jar, org.jboss.seam.core.Pages looks like it's downloading the DTD on every page invocation. If I disable my internet connection (all my resources are on one machine) then I get the following exception:

      16:33:10,527 ERROR [SeamPhaseListener] uncaught exception
      java.lang.RuntimeException: org.dom4j.DocumentException: jboss.com Nested exception: jboss.com
       at org.jboss.seam.core.Pages.getDocumentRoot(Pages.java:877)
       at org.jboss.seam.core.Pages.parse(Pages.java:835)
       at org.jboss.seam.core.Pages.initialize(Pages.java:108)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:597)
       at org.jboss.seam.util.Reflections.invoke(Reflections.java:21)
       at org.jboss.seam.util.Reflections.invokeAndWrap(Reflections.java:124)
       at org.jboss.seam.Component.callComponentMethod(Component.java:1838)
       at org.jboss.seam.Component.callCreateMethod(Component.java:1761)
       at org.jboss.seam.Component.newInstance(Component.java:1750)
       at org.jboss.seam.Component.getInstance(Component.java:1647)
       at org.jboss.seam.Component.getInstance(Component.java:1626)
       at org.jboss.seam.Component.getInstance(Component.java:1603)
       at org.jboss.seam.Component.getInstance(Component.java:1598)
       at org.jboss.seam.core.Pages.instance(Pages.java:519)
       at org.jboss.seam.core.Manager.restoreConversation(Manager.java:439)
       at org.jboss.seam.jsf.AbstractSeamPhaseListener.afterRestoreView(AbstractSeamPhaseListener.java:67)
       at org.jboss.seam.jsf.SeamPhaseListener.afterPhase(SeamPhaseListener.java:90)
       at com.sun.faces.lifecycle.LifecycleImpl.phase(LifecycleImpl.java:280)
       at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:117)
       at javax.faces.webapp.FacesServlet.service(FacesServlet.java:244)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
       at org.jboss.seam.web.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:69)
       at org.jboss.seam.web.ExceptionFilter.doFilter(ExceptionFilter.java:60)
       at org.jboss.seam.web.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:55)
       at org.jboss.seam.web.RedirectFilter.doFilter(RedirectFilter.java:47)
       at org.jboss.seam.web.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:55)
       at org.jboss.seam.web.MultipartFilter.doFilter(MultipartFilter.java:81)
       at org.jboss.seam.web.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:55)
       at org.ajax4jsf.framework.ajax.xmlfilter.BaseFilter.doFilter(BaseFilter.java:293)
       at org.jboss.seam.web.AbstractAjax4jsfFilter.doFilter(AbstractAjax4jsfFilter.java:35)
       at org.jboss.seam.web.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:55)
       at org.jboss.seam.debug.hot.HotDeployFilter.doFilter(HotDeployFilter.java:64)
       at org.jboss.seam.web.SeamFilter$FilterChainImpl.doFilter(SeamFilter.java:55)
       at org.jboss.seam.web.SeamFilter.doFilter(SeamFilter.java:126)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
       at org.ajax4jsf.framework.ajax.xmlfilter.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:127)
       at org.ajax4jsf.framework.ajax.xmlfilter.BaseFilter.doFilter(BaseFilter.java:277)
       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.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:156)
       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:619)
      Caused by: org.dom4j.DocumentException: jboss.com Nested exception: jboss.com
       at org.dom4j.io.SAXReader.read(SAXReader.java:484)
       at org.dom4j.io.SAXReader.read(SAXReader.java:343)
       at org.jboss.seam.util.XML.getRootElement(XML.java:16)
       at org.jboss.seam.core.Pages.getDocumentRoot(Pages.java:873)
       ... 60 more


      Now, the obvious fix for this is to update all instances of *pages.xml to refer to the new DTD and that works fine. What concerns me is that this situation is able to go completely undetected.

      Looking at the code for DTDEntityResolver, I notice that that the situation is handled but only logged as debug - given the performance impact of downloading a DTD on every page invocation shouldn't the resolver at least issue a warning?

      if ( dtdStream == null ) {
       log.debug( "unable to locate [" + systemId + "] on classpath" );
      }


      This issue might be even worse. It also looks like the DTD is being read and parsed quite frequently per page access. While debugging the invocation of a simple page with simple navigation, I get FOUR hits on the DTD reading code: both pages.xml and login.page.xml are read twice - postback and response;
      This seems like an unnecessary overhead, is it possible to lazy load the DTD and use a parsed instance over all requests?

      Cheers,

      Chris

        • 1. Re: DOCTYPE definition on *pages.xml performance warning/imp
          Chris Lowe Apprentice

          I added some basic timing code to Pages.class for the following methods. Both call getDocumentRoot():

          package org.jboss.seam.core;
          
          ...
          
          public class Pages {
           ...
          
           private void parse(InputStream stream)
           {
           long t1 = System.nanoTime();
          
           ...
          
           long t2 = System.nanoTime();
          
           System.out.println("pages1: handling = " + (t2 - t1) / 1000000);
           }
          
           private void parse(InputStream stream, String viewId)
           {
           long t1 = System.nanoTime();
           ...
           long t2 = System.nanoTime();
          
           System.out.println("pages2: handling = " + (t2 - t1) / 1000000);
           }
          
           ...
          }


          My test is to define 2 simple pages that had a linked to each other. So clicking the link should produce test output for request and response phases and hopefully show the cost of parsing for a page transition.

          Test 1: DOCTYPE was correct for verion 1.3 for pages.xml and test.page.xml - average time spent parsing and processing *pages.xml for a request/response cycle was 48ms.

          Test 2: DOCTYPE was set to 1.2 for for pages.xml and test.page.xml; running CVS Seam 1.3 - average time spent parsing and processing *pages.xml for a request/response cycle was 958ms.

          More detailed data is below:

          Test 1: DOCTYPE was correct for verion 1.3

          t1 -> t2
          pages1: handling = 11
          pages2: handling = 12
          pages2: handling = 8
          pages1: handling = 9
          pages2: handling = 7

          total: 47ms

          t2 -> t1
          pages1: handling = 9
          pages2: handling = 10
          pages2: handling = 15
          pages1: handling = 11
          pages2: handling = 9

          total: 54ms

          t1 -> t2
          pages1: handling = 9
          pages2: handling = 8
          pages2: handling = 9
          pages1: handling = 15
          pages2: handling = 10

          total: 51ms

          t2 -> t1
          pages1: handling = 9
          pages2: handling = 12
          pages2: handling = 7
          pages1: handling = 9
          pages2: handling = 5

          total: 42ms

          ----------------------

          Test 2: DOCTYPE was incorrect for verion 1.3

          t1 -> t2
          pages1: handling = 415
          pages2: handling = 138
          pages2: handling = 141
          pages1: handling = 145
          pages2: handling = 140

          total: 976ms

          t2 -> t1
          pages1: handling = 366
          pages2: handling = 129
          pages2: handling = 129
          pages1: handling = 132
          pages2: handling = 129

          total: 885ms

          t1 -> t2
          pages1: handling = 405
          pages2: handling = 149
          pages2: handling = 142
          pages1: handling = 145
          pages2: handling = 143

          total: 984ms

          t2 -> t1
          pages1: handling = 411
          pages2: handling = 144
          pages2: handling = 141
          pages1: handling = 146
          pages2: handling = 146

          total: 988ms


          Test was done an a dual Xeon 2.8Ghz/2Gb RAM. App was warmed by navigating between test pages 10 times before taking timings.

          [ServerInfo] Java version: 1.6.0_01,Sun Microsystems Inc.
          [ServerInfo] Java VM: Java HotSpot(TM) Server VM 1.6.0_01-b06,Sun Microsystems Inc.
          [ServerInfo] OS-System: Windows XP 5.1,x86

          • 2. Re: DOCTYPE definition on *pages.xml performance warning/imp
            Chris Lowe Apprentice

            Regarding lazy loading of pages.xml: please accept my apologies, I'd completely missed the hotDeployFilter which takes care of this loading when <core:init debug="true" /> and caches when debug = false.

            However... I had tried my experiments with debug set to true/false before posting and observed my page timing code on both accounts on every page access. On closer inspection it looks like components.properties is not being taken into account for projects created by seam-gen. In fact the value for the @debug@ token in components.xml resolves to the debug value set in build-dev.properties. components.properties does not appear to be referenced at all in build.xml.

            I could override the debug value using the following:

            <context-param>
             <param-name>org.jboss.seam.core.init.debug</param-name>
             <param-value>false</param-value>
            </context-param>


            Then I could see that pages.xml were only parsed once despite evidence from the startup logs that the hotDeployFilter still being deployed.

            • 3. Re: DOCTYPE definition on *pages.xml performance warning/imp
              Gavin King Master

              components.properties is used when running tests inside the IDE. It is not used when deploying (ant replaces the @tokens@ when deploying)

              • 4. Re: DOCTYPE definition on *pages.xml performance warning/imp
                Chris Lowe Apprentice

                 

                Sometimes we want to reuse the same components.xml file with minor changes during both deployment and testing. Seam lets you place wildcards of the form @wildcard@ in the components.xml file which can be replaced
                either by your Ant build script (at deployment time) or by providing a file named components.properties in the classpath (at development time). You'll see this approach used in the Seam examples.


                Sorry, I'd misread the reference manual on that one. My mistake...