Bug #6295
closed![Author: A Galtman](https://www.gravatar.com/avatar/cc758b846fc3ecdad3645517e2348a4c?rating=PG&size=50&default=https%3A%2F%2Fassets.plan.io%2Fimages%2Fdefault_avatar.png)
![Assignee: Michael Kay](https://www.gravatar.com/avatar/db6526d63053f09b62e52c2da8b2230a?rating=PG&size=22&default=https%3A%2F%2Fassets.plan.io%2Fimages%2Fdefault_avatar.png)
Saxon (HE; Java) trace missing xsl:choose children and xsl:sequence
100%
Description
Using the trace feature in Saxon-HE, I'm seeing cases where lines I expect to be hit are not showing that they were hit. The omissions create a problem for the Code Coverage reporting feature of XSpec, because users of that feature want a reliable report of which lines of XSLT code the tests reached.
Here is how to reproduce the situation outside of XSpec:
Sample XSLT¶
<?xml version="1.0" encoding="UTF-8"?>
<xsl:stylesheet xmlns:f="myfunctions" xmlns:xsl="http://www.w3.org/1999/XSL/Transform" version="3.0">
<xsl:template name="xsl:initial-template">
<xsl:variable name="child1" as="element(child1)"><child1/></xsl:variable>
<xsl:variable name="child2" as="element(child2)"><child2/></xsl:variable>
<xsl:variable name="other" as="element(other)"><other/></xsl:variable>
<xsl:sequence select="($child1, $child2, $other) ! f:fcn(.)" />
</xsl:template>
<xsl:function name="f:fcn">
<xsl:param name="node" as="element()"/>
<xsl:choose>
<xsl:when test="$node/self::child1">
<xsl:sequence select="'first'"/>
</xsl:when>
<xsl:when test="$node/self::child2">
<xsl:sequence select="'second'"/>
</xsl:when>
<xsl:otherwise>
<xsl:sequence select="'third'"/>
</xsl:otherwise>
</xsl:choose>
</xsl:function>
</xsl:stylesheet>
Saxon Command¶
java -cp "%SAXON_CP%" net.sf.saxon.Transform -opt:0 -T -Tlevel:high -it -xsl:choose-trace.xsl 2> trace-result.xml
Output from Saxon-HE 12.4¶
<trace saxon-version="12.4" xmlns:xsl="http://www.w3.org/1999/XSL/Transform">
<xsl:template name="xsl:initial-template" line="4" column="45" module="choose-trace.xsl">
<xsl:variable name="child1" line="5" column="54" module="choose-trace.xsl">
<trace name="child1" line="5" column="63" module="choose-trace.xsl">
</trace>
<xsl:variable name="child2" line="6" column="54" module="choose-trace.xsl">
<trace name="child2" line="6" column="63" module="choose-trace.xsl">
</trace>
<xsl:variable name="other" line="7" column="52" module="choose-trace.xsl">
<trace name="other" line="7" column="60" module="choose-trace.xsl">
</trace>
<xsl:function arity="1" name="f:fcn" line="11" column="30" module="choose-trace.xsl">
<choose line="13" column="17" module="choose-trace.xsl">
</choose>
</xsl:function>
<xsl:function arity="1" name="f:fcn" line="11" column="30" module="choose-trace.xsl">
<choose line="13" column="17" module="choose-trace.xsl">
</choose>
</xsl:function>
<xsl:function arity="1" name="f:fcn" line="11" column="30" module="choose-trace.xsl">
<choose line="13" column="17" module="choose-trace.xsl">
</choose>
</xsl:function>
</xsl:variable>
</xsl:variable>
</xsl:variable>
</xsl:template>
</trace>
Missing Lines¶
- The line with xsl:choose is included, but all its children are missing from the trace.
- The first line with xsl:sequence is missing from the trace.
It seems pretty clear that Saxon is reaching the missing lines. It's just not reporting them in the trace.
Item #1 seems to go way back, because I see it in Saxon-HE 9.9.1.8. Item #2 does not occur in Saxon-HE 9.9.1.8, but it does occur in Saxon-HE 10.9.
Updated by Michael Kay 9 months ago
At one time trace code was added while instructions and expressions were being parsed, these days it's done as a post-processing step on the compiled expression tree. One disadvantage of this is that we lose distinctions that are available in the source code, for example the difference between xsl:choose
, xsl:if
, and an XPath if/then/else expression. This is why the "!" operator is traced as "forEach" - it compiles to exactly the same code as an xsl:for-each instruction.
The -T option instantiates an XSLTTraceCodeInjector, and this attempts to wrap a trace() call around every "instruction". The source instruction <xsl:sequence select="'first'"/>
compiles down to the StringLiteral "first"
which isn't classified as an instruction, so it doesn't get traced. We should probably make the criteria a bit more flexible, e.g. tracing it if the line or column number is different from that of the parent instruction.
It is possible in principle to use your own TraceCodeInjector that applies different criteria - but we don't make it at all easy.
The compile-time TraceCodeInjector
that injects trace()
calls, and the run-time TraceCodeListener
that outputs trace information are pretty much orthogonal to each other, but of course the run-time TraceCodeListener
can only output anything if a trace()
instruction was injected into the expression tree in the first place. The -Tlevel
option (perhaps unhelpfully) only affects what the TraceCodeListener
does, it doesn't (apparently) affect the TraceCodeInjector
at all.
Updated by Michael Kay 9 months ago
I think the primary problem here is that the elaboration code for a TraceExpression
is notifying the TraceExpression
itself to the TraceListener
, not the instruction/expression that it wraps. That is easily fixed. But there are other issues too; generally it seems the quality of the trace output has been allowed to decline a little (there are a lot of very pragmatic decisions being made based on conditions that can easily change from one release to another). To be honest, the whole thing needs a bit of a revamp.
Updated by Michael Kay 9 months ago
I'm inclined to think that the best way of deciding whether an expression is an "instruction" for the purpose of XSLT tracing is that its location is something other than an AttributeLocation
. I'll experiment with that.
Updated by Michael Kay 9 months ago
This doesn't quite work out. For example, a sequence constructor (including an empty sequence constructor as in <child1/>
) compiles to an expression whose location is that of the parent element, so it ends up being traced. I can change the location to Loc.NONE
which probably has no adverse side-effects.
The other problem is that <xsl:sequence select="EXPR"/>
compiles to EXPR
and the location of EXPR
is an AttributeLocation
. However, an AttributeLocation
holds the name of the containing element, so we can treat xsl:sequence
specially...
With these tweaks I'm now getting decent trace output for this example:
<trace saxon-version="12.4.1" xmlns:xsl="http://www.w3.org/1999/XSL/Transform">
<xsl:template name="xsl:initial-template" line="4" column="46" module="test.xsl">
<xsl:variable name="child1" line="5" column="56" module="test.xsl">
<xsl:variable name="child2" line="6" column="56" module="test.xsl">
<LRE name="child2" line="6" column="65" module="test.xsl">
</LRE>
<xsl:variable name="other" line="7" column="54" module="test.xsl">
<LRE name="other" line="7" column="62" module="test.xsl">
</LRE>
<LRE name="child1" line="5" column="65" module="test.xsl">
</LRE>
<xsl:function arity="1" name="f:fcn" line="11" column="31" module="test.xsl">
<choose line="13" column="19" module="test.xsl">
<literal line="15" column="45" module="test.xsl">
</literal>
</choose>
</xsl:function>
<xsl:function arity="1" name="f:fcn" line="11" column="31" module="test.xsl">
<choose line="13" column="19" module="test.xsl">
<literal line="18" column="46" module="test.xsl">
</literal>
<LRE name="br" line="19" column="18" module="test.xsl">
</LRE>
</choose>
</xsl:function>
<xsl:function arity="1" name="f:fcn" line="11" column="31" module="test.xsl">
<choose line="13" column="19" module="test.xsl">
<literal line="22" column="45" module="test.xsl">
</literal>
</choose>
</xsl:function>
</xsl:variable>
</xsl:variable>
</xsl:variable>
</xsl:template>
</trace>
But I need to try it on some other examples, and perhaps to create some regression tests. At the moment I think we have tests that show trace output is produced, but don't look in detail at the actual content.
There's also room for improvement in the detail that's given.
Updated by Michael Kay 9 months ago
The thing I haven't achieved yet is to get a trace for the first xsl:sequence
instruction. That's because it's compiled into a Block
expression which looks pretty much exactly like a sequence constructor, and we don't want to trace a sequence constructor separately from the instructions it contains. Again, it might be possible to detect the difference based on the way the location is represented.
Updated by Michael Kay 9 months ago
Now working reasonably with the default -Tlevel:normal
and -Tlevel:low
. I'm not getting more detail with -Tlevel:high
because that option is only used at run time, not at compile time when trace code is injected . I'm reluctant to inject fine-grained trace code unconditionally when it will hardly ever be needed, but the API in XsltCompiler doesn't allow a trace level to be specified.
I don't particularly want to change the s9api API at this point; I think I'll introduce the ability to set the trace level at the lower-level CompilerInfo
level, which people can dive into if they need to.
After a bit more fine-tuning I'm now getting reasonable results for XSLT at all four trace levels. Now need to check XQuery.
Updated by Michael Kay 9 months ago
Now running some JUnit tests controlling tracing from the API level. New JUnit test set s9apitest/TestXsltTracing. Getting less output than expected...
Updated by Michael Kay 9 months ago
- Category set to Diagnostics
- Status changed from New to Resolved
- Assignee set to Michael Kay
- Priority changed from Low to Normal
- Applies to branch 12, trunk added
- Fix Committed on Branch 12, trunk added
- Platforms .NET, Java added
Now getting reasonable output both from the command line (Transform and Query) and in XSLT JUnit tests.
Updated by A Galtman 8 months ago
Thank you very much!
I'm looking at some other XSpec coverage reports today and seeing some results that could indicate more issues in the Saxon traces. I don't know whether they're duplicates of the issue you just fixed. Any chance I can get a .jar file with your fix so that I can check? It would save me the time of creating small, self-contained files to reproduce issues outside of XSpec. (Or maybe I shouldn't bother to make the reproduction stylesheets small.)
Some of the omissions I'm looking at now involve instructions not mentioned in this issue, such as (a) xsl:matching-substring not in a trace, while the parent xsl:analyze-string is in the trace; and (b) xsl:accumulator-rule/xsl:map/xsl:map-entry tree not in a trace in Saxon-HE 12.4, while Saxon-HE 9.9.1.8 includes the xsl:map/xsl:map-entry subtree in the trace but xsl:accumulator-rule not in the trace. There is also one case where the XML trace output is not well-formed.
Updated by A Galtman 5 months ago
For the new information, are you getting accurate column numbers in the trace? In the block right below "decent trace output" is a line that says
<literal line="15" column="45" module="test.xsl">
but the sample XSLT has only 40 characters on line 15.
Maybe your local copy of the XSLT merely uses different indentation and column 45 is the end of line 15. That would be OK. But when I try the reproduction steps using a test ("beta") jar file that has the fix, I actually get column="0", like this:
<literal expr='"first"' line="15" column="0" module="choose-trace.xsl">
The column="0" information doesn't enable the code coverage feature to recognize the xsl:sequence instruction as being hit.
By trying some experiments like changing the XSLT to say
<xsl:sequence select="(: ABC :) 'secon' || 'd'"/>
instead of
<xsl:sequence select="'second'"/>
I am wondering whether the column number being reported is offset from the select attribute of xsl:sequence, not from the beginning of the line in the file. That's different from how the column numbers seem to be reported in other parts of the trace.
Updated by O'Neil Delpratt 2 months ago
- Status changed from Resolved to Closed
- % Done changed from 0 to 100
- Fixed in Maintenance Release 12.5 added
Bug fix applied in the Saxon 12.5 Maintenance release.
Please register to edit this issue