Saxon

Thanks for reporting the problem you have found. In what maintenance version are you getting this error?

I used Saxon 9.5.0.2.

First let me point out that your stylesheet won't have the desired effect. When you do this:

<xsl:template name="main">
        <xsl:variable name="processstarttime" select="jdate:new()"/>
        <xsl:result-document href="processingResult.xml">
            <!-- cause some delay -->
            <xsl:for-each select="1 to 10000000">
                <xsl:value-of select="."/>
            </xsl:for-each>
        </xsl:result-document>
        
        <xsl:variable name="processendtime" select="jdate:new()"/>        
        <xsl:variable name="elapsedtime" select="$processendtime - $processstarttime" as="xs:duration"/>
        
        <xsl:text>&#10;</xsl:text>
        <xsl:value-of select="concat(hours-from-duration($elapsedtime), 'h ', minutes-from-duration($elapsedtime), 'm ', seconds-from-duration($elapsedtime), 's')"/>
        <xsl:text> This doesn't work in Saxon 9.5.0.2 but works in Saxon 9.4.0.6</xsl:text>
    </xsl:template>

Saxon does not evaluate a variable until it is used. The variable $processendtime is therefore evaluated BEFORE $processstarttime, and the elapsed time for your run is therefore likely to be negative. The code you inserted to cause some delay will have no useful effect. To fix this, have this code output $processstarttime as the first thing it does.

You are right that there have been some changes in the mapping of Java classes to XPath data types. These are described here:

http://www.saxonica.com/documentation/#!changes/extensibility/9.4-9.5

The relevant change is this one:

When a constructor is called the code now does what the documentation has always said: a wrapped external object is returned with no conversion. So for example Date:new() will return a wrapped java.util.Date object rather than an instance of xs:dateTime, and HashMap:new() will return a wrapped HashMap rather than an XPath map.

We had to decide whether to make the code match the documentation or vice versa, and we chose the former.

You can convert the java.util.Date value to an xs:dateTimeValue by calling the static method DateTimeValue.fromJavaDate() as an extension function.

I used Oxygen support as my proxy for this question. My objective to have a stylesheet output some tracing info where outputting its total running time is the final thing it should do. We used to do this through the jdate thing, but that stopped working as-of Oxygen 15 / Saxon 9.5. However I'm still unable to find an alternative because the initialization of the variables is not done when you would expect it. Even forcibly calling processstarttime right after setting it doesn't get me the desired effect.

        <xsl:variable name="processstarttime1" select="current-dateTime()" as="xs:dateTime"/>
        <xsl:value-of select="$processstarttime1"/>
        <xsl:text> -- start &#10;</xsl:text>
        <xsl:message>
            <!-- cause some delay -->
            <xsl:for-each select="1 to 100000">
                <xsl:value-of select="."/>
            </xsl:for-each>
        </xsl:message>
        <xsl:variable name="processendtime1" select="current-dateTime()" as="xs:dateTime"/>
        <xsl:value-of select="$processendtime1"/>
        <xsl:text> -- end &#10;</xsl:text>
        <xsl:variable name="elapsedtime1" select="$processendtime1 - $processstarttime1" as="xs:duration"/>

yields:

2013-06-20T20:00:57.814+02:00 -- start 

2013-06-20T20:00:57.814+02:00 -- end 


0h 0m 0s

How do I get the milestoning functionality back up?

I would normally use System.currentTimeMillis() to get a time value useful for performance measurement; as a static method it's convenient to call as an extension function, and it returns a long which is easy to manipulate without getting into date/time/duration complexities. If the precision isn't great enough then there's System.nanoTime.

The only other issue then is to control when the value is obtained. In Oxygen it probably works "by accident", because lazy evaluation of variables is inhibited to make debugging easier. The only certain way to be sure of the order of execution of calls in Saxon is to make one call dependent on another. The following will in practice do what you want:

<xsl:variable name="start" select="System:nanoTime()"/>

xsl:comment<xsl:value-of select="$start"/></xsl:comment>

.... do the processing ...

<xsl:variable name="end" select="System:nanoTime()"/>

xsl:messageElapsed time: <xsl:value-of select="$end - $start"/></xsl:message>

though in some future release an optimizer could evaluate $end BEFORE the "... do the processing ..." (or more likely, in parallel with it), if it chose.

Thanks! Indeed working off System:currentTimeMillis() works, but here's what I do not get: why do I need that extension function? Working off the same logic using current-dateTime() does not have the same result. This must mean that initialization occurs differently between the extension call and the regular XQuery function call. That's unexpected at least.

This works:

<xsl:variable name="start" select="System:currentTimeMillis()"/>

<xsl:value-of select="$start"/>

<xsl:text> -- start </xsl:text>

<xsl:message>

<!-- cause some delay -->

<xsl:for-each select="1 to 100000"><xsl:value-of select="."/></xsl:for-each>

</xsl:message>

<xsl:variable name="end" select="System:currentTimeMillis()"/>

<xsl:text>Elapsed time: </xsl:text><xsl:value-of select="($end - $start) div 1000"/>

<xsl:text> </xsl:text>

This does not leading to a 0 duration:

<xsl:variable name="start" select="current-dateTime()"/>

<xsl:value-of select="$start"/>

<xsl:text> -- start </xsl:text>

<xsl:message>

<!-- cause some delay -->

<xsl:for-each select="1 to 100000"><xsl:value-of select="."/></xsl:for-each>

</xsl:message>

<xsl:variable name="end" select="current-dateTime()"/>

<xsl:text>Elapsed time: </xsl:text><xsl:value-of select="($end - $start) div 1000"/>

<xsl:text> </xsl:text>

Typo in my post. The second:

<xsl:text>Elapsed time: </xsl:text><xsl:value-of select="($end - $start) div 1000"/>

should be:

<xsl:text>Elapsed time: </xsl:text><xsl:value-of select="$end - $start"/>

The point about the unexpected difference is the same.

Yikes! Wish I had been there when that came to table...not useful by design. I think I'm good for now although this part still worries me:

though in some future release an optimizer could evaluate $end BEFORE the "... do the processing ..." (or more likely, in parallel with it), if it chose.

I'll tackle that once that future optimizer comes along.