Recipe15.2.Tracing the Flow of Your Stylesheet Through Its Input Document

Recipe 15.2. Tracing the Flow of Your Stylesheet Through Its Input Document

Problem

You want to trace your stylesheet's navigation through the XML document.

Solution

XSLT 1.0

You should first consider the trace options available in your XSLT processor. Saxon has a -t option that displays timing information about various processing stages and a -T option that causes the output of trace information. Xalan has -TT, which traces the templates as they are called; -TG, which traces each generation event; -TS, which traces each selection event; and -TTC, which traces template children as they are called.

If your processor does not support trace output or you need higher degrees of control over the output, you can consider a solution based on xsl:message. With xsl:message, it is easy to generate debug output that lets you trace the flow of control through the stylesheet. It is also useful to trace the flow of the stylesheet through the document. Here is a utility you can import into any stylesheet for this purpose:

<!-- xtrace.xslt -->     <xsl:stylesheet version="1.0" xmlns:xsl="http://www.w3.org/1999/XSL/Transform"                                xmlns:dbg="http://www.ora.com/XSLTCookbook/ns/debug">     <xsl:param name="debugOn" select="false( )"/>     <xsl:template match="node( )" mode="dbg:trace" name="dbg:xtrace"> <xsl:param name="tag" select=" 'xtrace' "/> <xsl:if test="$debugOn">   <xsl:message>        <xsl:value-of select="$tag"/>: <xsl:call-template name="dbg:expand-path"/>    </xsl:message> </xsl:if> </xsl:template>      <!--Expand the xpath to the current node --> <xsl:template name="dbg:expand-path">   <xsl:apply-templates select="." mode="dbg:expand-path"/> </xsl:template>     <!-- Root --> <xsl:template match="/" mode="dbg:expand-path">   <xsl:text>/</xsl:text> </xsl:template>      <!--Top-level node --> <xsl:template match="/*" mode="dbg:expand-path">   <xsl:text>/</xsl:text><xsl:value-of select="name( )"/> </xsl:template>      <!--Nodes with node parents --> <xsl:template match="*/*" mode="dbg:expand-path">   <xsl:apply-templates select=".." mode="dbg:expand-path"/>/<xsl:value-of  select="name( )"/>[<xsl:number/>]<xsl:text/> </xsl:template>      <!--Attribute nodes --> <xsl:template match="@*" mode="dbg:expand-path">   <xsl:apply-templates select=".." mode="dbg:expand-path"/>/@<xsl:value-of  select="name( )"/> </xsl:template>      <!-- Text nodes (normalized for clarity) --> <xsl:template match="text( )" mode="dbg:expand-path">normalized-text(<xsl:value-of  select="normalize-space(.)"/>)</xsl:template>      </xsl:stylesheet>

When you place calls to dbg:xtrace in your stylesheet, you will generate a message containing the path to the current node. For example, this code instruments an identity stylesheet with xTRace:

<xsl:stylesheet version="1.0" xmlns:xsl="http://www.w3.org/1999/XSL/Transform"                                               xmlns:dbg="http://www.ora.com/ XSLTCookbook/ns/debug">     <xsl:include href="xtrace.xslt"/>     <xsl:template match="/ | node( ) | @* | comment( ) | processing-instruction( )">   <xsl:call-template name="dbg:trace"/>   <xsl:copy>     <xsl:apply-templates select="@* | node( )"/>   </xsl:copy> </xsl:template>     </xsl:stylesheet>

Using this test input:

<test foo="1">   <someElement n="1"/>   <someElement n="2">     <someChild>someValue</someChild>   </someElement>   <someElement n="3">     <someChild>someOtherValue</someChild>   </someElement>   <someElement n="4">     <someChild>someValue</someChild>   </someElement> </test>

you produce the following debug output:

xtrace: / xtrace: /test xtrace: /test/@foo xtrace: normalized-text( ) xtrace: /test/someElement[1] xtrace: /test/someElement[1]/@n xtrace: normalized-text( ) xtrace: /test/someElement[2] xtrace: /test/someElement[2]/@n xtrace: normalized-text( ) xtrace: /test/someElement[2]/someChild[1] xtrace: normalized-text(someValue) xtrace: normalized-text( ) xtrace: normalized-text( ) xtrace: /test/someElement[3] xtrace: /test/someElement[3]/@n xtrace: normalized-text( ) xtrace: /test/someElement[3]/someChild[1] xtrace: normalized-text(someOtherValue) xtrace: normalized-text( ) xtrace: normalized-text( ) xtrace: /test/someElement[4] xtrace: /test/someElement[4]/@n xtrace: normalized-text( ) xtrace: /test/someElement[4]/someChild[1] xtrace: normalized-text(someValue) xtrace: normalized-text( ) xtrace: normalized-text( )

XSLT 2.0

You can turn the calls to dbg:trace off and on using the use-when attribute in the same manner as we did with xsl:message in Recipe 15.1, provided that your processor supports testing system properties.

Saxon version 8.4 supports additional tracing options:

-TJ: Switches on tracing of the binding of calls to external Java methods. This is useful when analyzing why Saxon fails to find a Java method to match an extension function call in the stylesheet, or why it chooses one method over another when several are available.
-TL classname: Run the stylesheet using the specified traceListener. The classname names a user-defined class, which must implement net.sf.saxon.trace.TraceListener
-TP: Run the stylesheet using the traceListener TimedTraceListener. This creates an output file giving timings for each instruction executed. This output file can subsequently be analyzed to give an execution time profile for the stylesheet.

