Re: [xsl] Saxon performance difference in eClipse and App Server

Subject: Re: [xsl] Saxon performance difference in eClipse and App Server
From: Michael Kay <mike@xxxxxxxxxxxx>
Date: Tue, 14 Dec 2010 14:36:51 +0000
> From profiling the code, ALL of the difference comes from this line :-

transformer.transform(new DOMSource(doc), new StreamResult(baos));

and the difference is substantial. Running in eClipse the average time
taken is usually 60-80ms whereas within the app server its 700-800ms.

Some suggestions:


(a) Start by drilling down. Split this into three lines:

x = new DOMSource(doc);
s = new StreamResult(baos);
t = transformer.transform(x,s);

and see which of them accounts for the difference.

(b) Check the implementation class of doc in both cases. It may be a different DOM implementation (e.g. Sun vs Apache). Transforming a DOM in Saxon is always inefficient, but some DOMs are worse than others. It depends whether namespaces are represented in the DOM level-1 way or the DOM level-2 way. (Ideally, stop using DOM and use Saxon's native tree. There's nothing in your example that suggests you need to use DOM, so it's better not to. Usually it's better to understand the performance you are getting before you try to improve it, but in this case it may not be worth the effort).

Michael Kay
Saxonica

I'm at a loss to understand what could be causing a 10 fold increase
in the time taken for exactly the same code. Are there any JVM or
other settings that might be causing this ?

To be certain that the App Server (and eClipse) were picking up the
Saxon JARs and not some other parser I included in the output the
vendor name and version, which in both cases reported :-

<!--XSLT vendor: SAXON 9.1.0.6 from Saxonica, XSLT version: 2.0, XSLT
vendor URL: http://www.saxonica.com/-->

Some example code and outputs below ..

Regards

Fraser.

Example code perfroming the transform (including some timing output) :-

public String transformXml(String inputXml, String xslFilePath, Vector
paramsVector,) throws Exception {

long transformstart = System.currentTimeMillis();

        long start = System.currentTimeMillis();
        long end = 0L;
        long totalTime = 0L;

                ByteArrayInputStream bais = new
ByteArrayInputStream(inputXml.getBytes(stringEncoding));

                InputSource in = new InputSource(bais);
                DocumentBuilderFactory dfactory =
DocumentBuilderFactory.newInstance();
                dfactory.setNamespaceAware(true);
                Document doc = dfactory.newDocumentBuilder().parse(in);

                end = System.currentTimeMillis();
                totalTime = end - start;
                System.out.println("Time to parse input: " + totalTime);
                start = System.currentTimeMillis();

                TransformerFactory tFactory = cachingTransformerFactory;
                Transformer transformer;

                transformer = tFactory.newTransformer(new
StreamSource(new File(xslFilePath)));

transformer.clearParameters();

                end = System.currentTimeMillis();
                totalTime = end - start;
                System.out.println("Time to create transformer: " + totalTime);
                start = System.currentTimeMillis();


// Create an instance of the wbimb URI Resolver URIResolver objResolver = new MessageBrokerURIResolver(); transformer.setURIResolver(objResolver);

                end = System.currentTimeMillis();
                totalTime = end - start;
                System.out.println("Time to set URIResolver: " + totalTime);
                start = System.currentTimeMillis();

ByteArrayOutputStream baos = new ByteArrayOutputStream();

                //set parameters
                for (int x = 0; x<  paramsVector.size(); x++) {
                        Parameter param = (Parameter) paramsVector.get(x);
                        transformer.setParameter(param.name, param.value);
                }

                end = System.currentTimeMillis();
                totalTime = end - start;
                System.out.println("Time to parse params: " + totalTime);
                start = System.currentTimeMillis();

                /******* THIS IS WHERE MOST OF THE TIME TAKEN IS ********/
                transformer.transform(new DOMSource(doc), new
StreamResult(baos));

                end = System.currentTimeMillis();
                totalTime = end - start;
                System.out.println("Time to perform transform: " + totalTime);
                start = System.currentTimeMillis();

                baos.close();
                byte[] data = baos.toByteArray();
                String outputString = null;
                try {
                        outputString = new String(data, stringEncoding);
                } catch (Exception e) {
                        String message = "Got Exception converting the
output of transform to String using encoding: " + stringEncoding;
                        throw new Exception(message);
                }

                end = System.currentTimeMillis();
                totalTime = end - start;
                System.out.println("Time to convert the output of the
transform to a String: " + totalTime);

                long transformend = System.currentTimeMillis();
                long transformtotalTime = transformend - transformstart;
                System.out.println("Total time to run XSLT: " +
transformtotalTime);

return outputString;

}


... and this is some typical output from running in eClipse (I'm running 20 iterations here) :-

===================================================
TEST : validResponse_CachedStylesheet
===================================================
Time to parse input: 172
Time to create transformer: 547
Time to set URIResolver: 0
Time to parse params: 0
Time to perform transform: 187
Time to convert the output of the transform to a String: 0
Total time to run XSLT: 906
Time to parse input: 0
Time to create transformer: 0
Time to set URIResolver: 0
Time to parse params: 0
Time to perform transform: 94
Time to convert the output of the transform to a String: 0
Total time to run XSLT: 94
Time to parse input: 0
Time to create transformer: 0
Time to set URIResolver: 0
Time to parse params: 0
Time to perform transform: 78
Time to convert the output of the transform to a String: 0
Total time to run XSLT: 78
Time to parse input: 0
Time to create transformer: 0
Time to set URIResolver: 0
Time to parse params: 0
Time to perform transform: 78
Time to convert the output of the transform to a String: 0
Total time to run XSLT: 78
...
Total time to run XSLT for (20) iterations : 2500
Average time to run XSLT for (20) iterations : 125

Heres some Log4j output from running the same code in the App Server
(note the LAST entry - 735ms) :-

<PrimaryLogText>CachingTransformerFactory: Entry for file [C:\Program
Files\IBM\MQSI\6.1\bin\..\config\flows\service\exceedinboundadapter\resources\retrievepolicysummarylistbyclientref\validation\validateResponse.xslt]
FOUND in CACHE..</PrimaryLogText>

<PrimaryLogText>CachingTransformerFactory: Using CACHED stylesheet
[C:\Program Files\IBM\MQSI\6.1\bin\..\config\flows\service\exceedinboundadapter\resources\retrievepolicysummarylistbyclientref\validation\validateResponse.xslt]..</PrimaryLogText>

<PrimaryLogText>eXSLTPerformance.EnhancedXMLTransformationNode: Time
to create transformer: 0.</PrimaryLogText>

<PrimaryLogText>eXSLTPerformance.EnhancedXMLTransformationNode: Time
to set URIResolver: 0.</PrimaryLogText>

<PrimaryLogText>eXSLTPerformance.EnhancedXMLTransformationNode: Time
to parse params: 0.</PrimaryLogText>

<PrimaryLogText>eXSLTPerformance.EnhancedXMLTransformationNode: Time
to perfrom transform: 735.</PrimaryLogText>

Current Thread