Saxon

I succeeded in running this, and I see the same growth in heap size. I've taken a heap dump which I'm examining using JProfiler.

The heap is dominated by the usual byte[], int[], String, and HashMap$Node objects. The most immediately striking feature is that there are a large number (330K) of TinyTree instances on the heap. Most of these are quite small (888 bytes retained size), and they appear to be referenced from FocusTrackingIterator instances.

It looks as if the trees might be retained in memory as a result of using memo functions.

Tracing entry to MemoFunction.java shows we are building a big memo function cache for a number of functions, notably

<xsl:function name="filter:has-name" as="xs:boolean?" new-each-time="false">
        <xsl:param name="applic-item" as="element(applic)?"/>
        <xsl:param name="name" as="xs:string?"/>
        <xsl:sequence select="filter:has-some-name($applic-item, $name)"/>
    </xsl:function>

If I remove the "new-each-time", I haven't yet got the transformation to complete, but the heap usage seems to have stabilised.

This raises questions about the Saxon design in this area. The attribute new-each-time="false" means that if the function should behave like doc() - if it's called twice with the same arguments, it must return the same result. To achieve this, Saxon remembers the result of all previous calls,

The example function above in fact doesn't pose too much of a problem, because the HashMap used to cache the data has a string key and a boolean result. In fact, the key is always a string (we use the generate-id() of a node in cases where an argument is a node). But the associated value in the HashMap is the actual function result, and in some cases this is an element node. The causes the entire tree containing this element node to be locked in memory for the rest of the run. I think this is necessary to respect the semantics of new-each-time="false".

Now investigating the crash in TimingTraceListener, which is caused by a template rule in the compiled profile.xsl stylesheet having a null body. This appears to be associated with the fact that it's using a ProfessionalConfiguration, as requested in the configuration file. (However, changing the config.xml file to request an EnterpriseConfiguration seems to result in a different NPE in a different place.)

If we run without a configuration file, the profile.html file is generated successfully.

The template rule has no body because XSLTemplate.compileDeclaration() decided to use deferred (JIT) compilation of the template body, but this isn't supposed to happen under Saxon-PE, because it's an EE feature.

compilation.isDeferredCompilation() returned true because compilation.isPreScan() is true, which in turn is because OptimizerOptions.JIT is set in the compiler. This is apparently caused by the fact that the configuration file specifies optimizationLevel="10". We should interpret that as meaning "set all optimization options supported in this Saxon edition" - requesting an optimization that isn't fully supported in the edition is likely to cause things to break, as has happened here.

Confirmed that removing this line from the configuration file fixes the problem.

The above change solves the case where the configuration file requests a PE configuration, but we still get a (different) crash when it requests an EE configuration.

This arises because one of the function library lists for the configuration has a null entry.

It turns out this crash has nothing to do with setting the -TP option, it's a crash while executing the main transformation. It is, however, associated with something in the configuration file.

The crash occurs when the configuration file requests edition="EE" but the license file only allows PE features. Fixed.

Testing this now on the development branch (12.x) I get a different failure:

~~Error on line 28 column 64 of lib.overrides.xsl: XTSE0165 I/O error reported by XML parser processing urn:ovidius:names:edk:lib:lib.core.xsl: unknown protocol: urn: unknown protocol: urn I/O error reported by XML parser processing urn:ovidius:names:edk:lib:lib.core.xsl: unknown protocol: urn ~~

This appears to be because the catalog (specified using -catalog on the command line) isn't being picked up.

False alarm. I miscopied the command line options and failed to include -catalog.

I removed the optimization attribute from saxon config and then was able to time-trace the transformation like you. Following the time profile and your hints I realized the following:

(1) There were some functions which could be easily optimized by me. That was filter:match-applic-maps#2 and filter:normalize-applic-map#1.

(2) But there was still much time consumed in function filter:filter-applic-maps#2 . I tried to fragment the function out to get smaller parts which would (in theory) allow me to isolate the problem more in detail. Surprisingly the sum of the time-consumption of the out-fragmented functions was very small compared to filter:filter-applic-maps#2 which was still expensive. Then I did it the other way around and replaced called functions where element nodes were given as arguments with simpler expressions. That help a lot and reduced the time for the function by factor ~3 (another test-set). Unfortunately it is still too much time.

(3) Even if there was no breakthrough with (2), I thought I should test out the transformation in a non-debug mode and without profiling/time-tracing activated. The transformation was -- as before -- not coming to an end. Heap space and CPU time ran full. I supposed that the optimization in profiling mode may in parts be disabled. Et voilà, setting -opt:0 made the transformation run like in profiling mode. I tried to deactivate each optimization to see which one is causing the slowdown and ended with -opt:-t, which is the tail call optimization. How does that come?

(4) Removing new-each-time="true" did not seem to be a solution. The transformation became even more slow. There is a function that creates an element-based map/list and there is a function that normalizes those maps. Both produce elements and are called often. In this case the node IDs play no role for the transformation. The elements are "just data". I'm not confident that this it is a main cause as we had these element-based maps before without problems. What would be an alternative?

For the record:

(5) I replaced the element-based maps/lists with map-based ones to see if that brings performance advantages (element(applic-item)* becomes map(*)*), but that doesn't make a significant difference.

(6) I reduced the calls of exf:variant#1 by making simple comparisons with the parent element to check if a different result is to be expected. If not than a result is taken from a tunneled parameter. Even if this is just a workaround, it is effective and reduces transformation time by factor ~5 on top of the reduction described in (2).

The primary problem I investigated was the heap space problem, this was definitely caused by keeping about 300K XML trees in memory to support the caching of function results. Getting rid of this caching isn't going to make things run faster (on the contrary) - caching is a space/time tradeoff and removing the caching will solve the memory problem at the cost of increasing execution time.

I'm pleased you're making progress in eliminating some of the performance bottlenecks.

We're now in territory where there's no evidence of a Saxon bug or design problem, you're essentially asking for performance consultancy to tune your application. I'm afraid we're not resourced to provide that.

You asked about tail call optimization. The primary purpose of tail call optimization is to prevent stack overflow. I would expect it to be roughly neutral in terms of the effect on execution speed. You're right that certain optimizations are suppressed when tracing is in force - monitoring the entry and exit to functions isn't really possible if function calls aren't executed in the normal way.

Do you have data on how the elapsed time of the transformation increases with input data size?