See the Saxon documentation for more details.

Discussion

To get the biggest bang for your buck, combine this tracing technique with debugging output that indicates where you are in the stylesheet. You can do that with a separate message, but xtrace has a parameter named tag, which, if set, will be output instead of the default tag.

This example outputs text nodes as normalized so the trace output does not span multiple lines. You can easily remove this filtering if you prefer to see the actual text.

When you use document tracing, think carefully about where to place the calls to trace. The most useful place is at the point or points where the processing of the current node effectively takes place. Consider the following postorder traversal stylesheet borrowed from Recipe 5.5 and instrumented with trace:

<xsl:stylesheet version="1.0" xmlns:xsl="http://www.w3.org/1999/XSL/Transform"      xmlns:dbg="http://www.ora.com/XSLTCookbook/ns/debug">       <xsl:include href="xtrace.xslt"/>       <xsl:output method="text"/>       <xsl:strip-space elements="*"/>       <xsl:template match="/employee" priority="10">     <xsl:apply-templates/>     <xsl:call-template name="dbg:trace"/>     <xsl:value-of select="@name"/>     <xsl:text> is the head of the company. </xsl:text>     <xsl:call-template name="reportsTo"/>     <xsl:call-template name="HimHer"/>     <xsl:text>. </xsl:text>     <xsl:text>&#xa;&#xa;</xsl:text>   </xsl:template>       <xsl:template match="employee[employee]">     <xsl:apply-templates/>     <xsl:call-template name="dbg:trace"/>     <xsl:value-of select="@name"/>     <xsl:text> is a manager. </xsl:text>     <xsl:call-template name="reportsTo"/>     <xsl:call-template name="HimHer"/>     <xsl:text>. </xsl:text>     <xsl:text>&#xa;&#xa;</xsl:text>   </xsl:template>       <xsl:template match="employee">     <xsl:call-template name="dbg:trace"/>     <xsl:text>Nobody reports to </xsl:text>     <xsl:value-of select="@name"/>     <xsl:text>. &#xa;</xsl:text>   </xsl:template>     <!-- Remainder elided ... -->     </xsl:stylesheet>

Notice how you call trace when you act on the current node, not as the first statement of each template. This placement results in the following trace, which accurately reflects the postorder traversal:

xtrace: /employee/employee[1]/employee[1] xtrace: /employee/employee[1]/employee[2]/employee[1] xtrace: /employee/employee[1]/employee[2] xtrace: /employee/employee[1] xtrace: /employee/employee[2]/employee[1] xtrace: /employee/employee[2]/employee[2]/employee[1] xtrace: /employee/employee[2]/employee[2]/employee[2] xtrace: /employee/employee[2]/employee[2]/employee[3] xtrace: /employee/employee[2]/employee[2] xtrace: /employee/employee[2] xtrace: /employee/employee[3]/employee[1]/employee[1] xtrace: /employee/employee[3]/employee[1]/employee[2] xtrace: /employee/employee[3]/employee[1]/employee[3] xtrace: /employee/employee[3]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[1]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[2]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[2]/employee[2] xtrace: /employee/employee[3]/employee[2]/employee[2] xtrace: /employee/employee[3]/employee[2]/employee[3]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[3] xtrace: /employee/employee[3]/employee[2] xtrace: /employee/employee[3] xtrace: /employee

Had you simply placed the trace at the first line, you would have output the following misleading trace that reflects a preorder traversal:

xtrace: /employee xtrace: /employee/employee[1] xtrace: /employee/employee[1]/employee[1] xtrace: /employee/employee[1]/employee[2] xtrace: /employee/employee[1]/employee[2]/employee[1] xtrace: /employee/employee[1]/employee[2] xtrace: /employee/employee[1] xtrace: /employee/employee[2] xtrace: /employee/employee[2]/employee[1] xtrace: /employee/employee[2]/employee[2] xtrace: /employee/employee[2]/employee[2]/employee[1] xtrace: /employee/employee[2]/employee[2]/employee[2] xtrace: /employee/employee[2]/employee[2]/employee[3] xtrace: /employee/employee[2]/employee[2] xtrace: /employee/employee[2] xtrace: /employee/employee[3] xtrace: /employee/employee[3]/employee[1] xtrace: /employee/employee[3]/employee[1]/employee[1] xtrace: /employee/employee[3]/employee[1]/employee[2] xtrace: /employee/employee[3]/employee[1]/employee[3] xtrace: /employee/employee[3]/employee[1] xtrace: /employee/employee[3]/employee[2] xtrace: /employee/employee[3]/employee[2]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[1]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[2] xtrace: /employee/employee[3]/employee[2]/employee[2]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[2]/employee[2] xtrace: /employee/employee[3]/employee[2]/employee[2] xtrace: /employee/employee[3]/employee[2]/employee[3] xtrace: /employee/employee[3]/employee[2]/employee[3]/employee[1] xtrace: /employee/employee[3]/employee[2]/employee[3] xtrace: /employee/employee[3]/employee[2] xtrace: /employee/employee[3]