Saxon

The transform works when the threshold is lowered, e.g. by setting this on the command-line: --thresholdForFunctionInlining:10.

I think that lowering the threshold prevents it happening for this particular case, simply because the function in question has a size above that threshold. That means that the bug is still there, it just needs a bigger function to trigger it.

The code currently has a defence mechanism to prevent infinite recursion during optimization, and it seems this defence mechanism isn't good enough. It prevents UserFunctionReference.optimize() doing anything if it is activated while it is already active; but the loop here is more subtle.

The code in UserFunctionReference.optimize() causes optimization of the body of the function that is referenced in the case where that function is an anonymous inline function: that's because we are essentially treating the inline function and the reference to it as a unit. I don't know the exact nature of the looping but it's not a simple recursion of the kind we defend against; it seems to involve a function being inlined, and the caller being optimized, which causes further inlining, ad infinitum. I think a suitable defence might be to limit the number of times any given function can be inlined - this is probably a useful thing to do anyway, since inlining a function thousands of times can cause memory bloat and also affects export files.

There's clearly pathological compile time performance for taskBug2.xsl. The -explain trace shows a long sequence of function inlinings, like this:

OPT : At line 70 of file:/Users/mike/bugs/2019/2321-lockett/taskBug2.xsl
OPT : Moved function task:create-monadic-task inline: 
OPT : Expression after rewrite: let $apply-fn := (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_716157500#2))(?, $apply-fn) return (Q{http://www.w3.org/2005/xpath-functions/map}merge(Block(Q{http://www.w3.org/2005/xpath-functions/map}entry("apply", $apply-fn), Q{http://www.w3.org/2005/xpath-functions/map}entry("bind", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_984213526#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("then", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_942986815#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("fmap", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_1879034789#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("async", Q{http://ns.saxonica.com/anonymous-type}f_729864207#1($apply-fn))), net.sf.saxon.ma.map.DictionaryMap@5a01ccaa))
OPT : At line 70 of file:/Users/mike/bugs/2019/2321-lockett/taskBug2.xsl
OPT : Moved function task:create-monadic-task inline: 
OPT : Expression after rewrite: let $apply-fn := (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_716157500#2))(?, $apply-fn) return (Q{http://www.w3.org/2005/xpath-functions/map}merge(Block(Q{http://www.w3.org/2005/xpath-functions/map}entry("apply", $apply-fn), Q{http://www.w3.org/2005/xpath-functions/map}entry("bind", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_984213526#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("then", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_942986815#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("fmap", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_1879034789#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("async", Q{http://ns.saxonica.com/anonymous-type}f_729864207#1($apply-fn))), net.sf.saxon.ma.map.DictionaryMap@5a01ccaa))
OPT : At line 70 of file:/Users/mike/bugs/2019/2321-lockett/taskBug2.xsl
OPT : Moved function task:create-monadic-task inline: 
OPT : Expression after rewrite: let $apply-fn := (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_716157500#2))(?, $apply-fn) return (Q{http://www.w3.org/2005/xpath-functions/map}merge(Block(Q{http://www.w3.org/2005/xpath-functions/map}entry("apply", $apply-fn), Q{http://www.w3.org/2005/xpath-functions/map}entry("bind", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_984213526#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("then", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_942986815#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("fmap", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_1879034789#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("async", Q{http://ns.saxonica.com/anonymous-type}f_729864207#1($apply-fn))), net.sf.saxon.ma.map.DictionaryMap@5a01ccaa))
OPT : At line 70 of file:/Users/mike/bugs/2019/2321-lockett/taskBug2.xsl
OPT : Moved function task:create-monadic-task inline: 
OPT : Expression after rewrite: let $apply-fn := (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_716157500#2))(?, $apply-fn) return (Q{http://www.w3.org/2005/xpath-functions/map}merge(Block(Q{http://www.w3.org/2005/xpath-functions/map}entry("apply", $apply-fn), Q{http://www.w3.org/2005/xpath-functions/map}entry("bind", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_984213526#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("then", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_942986815#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("fmap", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_1879034789#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("async", Q{http://ns.saxonica.com/anonymous-type}f_729864207#1($apply-fn))), net.sf.saxon.ma.map.DictionaryMap@5a01ccaa))
OPT : At line 70 of file:/Users/mike/bugs/2019/2321-lockett/taskBug2.xsl
OPT : Moved function task:create-monadic-task inline: 
OPT : Expression after rewrite: let $apply-fn := (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_716157500#2))(?, $apply-fn) return (Q{http://www.w3.org/2005/xpath-functions/map}merge(Block(Q{http://www.w3.org/2005/xpath-functions/map}entry("apply", $apply-fn), Q{http://www.w3.org/2005/xpath-functions/map}entry("bind", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_984213526#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("then", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_942986815#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("fmap", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_1879034789#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("async", Q{http://ns.saxonica.com/anonymous-type}f_729864207#1($apply-fn))), net.sf.saxon.ma.map.DictionaryMap@5a01ccaa))
OPT : At line 70 of file:/Users/mike/bugs/2019/2321-lockett/taskBug2.xsl
OPT : Moved function task:create-monadic-task inline: 
OPT : Expression after rewrite: let $apply-fn := (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_716157500#2))(?, $apply-fn) return (Q{http://www.w3.org/2005/xpath-functions/map}merge(Block(Q{http://www.w3.org/2005/xpath-functions/map}entry("apply", $apply-fn), Q{http://www.w3.org/2005/xpath-functions/map}entry("bind", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_984213526#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("then", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_942986815#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("fmap", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_1879034789#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("async", Q{http://ns.saxonica.com/anonymous-type}f_729864207#1($apply-fn))), net.sf.saxon.ma.map.DictionaryMap@5a01ccaa))
OPT : At line 70 of file:/Users/mike/bugs/2019/2321-lockett/taskBug2.xsl
OPT : Moved function task:RUN-UNSAFE inline: 
OPT : Expression after rewrite: let $task := let $apply-fn := Q{http://ns.saxonica.com/anonymous-type}f_2030562336#1 return (Q{http://www.w3.org/2005/xpath-functions/map}merge(Block(Q{http://www.w3.org/2005/xpath-functions/map}entry("apply", $apply-fn), Q{http://www.w3.org/2005/xpath-functions/map}entry("bind", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_984213526#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("then", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_942986815#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("fmap", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_1879034789#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("async", Q{http://ns.saxonica.com/anonymous-type}f_729864207#1($apply-fn))))) return (tail(Q{http://saxon.sf.net/}apply(exactly-one((Q{http://saxon.sf.net/}apply($task, ["apply"])) treat as function(*)), SquareArrayConstructor($realworldEl))))
OPT : At line 92 of file:/Users/mike/bugs/2019/2321-lockett/taskBug2.xsl
OPT : Inlined references to $task
OPT : Expression after rewrite: tail(Q{http://saxon.sf.net/}apply(exactly-one(Q{http://saxon.sf.net/}apply(let $apply-fn := Q{http://ns.saxonica.com/anonymous-type}f_2030562336#1 return (Q{http://www.w3.org/2005/xpath-functions/map}merge(Block(Q{http://www.w3.org/2005/xpath-functions/map}entry("apply", $apply-fn), Q{http://www.w3.org/2005/xpath-functions/map}entry("bind", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_984213526#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("then", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_942986815#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("fmap", (fnCoercer(Q{http://ns.saxonica.com/anonymous-type}f_1879034789#2))(?, $apply-fn)), Q{http://www.w3.org/2005/xpath-functions/map}entry("async", Q{http://ns.saxonica.com/anonymous-type}f_729864207#1($apply-fn))))), ["apply"])), SquareArrayConstructor($realworldEl)))

and at this point it appears to hang.

The cut-off limit of 100 nested inlinings is taking effect, but there's something going wrong after it takes effect, and it's very hard to establish what, because by that time we've got 100 nested optimization operations on the stack all needing to be finished tidily. It feels like the cut-off mechanism is just too crude. We shouldn't be attempting inlining of a function as complex as this.

The reason it passes the complexity checks is that most of the complexity is within anonymous inline functions. These are treated as simple values; they don't contribute to the "expression size" calculation, and recursive calls within the anonymous functions are not considered; but they do add to the cost of the re-optimization that is performed after an inlining operation.

I have made two changes: (a) within OptimizerEE.tryInlineFunctionCall(), when optimizing the rewritten function call, we set a flag in the ExpressionVisitor that prevents further function inlining during this optimization phase; and (b) in UserFunctionCall.optimize(), we disable the optimization that occurs if the call has been inlined; this action is redundant because it has already been done as part of the inlining process.

With these changes, we avoid the deeply recursive repeated optimization, stopped only by the artificial max limit.

But it still hangs after the function inlining is complete. We now have a better chance of working out why it is hanging.

In UserFunctionReference.optimize, I have inserted a counter to show how many times the referenced anonymous function is being optimized. The counters get quite high, e.g. 3834, which is clearly excessive. However, they reach a limit before the process hangs/loops, so this is not the root cause of the problem.

After these counters stop rising, we're seeing a large (infinite?) number of calls on SystemFunctionCall.typeCheck(), especially on functions saxon:apply, map:entry, and map:merge. The JProfiler call graph suggests these are recursive.counter

I have solved the problem by adding counters to UserFunctionReference that limit the number of times a typeCheck() or optimize() call can cause the referenced function to be processed.

This change makes the change to ExpressionVisitor unnecessary, so I am reverting that. So the only changes are

(a) the counters in UserFunctionReference (b) UserFunctionCall no longer re-optimizes the function body after it is inlined.

XSLT 3.0 test suite test added for regression testing: -s:higher-order-functions -t:higher-order-functions-075

(Test stylesheet is basically a renamed copy of taskBug2.xsl.)