Saxon

I modified the stylesheet to stop after the first phase, in which variable groupAllItemsByParentID is created (this phase takes 2s on 9.5 and 3m on 9.8).

The 9.8 Java profile is dominated by calls on GeneralComparisonEE.compareOneToOne, called from FilterIterator.next(), which in turn is called from a DocumentOrderIterator, implying that something is being sorted into document order.

This appears to be the expression <xsl:for-each select="$allItems/*[@PARENT_PRODUCTGROUP_ID = 'null']"> on line 49.

$allItems is a global variable declared as [xsl:variable name="allItems" select="*"/], so we wouldn't expect a sort into document order to be necessary here.

Because the template is called recursively, this sort will be done repeatedly, so it could be significant. (However, the profile doesn't indicate that we are spending a lot of time sorting).

More significantly, 9.5 uses indexing for this filter expression, 9.8 does not. I think the reason for this is that we're searching for a literal, and 9.8 is assuming that there's no point building an index if we're searching for the same value every time: in fact, the whole expression $allItems/*[@PARENT_PRODUCTGROUP_ID = 'null'] should be promoted to a global variable since it has no local dependencies, and evaluated once. We need to see why this isn't happening.

But now we hit a complication. If we set -jit:off to suppress just-in-time compilation of template rules, execution time under 9.8 comes down to a few seconds. But this is a 9.8-specific feature, this can't have any relevance under 9.7.

It's highly relevant for 9.8, however, because with JIT enabled, expressions in the body of a template rule are never extracted as global variables, because of the complexity of creating new global variables on the fly. Perhaps we should put the 9.8 investigation to one side and focus first on 9.7.

With 9.7, we still haven't completed the first phase after 18 minutes: much worse than 9.8.

What on earth can be taking so long? Running it in the debugger to find out...

There appears to be a problem in the template

         <xsl:template name="createHierarchyNamesFromReport">
		<xsl:param name="self"/>
		<xsl:for-each select="$pgrLangItems/items/*[@PRODUCTGROUP_ID = $self]">
			<name lang="{@PRODUCTGROUP_LANGUAGE}">
				<xsl:value-of select="@PRODUCTGROUP_NAME"/>
			</name>
		</xsl:for-each>
	</xsl:template>

The expression $pgrLangItems/items/* has been promoted to a global variable, but for some reason it isn't indexed. Rather perversely, however, $self is indexed (the predicate is evaluated as an IndexedLookupExpression). This isn't as perverse as it seems, because the parameter $self has no declared type (in fact, nothing in this stylesheet has a declared type) so the compiler has to assume the worst.

But the IndexedLookupExpression isn't working as it should: it's taking the recovery path where it discovers that the value of $self is not an indexedValue, and so it creates an IndexedValue. If it were using the parameter $self directly, it would then put the IndexedValue back in the variable slot, but it's actually using a synthetic variable holding data(self), and it doesn't do so in this case. Fixing this, however, doesn't solve the problem.

I have established that by declaring the types of the template parameters on lines 74 and 88 using as="xs:string", execution time (of phase 1) comes down from 15+ minutes to 3 seconds.

I think what's happening is that we first optimize the filter predicate [@ATT = $self] as an IndexedLookupExpression, in the belief that $self might in the worst case be a large node-set. Having done this, the predicate is no longer a Comparison, which means that the outer filter expression is no longer a candidate for indexing. So we've done a low-value optimization that inhibited a subsequent high-value optimization. Yet another case where the optimizer is thwarted by a lack of type information.

By avoiding the conversion of a GeneralComparisonEE to an IndexedLookupExpression if its parent is a FilterExpression, we bring the elapsed time for the transformation under 9.7 to 1m 55s.

For 9.8 the effect is very similar: 2m 2s.

I will do a bit more probing though before closing this, to see if we can do better.

Looking at 9.8, the reason an IndexedFilterExpression doesn't get created is that we only do this if the base B of the filter expression B[P] is a variable reference. The expression $allItems/* won't be turned into a local variable reference because it's not in a loop, and it won't be turned into a global variable reference until a very late stage of optimization.

However, the actual problem seems to be that the expression $allItems/* is being treated by the GlobalExtractor as ineligible for conversion to a global variable. This is happening because its estimated cost is 2, and the threshold for creating a global variable is 3. It seems we are underestimating the cost. The cost metric used by the GlobalExtractor seems to have been simplified in order to reduce the cost of estimating the cost...

If we fix the cost metric, there is another reason the expression $allItems/* doesn't get promoted to global: the logic quite incorrectly decides that because child::element is dependent on the focus, neither it nor any of its ancestor expressions can be promoted to global.

When we fix this, the expression does get promoted, and an IndexedFilterExpression does get created. However, the performance doesn't improve very much: only to 1m 51s.

I took a more careful measurement, after suspending background tasks, and it finished in 54s. But under the same conditions, 9.5 is finishing in 32s.

The Java profile now shows nothing untoward: performance is dominated by XML parsing, serialization, whitespace stripping, indexing. So I think we'll close it with these changes (which still need to be implemented at production quality).

I don't propose to make any changes on the 9.7 branch: there's too much risk of causing regression to existing workloads.