Saxon

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.

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.

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.

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.

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.

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.

Now running some JUnit tests controlling tracing from the API level. New JUnit test set s9apitest/TestXsltTracing. Getting less output than expected...

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.

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.