Firstly, if you are doing this kind of interleaving, make sure that both trace streams are sent to the same output destination. If one goes to System.out and the other to System.err, then the relative order of the messages will depend on operating system buffering of the output streams.
 
Secondly, yes, you are right: events are buffered in the output pipeline. Here you are using SAX output. SAX has a single event, startElement(), to represent an element and all its attributes. This event can't be emitted until it's known that there will be no more attributes, which means when the first child node or the end tag is output, whichever comes first. Mapping back from emitter events to the tracing of the instructions in the stylesheet is therefore quite difficult.
 
Michael Kay


From: saxon-help-admin@lists.sourceforge.net [mailto:saxon-help-admin@lists.sourceforge.net] On Behalf Of ROSSEL Olivier (CIMPA)
Sent: 14 April 2004 10:47
To: 'saxon-help@lists.sourceforge.net'
Subject: [saxon] Tracing a transformation

I added a SimpleTraceListener to the "exampleSAXResult" sample.
For a simple transformation:


==== XML document ====
<a value="valueA"><b>valueB=1</b><b>valueB=2</b></a>
==== end of XML document ====


==== XSL stylesheet ====
<xsl:stylesheet
  xmlns:xsl="http://www.w3.org/1999/XSL/Transform" version="1.0"
  xmlns="http://www.w3.org/TR/REC-html40">

 
<xsl:template match="/">
 <html>
  <xsl:apply-templates/>
 </html>
</xsl:template>

<xsl:template match="a">
 <p>
  <strong>
  <xsl:apply-templates>
   <xsl:with-param name="a.value"><xsl:value-of select="@value"/></xsl:with-param>
  </xsl:apply-templates>
   </strong>
 </p>
</xsl:template>

<xsl:template match="a/b">
 <xsl:param name="a.value"/>
 <xsl:value-of select="concat('Name: ',$a.value,'.',.)"/>
 <xsl:value-of select="concat('Name: ',$a.value,':',.)"/>
</xsl:template>

</xsl:stylesheet>
==== end of XSL stylesheet ====


Here is the log I get:
==== exampleSAXResult ====
<trace>
setDocumentLocator
startDocument
<Source node="/" line="0">
 <Instruction element="template" line="6" file="*ax/xsl/foo.xsl">
  <Instruction element="element" name="html" line="7" file="*ax/xsl/foo.xsl">
   <Instruction element="apply-templates" line="8" file="*ax/xsl/foo.xsl" mode="#default">
    <Source node="/a[1]" line="-1">
     <Instruction element="template" line="12" file="*ax/xsl/foo.xsl">
      <Instruction element="element" name="p" line="13" file="*ax/xsl/foo.xsl">
startPrefixMapping: , http://www.w3.org/TR/REC-html40
startElement: http://www.w3.org/TR/REC-html40, html, html
       <Instruction element="element" name="strong" line="14" file="*ax/xsl/foo.xsl">
startElement: http://www.w3.org/TR/REC-html40, p, p
        <Instruction element="apply-templates" line="15" file="*ax/xsl/foo.xsl" mode="#default">
         <Instruction element="value-of" line="16" file="*ax/xsl/foo.xsl">
         </Instruction> <!-- value-of -->
         <Source node="/a[1]/b[1]" line="-1">
          <Instruction element="template" line="22" file="*ax/xsl/foo.xsl">
           <Instruction element="param" name="a.value" line="23" file="*ax/xsl/foo.xsl">
           </Instruction> <!-- param -->
           <Instruction element="value-of" line="24" file="*ax/xsl/foo.xsl">
startElement: http://www.w3.org/TR/REC-html40, strong, strong
characters: "Name: valueA.valueB=1"
           </Instruction> <!-- value-of -->
           <Instruction element="value-of" line="25" file="*ax/xsl/foo.xsl">
characters: "Name: valueA:valueB=1"
           </Instruction> <!-- value-of -->
          </Instruction> <!-- template -->
         </Source><!-- /a[1]/b[1] -->
         <Source node="/a[1]/b[2]" line="-1">
          <Instruction element="template" line="22" file="*ax/xsl/foo.xsl">
           <Instruction element="param" name="a.value" line="23" file="*ax/xsl/foo.xsl">
           </Instruction> <!-- param -->
           <Instruction element="value-of" line="24" file="*ax/xsl/foo.xsl">
characters: "Name: valueA.valueB=2"
           </Instruction> <!-- value-of -->
           <Instruction element="value-of" line="25" file="*ax/xsl/foo.xsl">
characters: "Name: valueA:valueB=2"
           </Instruction> <!-- value-of -->
          </Instruction> <!-- template -->
         </Source><!-- /a[1]/b[2] -->
        </Instruction> <!-- apply-templates -->
endElement: http://www.w3.org/TR/REC-html40, strong, strong
       </Instruction> <!-- element -->
endElement: http://www.w3.org/TR/REC-html40, p, p
      </Instruction> <!-- element -->
     </Instruction> <!-- template -->
    </Source><!-- /a[1] -->
   </Instruction> <!-- apply-templates -->
endElement: http://www.w3.org/TR/REC-html40, html, html
  </Instruction> <!-- element -->
 </Instruction> <!-- template -->
</Source><!-- / -->
</trace>
endDocument

==== done! ====



The intersting part is the beginning of the trace:
...
 <Instruction element="template" line="6" file="*ax/xsl/foo.xsl">
  <Instruction element="element" name="html" line="7" file="*ax/xsl/foo.xsl">
   <Instruction element="apply-templates" line="8" file="*ax/xsl/foo.xsl" mode="#default">
    <Source node="/a[1]" line="-1">
     <Instruction element="template" line="12" file="*ax/xsl/foo.xsl">
      <Instruction element="element" name="p" line="13" file="*ax/xsl/foo.xsl">
startPrefixMapping: , http://www.w3.org/TR/REC-html40
startElement: http://www.w3.org/TR/REC-html40, html, html
...

As you may see, the <html> startelement is sent much *after* the <html> tag in the XSL
has been encontered.
During that time, the <apply-templates> after the <html> tag in the XSL, has been half-managed.

Why is there such a delay?
Is it impossible to deduce, from the Saxon trace, which template was responsible
for a given startelement ?