| Summary: | <x:forEach> very slow in JSTL 1.1 | ||
|---|---|---|---|
| Product: | Taglibs | Reporter: | Chris Johnson <chrisjohnson> |
| Component: | Standard Taglib | Assignee: | Tomcat Developers Mailing List <dev> |
| Status: | RESOLVED FIXED | ||
| Severity: | major | CC: | davew, jlandin, kschneider, wim |
| Priority: | P2 | ||
| Version: | 1.1 | ||
| Target Milestone: | --- | ||
| Hardware: | Sun | ||
| OS: | Solaris | ||
| Bug Depends on: | |||
| Bug Blocks: | 61875 | ||
| Attachments: |
Test xforeach jsp file
Test xtransform jsp file Test xml file Test xsl file Update ExprSupport to use JAXP Supporting variable resolver Patch to use JAXP XPath support Patch for XPath using Xalan API Updated patch using Xalan directly |
||
|
Description
Chris Johnson
2004-03-16 17:27:15 UTC
Couple of comments: Previous id of problem: http://www.mail-archive.com/taglibs-user@jakarta.apache.org/msg06308.html Temporary workaround (use XSLT and <x:transform>): http://www.mail-archive.com/taglibs-user@jakarta.apache.org/msg06337.html I certainly don't have my head completely around the codebase, but it appears that Standard 1.1 is using an approach that leverages Xalan's XPathAPI as opposed to CachedXPathAPI. As a data point, I put together a test using an XML file like: <root> <child/> <child/> <!-- about 1400 total children --> ... </root> and two code variations: #1 -- Document doc = ...; String xpathStr = "//child"; CachedXPathAPI cachedXPath = new CachedXPathAPI(); NodeIterator i = cachedXPath.selectNodeIterator(doc, xpathStr); Map values = new TreeMap(); int count = 1; long now = System.currentTimeMillis(); for (Node node = i.nextNode(); node != null; node = i.nextNode()) { XObject xo = cachedXPath.eval(node, "."); values.put(new Integer(count), xo); count++; } long delta = System.currentTimeMillis() - now; System.out.println("duration: " + delta + "ms"); #2 -- Document doc = ...; String xpathStr = "//child"; NodeIterator i = XPathAPI.selectNodeIterator(doc, xpathStr); Map values = new TreeMap(); int count = 1; long now = System.currentTimeMillis(); for (Node node = i.nextNode(); node != null; node = i.nextNode()) { XObject xo = XPathAPI.eval(node, "."); values.put(new Integer(count), xo); count++; } long delta = System.currentTimeMillis() - now; System.out.println("duration: " + delta + "ms"); Running on WinXP with Sun's JDK 1.4.2_03 plus Xerces 2.6.2 and Xalan 2.6.0, the CachedXPathAPI test completes in under 700ms. The XPathAPI test threw an OutOfMemoryError. I had to use -Xmx256 (it failed with 220!) and then it completed in just under 10000ms. Again, I haven't spent the time in the codebase to say whether this is truly equivalent to how Standard 1.1 is using Xalan, but if it is, it looks like a memory issue in addition to a performance issue. CC'ing the taglibs-dev address to all Standard bugs. We have noticed that x:set also appears very slow. SHould I file this as a seperate issue Hi Mike, Yes, please fill a new bug, preferably with instructions on how to reproduce it. If we later realize the new bug is caused by the same problem , we can mark it then as duplicated of this one. Thanks, Felipe Created attachment 12261 [details]
Test xforeach jsp file
Created attachment 12262 [details]
Test xtransform jsp file
Created attachment 12263 [details]
Test xml file
Created attachment 12264 [details]
Test xsl file
Justyna, I prepared two test cases which show the difference in execution time between en x:forEach loop and an x:transform. Just try them. Test_xforeach.jsp uses Test.xml as input. (countains xml data) Test_xtransform.jsp uses Test.xml as input and Test.xsl as stylesheet. With jstl 1.1 things become problematic for the x:foreach loop The x:foreach loop with jstl 1.0 gives the same,good, response times as the x:transform in jstl 1.1 Regards Wim ps : the jsp files are send as .txt as attachment. You have to rename them. -----Oorspronkelijk bericht----- Van: Justyna Horwat Verzonden: woensdag 28 juli 2004 19:36 Aan: Tag Libraries Users List Onderwerp: Re: JSTL 1.1 jaxp problem (under tomcat 5.0.19/java 1.4.2_03) Hi Wim, Have you tried the following to avoid the property file lookups? What were the results when you set the following properties? ---- jaxp.properties file lookup: JAVA_OPTS="$JAVA_OPTS -Djavax.xml.parsers.DocumentBuilderFactory=org.apache.xerces.jaxp.DocumentBu ilderFactoryImpl" Lookup procedure (for my own reference): http://java.sun.com/j2se/1.4.2/docs/api/javax/xml/parsers/DocumentBuilderFac tory.html#newInstance() ---- xalan.properties file lookup: JAVA_OPTS="$JAVA_OPTS -Dorg.apache.xml.dtm.DTMManager=org.apache.xml.dtm.ref.DTMManagerDefault" Lookup procedure (for my own reference): http://xml.apache.org/xalan-j/apidocs/org/apache/xml/dtm/DTMManager.html#new Instance(org.apache.xml.utils.XMLStringFactory) ---- Thanks, Justyna Wim Goossens wrote: >> Chris, Kris, Pierre, >> >> Do you know anything about a fix for this problem ? >> I also submitted a bug report, probably at the wrong place, >> in february. No solution so far. >> http://developer.java.sun.com/developer/bugParade/bugs/4993200.html >> >> Regards, >> Wim >> >> >> >> -----Oorspronkelijk bericht----- >> Van: Johnson, Chris >> Verzonden: dinsdag 16 maart 2004 18:29 >> Aan: Tag Libraries Users List >> Onderwerp: RE: JSTL 1.1 jaxp problem (under tomcat 5.0.19/java 1.4.2_03) >> >> >> Thanks for all of the help so far. >> >> I submitted bug 27717. >> >> Chris >> >> -----Original Message----- >> From: Pierre.Delisle >> Sent: Tuesday, March 16, 2004 10:58 AM >> To: Tag Libraries Users List >> Subject: Re: JSTL 1.1 jaxp problem (under tomcat 5.0.19/java 1.4.2_03) >> >> >> Yes, as Kris mentioned, please file a bug report with proper test cases. >> We'll have a look into it. >> >> -- Pierre >> >> Kris Schneider wrote: >> >> > >>>>You're posting to the right place to make people aware of the problem. > >> >> > >>>>To formalize the issue, a bug report should probably get submitted: >>>> >>>>http://issues.apache.org/bugzilla/enter_bug.cgi?product=Taglibs >>>> >>>>As part of the report, it would be helpful to include a simplified >>>>test case (XML and JSP files) that reproduces the problem. If you have > >> >> > >>>>any questions about the bug submission process just let me (us) know. >>>>At this point, the problem seems to be either the way JSTL is using >>>>Xalan or Xalan itself. >>>> >>>>Quoting "Johnson, Chris" <chrisjohnson>: >>>> >>>> >>>> >> >>>>>>That gets rid of the xalan file search, but the performance is still >>>>>>awful. For now I guess I'll try to look into xslt, but this looks >>>>>>like a bug that needs to be fixed or something. Who else needs to >>>>>>know about this to get it either fixed, or to tell me what else I >>>>>>might be doing wrong (if anything). Here's more of what truss is >>>>>>spitting out if that >>>>>>helps: >>>>>> >>>>>>lwp_cond_wait(0x0002E7F8, 0x0002E7E0, 0xEC681B08) = 0 >>>>>>lwp_cond_signal(0x0002E7F8) = 0 >>>>>>lwp_mutex_lock(0x0002E7E0) = 0 >>>>>>lwp_mutex_unlock(0x0002E7E0) = 0 >>>>>>lwp_mutex_lock(0x0002E710) = 0 >>>>>>lwp_cond_wait(0x0002E728, 0x0002E710, 0x00000000) = 0 >>>>>>lwp_cond_broadcast(0x0002E728) = 0 >>>>>>lwp_mutex_unlock(0x0002E778) = 0 >>>>>>lwp_mutex_lock(0x0002E778) = 0 >>>>>>lwp_cond_broadcast(0x0002E860) = 0 >>>>>>lwp_cond_wait(0x0002E860, 0x0002E848, 0x00000000) = 0 >>>>>>lwp_mutex_unlock(0x0002E848) = 0 >>>>>>lwp_mutex_lock(0x0002E848) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>lwp_cond_wait(0x0002E7F8, 0x0002E7E0, 0xEC681B08) = 0 >>>>>>lwp_cond_signal(0x0002E7F8) = 0 >>>>>>lwp_cond_broadcast(0x0002E860) = 0 >>>>>>lwp_cond_wait(0x0002E860, 0x0002E848, 0x00000000) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>lwp_cond_wait(0x0002E7F8, 0x0002E7E0, 0xEC681B08) = 0 >>>>>>lwp_cond_signal(0x0002E7F8) = 0 >>>>>>lwp_cond_broadcast(0x0002E860) = 0 >>>>>>lwp_cond_wait(0x0002E860, 0x0002E848, 0x00000000) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>lwp_cond_wait(0x0002E7F8, 0x0002E7E0, 0xEC681B08) = 0 >>>>>>lwp_cond_signal(0x0002E7F8) = 0 >>>>>>lwp_cond_broadcast(0x0002E860) = 0 >>>>>>lwp_cond_wait(0x0002E860, 0x0002E848, 0x00000000) = 0 >>>>>>lwp_mutex_unlock(0x0002E848) = 0 >>>>>>lwp_mutex_lock(0x0002E848) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>lwp_cond_wait(0x0002E7F8, 0x0002E7E0, 0xEC681B08) = 0 >>>>>>lwp_cond_signal(0x0002E7F8) = 0 >>>>>>lwp_mutex_lock(0x0002E7E0) = 0 >>>>>>lwp_mutex_unlock(0x0002E7E0) = 0 >>>>>>lwp_mutex_lock(0x0002E710) = 0 >>>>>>lwp_cond_wait(0x0002E728, 0x0002E710, 0x00000000) = 0 >>>>>>lwp_cond_broadcast(0x0002E728) = 0 >>>>>>lwp_mutex_unlock(0x0002E778) = 0 >>>>>>lwp_mutex_lock(0x0002E778) = 0 >>>>>>lwp_mutex_lock(0x0002E848) = 0 >>>>>>lwp_cond_broadcast(0x0002E860) = 0 >>>>>>lwp_cond_wait(0x0002E860, 0x0002E848, 0x00000000) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>>poll(0xE997FBC0, 0, 50) = 0 >>>>>> >>>>>>It looks like a lot of locking, unlocking and waiting to me, but what >>>>>>do I know? >>>>>> >>>>>>Any help you can get me in escalating this would be much appreciated. >>>>>> >>>>>>Thanks again, >>>>>>Chris >>>>>> >>>>>>-----Original Message----- >>>>>>From: Kris Schneider [] >>>>>>Sent: Monday, March 15, 2004 3:37 PM >>>>>>To: Tag Libraries Users List >>>>>>Subject: RE: JSTL 1.1 jaxp problem (under tomcat 5.0.19/java 1.4.2_03) >>>>>> >>>>>> >>>>>>Try adding >>>>>>-Dorg.apache.xml.dtm.DTMManager=org.apache.xml.dtm.ref.DTMManagerDefau >>>>>>lt >>>>>>to JAVA_OPTS. >>>>>> >>>>>>Quoting "Johnson, Chris" <chrisjohnson@ti.com>: >>>>>> >>>>>> >>>>>> >>> >>>>>>>>Thanks, Kris. >>>>>>>> >>>>>>>>I did all that you suggested (setting the system properties and >>>>>>>>installing new jars), and indeed tomcat doesn't seem to be searching >>>>>>>>for the jaxp.properties file any longer. But, the performance is >>>>>>>>still just about as bad as before. So, I did truss again and now >>>>>>>>tomcat is looking for xalan.properties >>>>>>>>(stat64("/usr/j2sdk1.4.2_03/jre/lib/xalan.properties", 0xDF47F850) >>>>>>>>Err#2 ENOENT), just about as much, if not more, than it was for >>>>>>>>jaxp.properties. So how can I fix this? >>>>>>>> >>>>>>>>Chris >>>>>>>> >>>>>>>>-----Original Message----- >>>>>>>>From: Kris Schneider [] >>>>>>>>Sent: Monday, March 15, 2004 2:32 PM >>>>>>>>To: Tag Libraries Users List >>>>>>>>Subject: Re: JSTL 1.1 jaxp problem (under tomcat 5.0.19/java >>>>>>>>1.4.2_03) >>>>>>>> >>>>>>>> >>>>>>>>Interesting. <x:forEach> has been tagged as a performance problem >>>>>>>>before for JSTL 1.1, but without the accompanying truss info. The >>>>>>>>XPath engine for JSTL was changed from Jaxen/SAXPath in 1.0 to Xalan >>>>>>>>in 1.1. If you can replace <x:forEach> with <x:transform> and an XSLT > >> >> > >>>>>>>>stylesheet, that seemed to help with the last performance issue. >>>>>>>>Otherwise, you could try explicitly configuring JAXP by setting the >>>>>>>>appropriate system properties (assuming Xerces and Xalan): >>>>>>>> >>>>>>>>env >>>>>>>>JAVA_OPTS="-Djavax.xml.parsers.DocumentBuilderFactory=org.apache.xerc > >> >> e >> > >>>>>>>>s. >>>>>>>>jaxp.DocumentBuilderFactoryImpl >>>>>>>> >>> >>>>>> >>>>>>-Djavax.xml.parsers.SAXParserFactory=org.apache.xerces.jaxp.SAXParserF >>>>>>ac >>>>>> >>>>>> >>> >>>>>>>>toryImpl >>>>>>>> >>> >>>>>> >>>>>>-Djavax.xml.transform.TransformerFactory=org.apache.xalan.processor.Tr >>>>>>an >>>>>> >>>>>> >>> >>>>>>>>sformerFactoryImpl" >>>>>>>>$CATALINA_HOME/bin/startup.sh >>>>>>>> >>>>>>>>That way, jaxp.properties should never be searched for. You may also >>>>>>>>want to download the latest Xalan release and dump the following in >>>>>>>>$CATALINA_HOME/common/endorsed: >>>>>>>> >>>>>>>>xalan.jar >>>>>>>>xercesImpl.jar >>>>>>>>xml-apis.jar >>>>>>>> >>>>>>>>Quoting "Johnson, Chris" <chrisjohnson>: >>>>>>>> >>>>>>>> >>>>>>>> >>>> >>>>>>>>>>Hello, >>>>>>>>>> >>>>>>>>>>I'm new to the world of JSP/JSTL, but have managed to get some code >>>>>>>>>>running under tomcat 4.1.29 (bundled with jboss 3.2.3 - as I'm using >>> >>>>>> >>> >>>>>>>>>>JMS too)/JSTL 1.0. I'm using java 1.4.2_03. >>>>>>>>>> >>>>>>>>>>I'm using only the c and x libraries currently, but wanted to use >>>>>>>>>>the >>>>>>>>>>new EL functions of JSTL 1.1, so I installed tomcat 5.0.19 alongside >>> >>>>>> >>> >>>>>>>>>>the previously mentioned jboss/tomcat versions. >>>>>>>>>> >>>>>>>>>>I've gotten the code to run under the new tomcat, but the >>>>>>>>>>performance >>>>>>>>>>is terrible. I've narrowed the performance problem down to any >>>>>>>>>><x:forEach> loop. There wasn't anything of interest in the tomcat >>>>>>>>>>log, so I did a truss on the tomcat process, and found it spitting >>> >>>>>> >>>>>>out >>>>>> >>>>>> >>> >>>>>>>>>>this error over and over: >>>>>>>>>>stat64("/usr/j2sdk1.4.2_03/jre/lib/jaxp.properties", >>>>>>>>>>0xDF97FFF8) Err#2 ENOENT. I understand this to be tomcat looking >>> >>>>>> >>>>>>for >>>>>> >>>>>> >>> >>>>>>>>>>the jaxp.properties file and not finding it. I never saw this error > >> >> > >>>>>>>>>>message while trussing the tomcat 4.1.29 process, and it processes >>> >>>>>> >>>>>>the >>>>>> >>>>>> >>> >>>>>>>>>>xml extremely quickly. >>>>>>>>>> >>>>>>>>>>With the older tomcat and JSTL 1.0, I didn't have to do any special >>>>>>>>>>configuration of jaxp (I understood that to be built into java >>>>>>>>>>1.4.2x), so I figured it would be the same with the newer tomcat, >>> >>>>>> >>>>>>but >>>>>> >>>>>> >>> >>>>>>>>>>I guess not. >>>>>>>>>> >>>>>>>>>>So far I've tried setting parser system properties in the web.xml >>>>>>>>>>and >>>>>>>>>>in files under META-INF with no change. What am I missing? If >>>>>>>>>>someone can just point me to some good docs on the subject, I'd >>>>>>>>>>appreciate it greatly. >>>>>>>>>> >>>>>>>>>>Thanks, >>>>>>>>>>Chris Johnson *** Bug 33297 has been marked as a duplicate of this bug. *** *** Bug 40717 has been marked as a duplicate of this bug. *** See the suggested fix in 40717. Ignore the fix suggestion in 40717 - I believe it is really just suggesting a change that would be akin to reverting back to CachedXPathUtil. Pushing this a bit - I don't think the problem is in x:foreach. I think it's in
x:out. x:foreach executes relatively quickly, but then each execution of x:out
is not cheap and it's adding up as the loop gets bigger.
Presumably running the following is hurting:
XPathUtil xu = new XPathUtil(pageContext);
String result = xu.valueOf(XPathUtil.getContext(this), select);
Digging into valueOf leads to agreement with David Winterbourne's comment in
40717 that the problem is in fillVarStack. It's in valueOf too and definitely
looks like a culprit. So apologies for my last comment on 40717 being akin to
CachedXPathAPI. That just caches the xpathSupport variable.
Looking at the speed of things, I've not found where the slow down is yet. There
are times when there are large chunks of slow down (100 milliseconds), which
might be GC due to massive object creation. Also over time the general time
taken on each eval call slowly rises, although still only to 10 milliseconds.
Obviously I need to test in a profiler etc.
(In reply to comment #14) > Obviously I need to test in a profiler etc. Speaking of which, I just grabbed NB6 and set up Standard 1.0.6 and Standard 1.1.2 projects to get a better idea of the performance difference. Using the Test.xml attached a few years back and the following loop: <% long start = System.currentTimeMillis(); %> <x:forEach select="$doc//countries/country"> country id: <x:out select="id"/> country description: <x:out select="description"/> country countrycode: <x:out select="countrycode"/> country carcode: <x:out select="carcode"/> country nationality: <x:out select="nationality"/> </x:forEach> <% long delta = System.currentTimeMillis() - start; out.println("Duration: " + delta + "ms"); %> Here's what I got: Standard 1.0.6: ~150ms Standard 1.1.2: ~16000ms I'm running JDK 1.5.0_12, Xalan 2.7.0, Xerces 2.7.1, Tomcat 5.5.23, and WinXP SP2. Profiling, all the time is spent in the following line:
int ctxtNode = xpathSupport.getDTMHandleFromNode(contextNode);
The Javadoc for this method notes that it is non-optimal [wheee].
Reading CachedXPathAPI, what it does is cache the DTMManager, so definitely
makes sense that switching back to CachedXPathAPI will fix the slowness of x:out.
As there's no JSTL API to modify the DOM, I don't see any reason not to use
CachedXPathAPI - except for the memory issue of caching and figuring out where
in the lifecycle to remove it.
Given that this is only a notable problem for x:out in x:foreach, it would seem
that we need to attach the cache to the x:foreach start/close cycle, and have
the x:out notice that its session has such a thing.
Time to poke around in the code.
The src/org/apache/taglibs/standard/tag/common/xml/ForEachTag.java class needs to cache its XPathUtil object in setAttribute (default page scope), and tell XPathUtil to use CachedJSTLXPathAPI rather than JSTLXPathAPI. Additionally, XPathUtil needs that change, and a CachedJSTLXPathAPI needs to exist that includes all the changes that JSTLXPathAPI has had from Xalan's XPathAPI. ExprSupport needs to be changed to (somehow) find the XPathUtil and use it instead of making a new one. Presumably this can be attached to the forEach's var attribute (and whatever system is used to handle nested var's with the same name (such as default name). --- Maybe. I think the problem with all that is that x:foreach is supplying a new node each time around. We need to cache the original node, and adjust the x:out by appending(?) it to the x:foreach pattern each time. That all seems very dodgy. CachedXPathAPI says that: "A faster way is to precompile the XPaths using the low-level API, and then just use the XPaths over and over". That sounds quite attractive - each x:out could precompile an XPath and run it on its node. The pain there is figuring out how to use the low level XPath API. (In reply to comment #17) > CachedXPathAPI says that: "A faster way is to precompile the XPaths using the > low-level API, and then just use the XPaths over and over". That sounds quite > attractive - each x:out could precompile an XPath and run it on its node. The > pain there is figuring out how to use the low level XPath API. Java5 introduced a standard XPath API that supports pre-compilation of XPath expressions. How about parsing the supplied XPath in the setter for the tag attribute and relying on tag pooling to avoid unnecessary recompilations? The API also provides for a XPathVariableResolver that could work with the ELResolver to handle variables present in the XPath expressions. Created attachment 25749 [details]
Update ExprSupport to use JAXP
Created attachment 25750 [details]
Supporting variable resolver
Created attachment 26445 [details]
Patch to use JAXP XPath support
Patch attached to abstract the XPath API and provide an implementation using JAXP XPath.
However, there is a issue with <x:set> as it does not appear JAXP's XPath class can return the actual result type of the XPath expression - it requires coercion to specific return type. This breaks the contract for <x:set> where the variable needs to be set to the actual return type.
Created attachment 26448 [details]
Patch for XPath using Xalan API
Continuation of patch 26445 with addition of a Xalan based implementation.
Created attachment 26452 [details]
Updated patch using Xalan directly
Simplified patch that just uses the low-level Xalan APIs directly.
Fixed in revision 1054175 Refactored XPath support to use Xalan low-level APIs directly. Performance for large data sets scales with n^2 due to Xalan constructing a backing array for the iterator with a monotonic block size causing multiple calls to System.arrayCopy(). On a 2006 generation MacBookPro iterating 100000 elements takes ~1600ms. Reverting spam changes |