Bug #6131
closed
Unexpected function call triggers cardinality check and error
Added by Johan Gheys 10 months ago. Updated 5 months ago.
100%
Description
We are running tests to switch from Saxon-EE 11.5 to 12.3. In one of our transformations (see attachment), we now get the following error:
Type error at char 17 in expression in xsl:variable/@select on line 41 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day()
at function dow:previous-day on line 71 column 57 of day-of-week.xslt:
Focus: absent
Local variables
$date = (*unreadable*)
An empty sequence is not allowed as the first argument of dow:previous-day()
whereas with version 11.5 this went smoothly.
The variable hole-valday on line 43 of day-of-week.xslt is the empty sequence because the predicate exists($next-valday) is false. Apparently version 11.5 does lazy evaluation of the function call dow:val-to-valday($hole-val, $feastday) whereas version 12.3 does eager evaluation. I did not reopen bug #6026 because the previously reported problem was correctly fixed.
Files
| eager-evaluation.zip (3.05 KB) eager-evaluation.zip | Johan Gheys, 2023-07-17 17:05 | ||
| day-of-week.xslt (6.29 KB) day-of-week.xslt | Johan Gheys, 2023-07-19 08:44 | ||
| batch.xslt (4.34 KB) batch.xslt | Johan Gheys, 2023-07-20 17:25 |
Updated by Michael Kay 10 months ago
My first reaction is that it only worked before by chance; it might be using a different evaluation strategy in the latest release, but it's one that's perfectly legitimate. However, I'm analysing it more carefully before I can be sure of that.
(In issue 6022, Saxon was lifting an expression out of a loop, and that's only legitimate if it doesn't cause spurious dynamic errors, which is achieved by using lazy evaluation. In normal circumstances the choice between lazy and eager evaluation is one made by the processor, and isn't something you can rely on. Lazy evaluation can be expensive because it requires saving a lot of context, and Saxon tries to use it only where it's going to deliver benefits. There have been changes in the strategy in 12.x, in particular we now use a "learning" approach where we start with lazy evaluation, and then switch to eager evaluation if lazy evaluation appears to be delivering no savings. I haven't established whether that's relevant here, but it could be.)
I'm somewhat distracted by a secondary problem: I don't think the stack trace is accurate or complete. Perhaps that's because we're inside an xsl:iterate. I'm looking into that.
Updated by Johan Gheys 10 months ago
If we can't rely on the evaluation strategy, it's probably bettter to replace
<xsl:variable name="hole-valday" select="dow:val-to-valday($hole-val, $feastday)[exists($next-valday)]"/>
by
<xsl:variable name="hole-valday" select="if (exists($next-valday)) then dow:val-to-valday($hole-val, $feastday) else ()"/>
Updated by Michael Kay 10 months ago
Interestingly, if I add an xsl:message after the xsl:params in function dow:merge-valday, I get a much more complete stack trace of the failure.
Running with -T, the final part of the trace looks like this:
<xsl:function arity="2" name="dow:merge-valday" line="30" column="55" module="day-of-week.xslt">
<trace line="33" column="37" module="day-of-week.xslt">
<trace name="hole-validFromDate" line="41" column="103" module="day-of-week.xslt">
<trace name="hole-validToDate" line="42" column="126" module="day-of-week.xslt">
<trace name="hole-val" line="43" column="115" module="day-of-week.xslt">
<choose line="46" column="34" module="day-of-week.xslt">
</choose>
<trace name="merged-valday" line="61" column="77" module="day-of-week.xslt">
<xsl:next-iteration line="61" column="77" module="day-of-week.xslt">
</xsl:next-iteration>
</trace>
</trace>
</trace>
</trace>
</trace>
</xsl:function>
</trace>
</xsl:function>
<choose line="46" column="34" module="day-of-week.xslt">
</choose>
<trace name="merged-valday" line="61" column="77" module="day-of-week.xslt">
<xsl:next-iteration line="61" column="77" module="day-of-week.xslt">
</xsl:next-iteration>
</trace>
</trace>
</trace>
</trace>
<trace line="50" column="42" module="day-of-week.xslt">
</trace>
<trace name="hole-validFromDate" line="41" column="103" module="day-of-week.xslt">
<trace name="hole-validToDate" line="42" column="126" module="day-of-week.xslt">
<trace name="hole-val" line="43" column="115" module="day-of-week.xslt">
<xsl:function arity="1" name="dow:next-day" line="66" column="53" module="day-of-week.xslt">
<xsl:function arity="2" name="dow:shift-day" line="76" column="54" module="day-of-week.xslt">
<trace line="80" column="0" module="day-of-week.xslt">
<trace line="82" column="8" module="day-of-week.xslt">
</trace>
</trace>
</xsl:function>
</xsl:function>
<xsl:function arity="1" name="dow:previous-day" line="71" column="57" module="day-of-week.xslt">
<xsl:function arity="2" name="dow:shift-day" line="76" column="54" module="day-of-week.xslt">
<trace line="80" column="0" module="day-of-week.xslt">
<trace line="85" column="8" module="day-of-week.xslt">
Error at char 17 in expression in xsl:variable/@select on line 41 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day().
Found while atomizing the result of a call to dow:shift-day#2
at function dow:previous-day on line 71 column 57 of day-of-week.xslt:
That's not very easy to follow, but it does give some clues about how the order of execution has been rearranged by the optimizer. Unfortunately, though, injecting trace code into the expression can often affect the way it gets rewritten by the optimizer, so this may not be much use.
Updated by Michael Kay 10 months ago
Perhaps the -explain output will be more helpful. This shows the compiled form of the function like this:
<function name="Q{urn:dow-functions}merge-valday"
line="30"
module="file:/Users/mike/bugs/2023/6131-Gheys/day-of-week.xslt"
flags="pU"
as="*FM"
slots="15">
<arg name="Q{}valday" as="*FM"/>
<arg name="Q{}feastday" as="*AS"/>
<treat role="body"
baseUri="file:/Users/mike/bugs/2023/6131-Gheys/day-of-week.xslt"
ns="dow=urn:dow-functions map=~ xs=~ xsl=~ xml=~"
line="33"
as="FM"
diag="5|0|XTTE0780|dow:merge-valday#2">
<iterate>
<varRef role="select" name="Q{}valday" slot="0"/>
<params role="params" line="34">
<param name="Q{}previous-valday" slot="2" as="?FM">
<empty role="select"/>
<treat role="conversion" as="FM" diag="8|0|XTTE0590|previous-valday">
<check card="?" diag="8|0|XTTE0590|previous-valday">
<supplied slot="2"/>
</check>
</treat>
</param>
</params>
<let role="action" line="35" var="Q{}index" as="1ADI" slot="3">
<fn name="position"/>
<let line="36" var="Q{}current-valday" as="1" slot="4">
<first>
<sequence>
<varRef name="Q{}previous-valday" slot="2"/>
<dot type="1FM"/>
</sequence>
</first>
<let line="37" var="Q{}next-valday" as="*FM" slot="5">
<subscript>
<varRef name="Q{}valday" slot="0"/>
<arith op="+" calc="i+i">
<varRef name="Q{}index" slot="3"/>
<int val="1"/>
</arith>
</subscript>
<let line="43"
var="Q{http://saxon.sf.net/generated-variable}v0"
as="1AB"
slot="6"
flags="l">
<fn name="exists">
<varRef name="Q{}next-valday" slot="5"/>
</fn>
<let line="38" var="Q{}merged-R" slot="7">
<fn name="sort">
<fn name="distinct-values">
<sequence>
<data diag="0|0||fn:distinct-values">
<lookup>
<varRef name="Q{}current-valday" slot="4"/>
<str val="R"/>
</lookup>
</data>
<data diag="0|0||fn:distinct-values">
<lookup>
<varRef name="Q{}next-valday" slot="5"/>
<str val="R"/>
</lookup>
</data>
</sequence>
</fn>
</fn>
<let line="39" var="Q{}merged-F" slot="8">
<fn name="sort">
<fn name="distinct-values">
<sequence>
<data diag="0|0||fn:distinct-values">
<lookup>
<varRef name="Q{}current-valday" slot="4"/>
<str val="F"/>
</lookup>
</data>
<data diag="0|0||fn:distinct-values">
<lookup>
<varRef name="Q{}next-valday" slot="5"/>
<str val="F"/>
</lookup>
</data>
</sequence>
</fn>
</fn>
<let line="45"
var="Q{http://saxon.sf.net/generated-variable}v3"
as="*A"
slot="9"
flags="l">
<sequence>
<data diag="1|1||=">
<varRef name="Q{}merged-R" slot="7"/>
</data>
<data diag="1|1||=">
<varRef name="Q{}merged-F" slot="8"/>
</data>
</sequence>
<let line="43" var="Q{}hole-valday" slot="10">
<filter flags="ib">
<ufCall name="Q{urn:dow-functions}val-to-valday" tailCall="false" bSlot="0">
<ifCall line="42"
name="Q{http://www.w3.org/2005/xpath-functions/map}merge"
type="1FM">
<sequence>
<ifCall name="Q{http://www.w3.org/2005/xpath-functions/map}entry" type="1FM">
<str val="validFromDate"/>
<ufCall line="40"
name="Q{urn:dow-functions}next-day"
tailCall="false"
bSlot="1">
<treat as="AS" diag="0|0||dow:next-day">
<check card="1" diag="0|0||dow:next-day">
<cvUntyped to="AS" diag="0|0||dow:next-day">
<data diag="0|0||dow:next-day">
<lookup>
<varRef name="Q{}current-valday" slot="4"/>
<str val="validToDate"/>
</lookup>
</data>
</cvUntyped>
</check>
</treat>
</ufCall>
</ifCall>
<ifCall name="Q{http://www.w3.org/2005/xpath-functions/map}entry" type="1FM">
<str val="validToDate"/>
<ufCall line="41"
name="Q{urn:dow-functions}previous-day"
tailCall="false"
bSlot="2">
<treat as="AS" diag="0|0||dow:previous-day">
<check card="1" diag="0|0||dow:previous-day">
<cvUntyped to="AS" diag="0|0||dow:previous-day">
<data diag="0|0||dow:previous-day">
<lookup>
<varRef name="Q{}next-valday" slot="5"/>
<str val="validFromDate"/>
</lookup>
</data>
</cvUntyped>
</check>
</treat>
</ufCall>
</ifCall>
</sequence>
<map size="2">
<str val="duplicates"/>
<str val="reject"/>
<str val="duplicates-error-code"/>
<str val="XQDY0137"/>
</map>
</ifCall>
<varRef name="Q{}feastday" slot="1"/>
</ufCall>
<varRef name="Q{http://saxon.sf.net/generated-variable}v0" slot="6"/>
</filter>
<let line="45"
var="Q{http://saxon.sf.net/generated-variable}v2"
as="*A"
slot="11"
flags="l">
<data diag="1|1||=">
<lookup>
<varRef name="Q{}hole-valday" slot="10"/>
<str val="R"/>
</lookup>
</data>
<let var="Q{http://saxon.sf.net/generated-variable}v1"
as="*A"
slot="12"
flags="l">
<sequence>
<data diag="1|1||=">
<varRef name="Q{}merged-F" slot="8"/>
</data>
<data diag="1|1||=">
<lookup>
<varRef name="Q{}hole-valday" slot="10"/>
<str val="R"/>
</lookup>
</data>
</sequence>
<let line="44" var="Q{}merged-N" slot="13">
<fn name="sort">
<fn name="distinct-values">
<sequence>
<data diag="0|0||fn:distinct-values">
<lookup>
<varRef name="Q{}current-valday" slot="4"/>
<str val="N"/>
</lookup>
</data>
<data diag="0|0||fn:distinct-values">
<lookup>
<varRef name="Q{}next-valday" slot="5"/>
<str val="N"/>
</lookup>
</data>
<data diag="0|0||fn:distinct-values">
<lookup>
<varRef name="Q{}hole-valday" slot="10"/>
<str val="R"/>
</lookup>
</data>
</sequence>
</fn>
</fn>
<let line="45" var="Q{}add-now" as="1AB" slot="14">
<or op="or">
<vc op="eq" onEmpty="0">
<varRef name="Q{}index" slot="3"/>
<fn name="last"/>
</vc>
<fn name="exists">
<sequence>
<filter flags="b">
<varRef name="Q{}merged-R" slot="7"/>
<gcEE op="="
card="M:N"
comp="GAC|http://www.w3.org/2005/xpath-functions/collation/codepoint">
<data diag="1|0||=">
<dot/>
</data>
<varRef name="Q{http://saxon.sf.net/generated-variable}v1" slot="12"/>
</gcEE>
</filter>
<filter flags="b">
<varRef name="Q{}merged-F" slot="8"/>
<gcEE op="="
card="M:N"
comp="GAC|http://www.w3.org/2005/xpath-functions/collation/codepoint">
<data diag="1|0||=">
<dot/>
</data>
<varRef name="Q{http://saxon.sf.net/generated-variable}v2" slot="11"/>
</gcEE>
</filter>
<filter flags="b">
<varRef name="Q{}merged-N" slot="13"/>
<gcEE op="="
card="M:N"
comp="GAC|http://www.w3.org/2005/xpath-functions/collation/codepoint">
<data diag="1|0||=">
<dot/>
</data>
<varRef name="Q{http://saxon.sf.net/generated-variable}v3" slot="9"/>
</gcEE>
</filter>
</sequence>
</fn>
</or>
<sequence line="46">
<choose>
<varRef name="Q{}add-now" slot="14"/>
<varRef line="47" name="Q{}current-valday" slot="4"/>
</choose>
<nextIteration line="61">
<withParam name="Q{}previous-valday" as="?FM" slot="2">
<choose line="50">
<fn name="not">
<varRef name="Q{}add-now" slot="14"/>
</fn>
<ifCall line="52"
name="Q{http://www.w3.org/2005/xpath-functions/map}merge"
type="1FM">
<sequence>
<ifCall name="Q{http://www.w3.org/2005/xpath-functions/map}entry" type="1FM">
<str val="validFromDate"/>
<lookup>
<varRef name="Q{}current-valday" slot="4"/>
<str val="validFromDate"/>
</lookup>
</ifCall>
<ifCall line="53"
name="Q{http://www.w3.org/2005/xpath-functions/map}entry"
type="1FM">
<str val="validToDate"/>
<lookup>
<varRef name="Q{}next-valday" slot="5"/>
<str val="validToDate"/>
</lookup>
</ifCall>
<ifCall line="54"
name="Q{http://www.w3.org/2005/xpath-functions/map}entry"
type="1FM">
<str val="R"/>
<varRef name="Q{}merged-R" slot="7"/>
</ifCall>
<ifCall line="55"
name="Q{http://www.w3.org/2005/xpath-functions/map}entry"
type="1FM">
<str val="F"/>
<varRef name="Q{}merged-F" slot="8"/>
</ifCall>
<ifCall line="56"
name="Q{http://www.w3.org/2005/xpath-functions/map}entry"
type="1FM">
<str val="N"/>
<varRef name="Q{}merged-N" slot="13"/>
</ifCall>
</sequence>
<map size="2">
<str val="duplicates"/>
<str val="reject"/>
<str val="duplicates-error-code"/>
<str val="XTDE3365"/>
</map>
</ifCall>
</choose>
</withParam>
</nextIteration>
</sequence>
</let>
</let>
</let>
</let>
</let>
</let>
</let>
</let>
</let>
</let>
</let>
</let>
</iterate>
</treat>
</function>
Again, nothing obviously wrong with this, but it doesn't tell us much.
Updated by Michael Kay 10 months ago
One interesting difference between the 11.x and 12.x SEF expansions is that in 12.x, in the expression on line 43
let $hole-valday := dow:val-to-valday(...)[exists($next-valday)]
the predicate exists($next-valday) has been loop-lifted to avoid repeated evaluation, whereas this hasn't happened in 11.x.
It's interesting to ask what the best strategy here is. Ideally, if $next-valday is empty, we ideally don't want to evaluate the function call at all. At the same time, though, we don't want a failure in evaluating $next-valday to propagate if dow:val-to-valday() returns an empty sequence (so that the predicate is never needed). In theory, the approach we should be using is to loop-lift the predicate, but with forced lazy evaluation, so it is only evaluated once, on the first item that dow:val-to-valday() returns.
There's an alternative approach we are now using in some cases (not this one) which is to evaluate the predicate up front and catch any errors. If the result is false, we don't evaluate the function call. If the result is true, we evaluate the function call unconditionally. If the result is an error, we evaluate the function call and return empty if empty, or throw the error if non-empty.
Updated by Michael Kay 10 months ago
I've switched on some internal instrumentation and have established that although a LearningEvaluator is being used, it's never executed often enough to trigger a change in strategy.
I'm now focusing back on the actual exception. The exception is being thrown from CardinalityCheckingIterator#59 checking the arguments to a call on dow:previous-day() at line 41. The value of $next-valday is an empty sequence, so the argument will also be an empty sequence.
Going down the Java stack, we can see the call on dow:previous-day() on line 41, called from the map initialiser on line 42, called while evaluating $hole-val on line 43, called while evaluating $merged-N. Further down we have the evaluation of xsl:iterate. All this is being done lazily, so the logic is very hard to follow.
But I think my initial analysis is correct: we're using a valid evaluation strategy and the code only worked before because we did things a bit differently.
Updated by Michael Kay 10 months ago
Now looking at the diagnostics.
We go through a deep sequence of try/catch clauses until we eventually hit an atomiser, and at this point it adds the message "Found while evaluating the second operand of "="". This is rather useless without knowning where the "=" sign is. I fact the expression in question is . = ($merged-F, $hole-valday?R) on line 45. I've improved that message -- but we're not actually seeing it as the final outcome anyway.
There seems to be a problem that this code in Atomizer is discarding the original exception (in order to improve the message) and this is losing information.
Updated by Johan Gheys 10 months ago
I don't know if the information is relevant, but when testing with 2 items instead of 3 (by putting line 39 in batch.xslt in comments), version 12.3 does work correctly.
Updated by Johan Gheys 10 months ago
And what is even stranger: when the test contains 3 items again afterwards, version 12.3 suddenly works correctly:
C:\Data\MyProjects\upm-batch\src\test\resources\saxon\eager-evaluation-6131>java -jar C:\Data\MyProjects\upm-batch\src\test\lib\saxon-ee-12.3.jar -xsl:batch.xslt -it
Batch execution starting...
input:
val=[2024-07-01,2024-07-01] day=R1
val=[2024-07-08,2024-07-08] day=R1
val=[2024-07-15,2024-07-15] day=R1
output:
val=[2024-07-01,2024-07-15] day=R1N234567
Batch execution succeeded
Execution time: 0.097s
Or am I dreaming?
Updated by Johan Gheys 10 months ago
After a few runs, I get back the reported error, but now with an extended stack trace:
Error at char 17 in expression in xsl:variable/@select on line 41 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day().
Found while atomizing the second operand of '='
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}
Context position: 1
Local variables
$merged-F = ()
$hole-valday = (*unreadable*)
invoked by unknown caller (class net.sf.saxon.value.MemoClosure)
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}
Context position: 2
Local variables
$valday = (map{"validToDate":"2024-07-01","R":1,"validFromDate":"2024-07-01"}, map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}, map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"})
$feastday = ()
$previous-valday = map{"validToDate":"2024-07-08","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$index = 2
$current-valday = map{"validToDate":"2024-07-08","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$next-valday = map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
$vv:v0 = true()
$merged-R = 1
$merged-F = ()
$vv:v3 = 1
$hole-valday = (*unreadable*)
$vv:v2 = (*unreadable*)
$vv:v1 = (*unreadable*)
$merged-N = (*unreadable*)
$add-now = (*unreadable*)
invoked by xsl:iterate at file:/C:/Data/MyProjects/upm-batch/src/test/resources/saxon/eager-evaluation-6131/day-of-week.xslt#33
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus: absent
Local variables
$valday = (map{"validToDate":"2024-07-01","R":1,"validFromDate":"2024-07-01"}, map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}, map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"})
$feastday = ()
$previous-valday = map{"validToDate":"2024-07-08","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$index = 2
$current-valday = map{"validToDate":"2024-07-08","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$next-valday = map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
$vv:v0 = true()
$merged-R = 1
$merged-F = ()
$vv:v3 = 1
$hole-valday = (*unreadable*)
$vv:v2 = (*unreadable*)
$vv:v1 = (*unreadable*)
$merged-N = (*unreadable*)
$add-now = (*unreadable*)
invoked by unknown caller (class net.sf.saxon.value.MemoClosure)
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus: absent
Local variables
$valday = (map{"validToDate":"2024-07-01","R":1,"validFromDate":"2024-07-01"}, map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}, map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"})
$feastday = ()
invoked by function call at file:/C:/Data/MyProjects/upm-batch/src/test/resources/saxon/eager-evaluation-6131/batch.xslt#37
at template local:test on line 34 column 36 of batch.xslt:
invoked by xsl:call-template at file:/C:/Data/MyProjects/upm-batch/src/test/resources/saxon/eager-evaluation-6131/batch.xslt#15
at template xsl:initial-template on line 11 column 56 of batch.xslt:
Focus: absent
Local variables
$vv:v0 = false()
$startTime = xs:dateTimeStamp("2023-07-18T17:24:23.476+02:00")
An empty sequence is not allowed as the first argument of dow:previous-day(). Found while atomizing the second operand of '='
Updated by Johan Gheys 10 months ago
And sometimes the stack trace looks like this:
Type error at char 17 in expression in xsl:variable/@select on line 41 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day()
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
Context position: 1
Local variables
$current-valday = map{"validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$next-valday = ()
An empty sequence is not allowed as the first argument of dow:previous-day()
I really don't understand what is going on, but no doubt there will be a logical explanation.
Updated by Johan Gheys 10 months ago
- File day-of-week.xslt day-of-week.xslt added
For your information, if I make the following 2 changes to dow:merge-valday() (see attachment), version 12.3 also works fine:
- line 43: replace dow:val-to-valday() with dow:val-to-continuous-valday() so that dow:merge-valday() is no longer called recursively
- line 45: replace $index eq last() with empty($next-valday)
Updated by Johan Gheys 10 months ago
- File batch.xslt batch.xslt added
With the above adjustments, version 12.3 works fine as long as the number of items is less than 22, which is very similar to the problem reported in bug #6022. To illustrate this, I modified the test data (see attachment). The result is now the following error message:
Type error at char 17 in expression in xsl:variable/@select on line 63 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day()
at function dow:merge-valday on line 52 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-05-01","R":7,"validFromDate":"2024-05-01"}
Context position: 22
Local variables
$valday = (map{"validToDate":"2023-12-10","R":7,"validFromDate":"2023-12-10"}, map{"validToDate":"2023-12-17","R": (6, 7) ,"validFromDate":"2023-12-16"}, map{"validToDate":"2023-12-25","R": (6, 7) ,"validFromDate":"2023-12-23"}, ... [22])
$feastday = ("2023-12-25", "2024-01-01", "2024-04-01", ... [4])
$previous-valday = map{"validToDate":"2024-05-01","F":(),"N": (1, 2, 3, ... [5]),"R": (6, 7) ,"validFromDate":"2023-12-10"}
$index = 22
$current-valday = map{"validToDate":"2024-05-01","F":(),"N": (1, 2, 3, ... [5]),"R": (6, 7) ,"validFromDate":"2023-12-10"}
$next-valday = ()
$vv:v0 = false()
$merged-R = (6, 7)
$merged-F = ()
$vv:v3 = (6, 7)
$hole-valday = map{"validToDate":"2024-04-30","R": (1, 2) ,"validFromDate":"2024-04-29"}
$vv:v2 = (1, 2)
$vv:v1 = (1, 2)
$merged-N = (1, 2, 3, ... [5])
$add-now = false()
invoked by xsl:iterate at file:/C:/Data/MyProjects/upm-batch/src/test/resources/saxon/eager-evaluation-6131/day-of-week.xslt#55
at function dow:merge-valday on line 52 column 55 of day-of-week.xslt:
Focus: absent
Local variables
$valday = (map{"validToDate":"2023-12-10","R":7,"validFromDate":"2023-12-10"}, map{"validToDate":"2023-12-17","R": (6, 7) ,"validFromDate":"2023-12-16"}, map{"validToDate":"2023-12-25","R": (6, 7) ,"validFromDate":"2023-12-23"}, ... [22])
$feastday = ("2023-12-25", "2024-01-01", "2024-04-01", ... [4])
$previous-valday = map{"validToDate":"2024-05-01","F":(),"N": (1, 2, 3, ... [5]),"R": (6, 7) ,"validFromDate":"2023-12-10"}
$index = 22
$current-valday = map{"validToDate":"2024-05-01","F":(),"N": (1, 2, 3, ... [5]),"R": (6, 7) ,"validFromDate":"2023-12-10"}
$next-valday = ()
$vv:v0 = false()
$merged-R = (6, 7)
$merged-F = ()
$vv:v3 = (6, 7)
$hole-valday = map{"validToDate":"2024-04-30","R": (1, 2) ,"validFromDate":"2024-04-29"}
$vv:v2 = (1, 2)
$vv:v1 = (1, 2)
$merged-N = (1, 2, 3, ... [5])
$add-now = false()
invoked by unknown caller (class net.sf.saxon.value.MemoClosure)
at function dow:merge-valday on line 52 column 55 of day-of-week.xslt:
Focus: absent
Local variables
$valday = (map{"validToDate":"2023-12-10","R":7,"validFromDate":"2023-12-10"}, map{"validToDate":"2023-12-17","R": (6, 7) ,"validFromDate":"2023-12-16"}, map{"validToDate":"2023-12-25","R": (6, 7) ,"validFromDate":"2023-12-23"}, ... [22])
$feastday = ("2023-12-25", "2024-01-01", "2024-04-01", ... [4])
invoked by function call at file:/C:/Data/MyProjects/upm-batch/src/test/resources/saxon/eager-evaluation-6131/batch.xslt#37
at template local:test on line 34 column 36 of batch.xslt:
invoked by xsl:call-template at file:/C:/Data/MyProjects/upm-batch/src/test/resources/saxon/eager-evaluation-6131/batch.xslt#15
at template xsl:initial-template on line 11 column 56 of batch.xslt:
Focus: absent
Local variables
$vv:v0 = false()
$startTime = xs:dateTimeStamp("2023-07-20T17:16:48.779+02:00")
An empty sequence is not allowed as the first argument of dow:previous-day()
Updated by Michael Kay 10 months ago
as long as the number of items is less than 22
Indeed, that's strongly suggestive of the evaluation strategy changing after the first 20 evaluations. I suspected that and looked for it and didn't see it happening, so I obviously need to look more carefully.
Updated by Michael Kay 6 months ago
I'm revisiting this after an incorrigible delay, and starting by looking at why the diagnostics aren't up to scratch.
I've established that what we are reporting appears to be a secondary error occurring during the creation of diagnostics for the first error.
Specifically, SlotManagerEE.showStackFrame() is calling Err.depictSequence(), which is calling Sequence.materialize(), which triggers the evaluation of a lazily-evaluated variable, which fails with a secondary error.
Having fixed that, I'm starting to get some decent diagnostics when I run in the IntelliJ debugger:
Error at char 18 in expression in xsl:variable/@select on line 41 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day().
Found while atomizing the second operand of '=' in {$hole-valday ? "R"} on line 45
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}
Context position: 1
Local variables
$merged-F = ()
$hole-valday = (*not-yet-evaluated sequence*)
invoked by lazy evaluation of ($merged-F, ...)
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}
Context position: 2
Local variables
$valday = (map{"validToDate":"2024-07-01","R":1,"validFromDate":"2024-07-01"}, map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}, map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"})
$feastday = ()
$previous-valday = map{"validToDate":"2024-07-08","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$index = 2
$current-valday = map{"validToDate":"2024-07-08","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$next-valday = map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
$vv:v0 = (*not-yet-evaluated singleton*)
$merged-R = 1
$merged-F = ()
$vv:v3 = (*not-yet-evaluated sequence*)
$hole-valday = (*not-yet-evaluated sequence*)
$vv:v2 = (*not-yet-evaluated sequence*)
$vv:v1 = (*lazily evaluated*)
$merged-N = (*not-yet-evaluated sequence*)
$add-now = false()
Unfortunately at the moment this isn't replicated when I run outside the debugger; it looks as if a toString() call invoked by the debugger is having (in this case beneficial) side-effects of lazily-evaluating some null value.
Updated by Michael Kay 6 months ago
Adding some println() diagnostics, with debugging off, XsltController on completion is calling handleXPathException() around line 894, and this is coming back with a secondary exception - or more accurately, it is re-throwing the original exception (which makes it very hard to find out where this is happening).
There are two clues in the output, which reads:
Type error at char 18 in expression in xsl:variable/@select on line 41 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day()
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
Context position: 1
Local variables
$next-valday = (*null*)
(a) Note the omission of the line Found while atomizing the second operand of '=' in {$hole-valday ? "R"} on line 45
(b) The stack-frame starts with $next-valday = null; but the debugger version doesn't even attempt to output a variable whose value is null.
Updated by Michael Kay 6 months ago
The "found while atomising" line in the stack trace for the debugger case indicates that there's an Atomizer on the stack. Its absence for the non-debugging case indicates that there isn't. In fact, there are many differences between the two stack traces. It seems that the two cases diverge well before we ever hit a debugger breakpoint.
Updated by Michael Kay 6 months ago
Now trying it on SaxonCS (in Rider). Here the output in debugging mode is the same as non-debugging mode, and corresponds to the non-debugging output in SaxonJ. So perhaps by studying it with the SaxonCS/Rider debugger I can get a better understanding of what's going on.
At the point we show the stack (in StandardDiagnostics.locgStackTrace()) the stack has 15 slots of which only slots 4 and 5, corresponding to variables $current-valday and $next-valday are non-null. After showing these variables, we exit because context.originator is null.
If I change this so we carry on when originator==null (provided that the calling context is not null) then we get a more complete stack trace:
at function dow:merge-valday on line 30 column 5 of day-of-week.xslt:
Focus
Context item: map{"validFromDate":"2024-07-15","validToDate":"2024-07-15","R":1}
Context position: 1
Local variables
$current-valday = map{"validFromDate":"2024-07-01","validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1}
$next-valday = (*null*)
at function dow:merge-valday on line 30 column 5 of day-of-week.xslt:
Focus
Context item: map{"validFromDate":"2024-07-15","validToDate":"2024-07-15","R":1}
Context position: 1
Local variables
$feastday = ()
$current-valday = map{"validFromDate":"2024-07-01","validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1}
$next-valday = (*null*)
$vv:v0 = (*not-yet-evaluated singleton*)
invoked by lazy evaluation of dow:val-to-valday(...)[$vv:v0] on line 43
at function dow:merge-valday on line 30 column 5 of day-of-week.xslt:
Focus
Context item: map{"validFromDate":"2024-07-15","validToDate":"2024-07-15","R":1}
Context position: 3
Local variables
$valday = (map{"validFromDate":"2024-07-01","validToDate":"2024-07-01","R":1}, map{"validFromDate":"2024-07-08","validToDate":"2024-07-08","R":1}, map{"validFromDate":"2024-07-15","validToDate":"2024-07-15","R":1})
$feastday = ()
$previous-valday = map{"validFromDate":"2024-07-01","validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1}
$index = 3
$current-valday = map{"validFromDate":"2024-07-01","validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1}
$next-valday = (*null*)
$vv:v0 = (*not-yet-evaluated singleton*)
$merged-R = 1
$merged-F = ()
$vv:v3 = (*not-yet-evaluated sequence*)
$hole-valday = (*not-yet-evaluated sequence*)
$vv:v2 = (*not-yet-evaluated sequence*)
$vv:v1 = (*lazily evaluated*)
$merged-N = (2, 3, 4, ... [6])
$add-now = false()
invoked by xsl:iterate at file:///Users/mike/bugs/2023/6131-Gheys/day-of-week.xslt#33
at function dow:merge-valday on line 30 column 5 of day-of-week.xslt:
Focus: absent
Local variables
$valday = (map{"validFromDate":"2024-07-01","validToDate":"2024-07-01","R":1}, map{"validFromDate":"2024-07-08","validToDate":"2024-07-08","R":1}, map{"validFromDate":"2024-07-15","validToDate":"2024-07-15","R":1})
$feastday = ()
$previous-valday = map{"validFromDate":"2024-07-01","validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1}
$index = 3
$current-valday = map{"validFromDate":"2024-07-01","validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1}
$next-valday = (*null*)
$vv:v0 = (*not-yet-evaluated singleton*)
$merged-R = 1
$merged-F = ()
$vv:v3 = (*not-yet-evaluated sequence*)
$hole-valday = (*not-yet-evaluated sequence*)
$vv:v2 = (*not-yet-evaluated sequence*)
$vv:v1 = (*lazily evaluated*)
$merged-N = (2, 3, 4, ... [6])
$add-now = false()
invoked by lazy evaluation of xsl:iterate on line 33
at function dow:merge-valday on line 30 column 5 of day-of-week.xslt:
Focus: absent
Local variables
$valday = (map{"validFromDate":"2024-07-01","validToDate":"2024-07-01","R":1}, map{"validFromDate":"2024-07-08","validToDate":"2024-07-08","R":1}, map{"validFromDate":"2024-07-15","validToDate":"2024-07-15","R":1})
$feastday = ()
invoked by function call at file:///Users/mike/bugs/2023/6131-Gheys/batch.xslt#37
at template local:test on line 34 column 5 of batch.xslt:
invoked by xsl:call-template at file:///Users/mike/bugs/2023/6131-Gheys/batch.xslt#15
at template xsl:initial-template on line 11 column 5 of batch.xslt:
Focus: absent
Local variables
$vv:v0 = false()
$startTime = xs:dateTimeStamp("2023-11-14T09:42:14.057Z")
The SaxonJ output after this change is the same.
Updated by Michael Kay 6 months ago
The missing "originator" field that caused the stack trace to be truncated comes from SingletonClosure, which creates a copy of the context without marking its origins. With this fixed, we now get the trace:
Type error at char 18 in expression in xsl:variable/@select on line 41 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day()
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
Context position: 1
Local variables
$next-valday = (*null*)
invoked by lazy evaluation of convert($next-valday ? "validFromDate") on line 41
at function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus &c&c
So what exactly does it mean by saying that $next-valday is (null)? It turns out that it's actually an empty sequence (I'll improve the display).
How does it come to be an empty sequence? Well, the stack now tells us that $valday is a sequence of three maps, and $index is 3, so $next-valday which is computed as $valday[$index + 1] should indeed be an empty sequence.
The regression from previous releases appears to be because the expression is being evaluated at all, when it was previously evaluated lazily and therefore no error was detected. Let's now look at that.
Updated by Michael Kay 6 months ago
The failure comes when we evaluate $hole-validToDate on line 41.
The stack trace now tells us this is invoked by lazy evaluation of $hole-valday on line 43.
Evaluating $hole-valday presumably triggers evaluation of $hole-validToDate via evaluation of $hole-val on line 42, which references $hole-validToDate.
The expression is
<xsl:variable name="hole-valday" select="dow:val-to-valday($hole-val, $feastday)[exists($next-valday)]"/>
and presumably earlier releases were not calling dow:val-to-valday($hole-val, $feastday) because they first established that the predicate exists($next-valday) was false.
In fact there has been a clarification to the spec in 4.0, which we have also treated as applying to earlier releases: it says that in a filter expression E[C], you shouldn't evaluate the predicate C if the result of evaluating E is empty. The purpose of the change is to give more predictable behaviour if evaluation of the predicate C throws an error in this case. So it might be that the change in Saxon behaviour is a consequence of this spec change.
The stylesheet executes successfully if we change this line to:
select="if (exists($next-valday)) then dow:val-to-valday($hole-val, $feastday) else ()"
So, as suggested earlier in this thread, I think we've confirmed that the regression occurs because the stylesheet was relying on implementation-defined behaviour that has changed between releases, and we've now established more clearly exactly what change was made and why.
In the course of investigating it we've identified some significant improvements to diagnostics, and I'm going to pursue that to see if we can make further improvements based on this test case.
I'm none the wiser as to why the IntelliJ debugger is taking a completely different path. I'll check to see if that's still the case after making these changes, but it's a secondary issue and I don't really know how to make progress on it.
Updated by Johan Gheys 6 months ago
Thanks Michael for your expert view on this problem. I am glad that this fix will normally be in version 12.4. Just a small additional question: does this fix also solve the problem when there are more than 20 items (see comments #12, #13 and #14)?
Updated by Johan Gheys 6 months ago
Sorry, silly question. Of course, adding the test exists($next-valday) will solve all cases.
Updated by Michael Kay 6 months ago
I have enhanced the display of variables in the stack trace so that system-allocated variables, where possible, now identify the expression to which they are bound. For example:
$vv:v0 {fn:current-date() lt xs:date("2000-01-01")} = false()
$merged-R = 1
$merged-F = ()
$vv:v3 {($merged-R, ...)} = (*not-yet-evaluated sequence*)
Updated by Michael Kay 6 months ago
One further glitch in the stack trace report: it contains the line
invoked by function call at file:/Users/mike/bugs/2023/6131-Gheys/batch.xslt#37
but there is no function call at that location. The call is actually at line 43. The problem seems to be a consequence of variable inlining and/or constant folding.
In fact the problem occurs in UserFunctionCall.copy() - when a function call is copied in the course of an optimization rewrite, the line number for the new function is not that of the old function, but that of the first argument, which in this case is some way off, because the argument is a variable reference that has been replaced by its constant value. Fixed.
Updated by Michael Kay 6 months ago
Note that whatever caused the problem with the IntelliJ debugger seems to have gone away. I am now getting the same output whether using "Run" or "Debug". Here is the final output:
Type error at char 18 in expression in xsl:variable/@select on line 41 column 103 of day-of-week.xslt:
XPTY0004 An empty sequence is not allowed as the first argument of dow:previous-day()
During lazy evaluation of convert($next-valday ? "validFromDate") on line 41 of file:/Users/mike/bugs/2023/6131-Gheys/day-of-week.xslt
Focus
Context item: map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
Context position: 1
Local variables
$next-valday = ()
During lazy evaluation of dow:val-to-valday(...)[$vv:v0] on line 43 of file:/Users/mike/bugs/2023/6131-Gheys/day-of-week.xslt
Focus
Context item: map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
Context position: 1
Local variables
$feastday = ()
$current-valday = map{"validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$next-valday = ()
$vv:v0 {fn:exists(...)} = (*not-yet-evaluated singleton*)
In function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus
Context item: map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"}
Context position: 3
Local variables
$valday = (map{"validToDate":"2024-07-01","R":1,"validFromDate":"2024-07-01"}, map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}, map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"})
$feastday = ()
$previous-valday = map{"validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$index = 3
$current-valday = map{"validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$next-valday = ()
$vv:v0 {fn:exists(...)} = (*not-yet-evaluated singleton*)
$merged-R = 1
$merged-F = ()
$vv:v3 {($merged-R, ...)} = (*not-yet-evaluated sequence*)
$hole-valday = (*not-yet-evaluated sequence*)
$vv:v2 {$hole-valday ? "R"} = (*not-yet-evaluated sequence*)
$vv:v1 {($merged-F, ...)} = (*lazily evaluated*)
$merged-N = (2, 3, 4, ... [6])
$add-now = false()
invoked by xsl:iterate at file:/Users/mike/bugs/2023/6131-Gheys/day-of-week.xslt#33
During lazy evaluation of xsl:iterate on line 33 of file:/Users/mike/bugs/2023/6131-Gheys/day-of-week.xslt
Focus: absent
Local variables
$valday = (map{"validToDate":"2024-07-01","R":1,"validFromDate":"2024-07-01"}, map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}, map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"})
$feastday = ()
$previous-valday = map{"validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$index = 3
$current-valday = map{"validToDate":"2024-07-15","F":(),"N": (2, 3, 4, ... [6]),"R":1,"validFromDate":"2024-07-01"}
$next-valday = ()
$vv:v0 {fn:exists(...)} = (*not-yet-evaluated singleton*)
$merged-R = 1
$merged-F = ()
$vv:v3 {($merged-R, ...)} = (*not-yet-evaluated sequence*)
$hole-valday = (*not-yet-evaluated sequence*)
$vv:v2 {$hole-valday ? "R"} = (*not-yet-evaluated sequence*)
$vv:v1 {($merged-F, ...)} = (*lazily evaluated*)
$merged-N = (2, 3, 4, ... [6])
$add-now = false()
In function dow:merge-valday on line 30 column 55 of day-of-week.xslt:
Focus: absent
Local variables
$valday = (map{"validToDate":"2024-07-01","R":1,"validFromDate":"2024-07-01"}, map{"validToDate":"2024-07-08","R":1,"validFromDate":"2024-07-08"}, map{"validToDate":"2024-07-15","R":1,"validFromDate":"2024-07-15"})
$feastday = ()
invoked by function call at file:/Users/mike/bugs/2023/6131-Gheys/batch.xslt#43
In template local:test on line 34 column 36 of batch.xslt:
invoked by xsl:call-template at file:/Users/mike/bugs/2023/6131-Gheys/batch.xslt#15
In template xsl:initial-template on line 11 column 56 of batch.xslt:
Focus: absent
Local variables
$vv:v0 {fn:current-date() lt xs:date("2000-01-01")} = false()
$startTime = xs:dateTimeStamp("2023-11-14T15:17:07.19682Z")
An empty sequence is not allowed as the first argument of dow:previous-day()
Updated by Michael Kay 6 months ago
- Category set to Diagnostics
- Status changed from New to Resolved
- Assignee set to Michael Kay
- Applies to branch 12, trunk added
- Fix Committed on Branch 12, trunk added
- Platforms .NET, Java added
Updated by Johan Gheys 6 months ago
This is indeed a spectacular improvement of the info in the error message. Thanks a lot!
Updated by O'Neil Delpratt 5 months ago
- Status changed from Resolved to Closed
- % Done changed from 0 to 100
- Fixed in Maintenance Release 12.4 added
Bug fix applied in the Saxon 12.4 maintenance release
Please register to edit this issue
.