DOCTYPE definition on *pages.xml performance warning/improve

[lowecg2004]

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

[lowecg2004]

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

[lowecg2004]

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.

[gavin.king]

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

[lowecg2004]

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...