Saxon

What's happening here is a little bit strange. Saxon injects the trace instructions into the tree, then does optimization. The optimization removes the unused local variable declarations, but it doesn't remove the trace instructions, which are now reporting the evaluation of a phantom variable that is no longer there. You can see the detail of what's happening if you run with -explain.

Why the mismatched line numbers? I need to look into this more carefully, but I suspect what is happening is that after the "let" expression (representing the local variable) is eliminated, we get two trace instructions next to each other, and these are elided into a single trace instruction and this is where the incorrect line numbers are picked up.

It's always been an open question whether tracing should suppress optimisation rewrites. On the one hand, tracing is there to help with debugging, and you want the output to be intelligible, which it isn't if there are a lot of radical rewrites. On the other hand, the reason you are debugging might be because of "bad" rewrites, for example loop-lifting calls to external functions with side-effects, and you don't wan't Heisenbugs where the code works when tracing and not otherwise. So on the whole, we don't suppress optimisations just because tracing is enabled. One major exception is global variables: IIRC correctly we evaluate globals eagerly if tracing is enabled. The other exception is that the presence of trace expressions in the tree may mean that the optimizer fails to detect opportunities for optimization that it would detect otherwise.

I think, though I would need to check my facts, that tracing also suppresses lazy evaluation (which is a run-time optimization rather than an expression tree rewrite). Lazy evaluation makes the order of evaluation of subexpressions very chaotic indeed.

I've been doing work on a fairly radical upheaval of line/column maintenance, and although much of this will probably only appear in the 13 branch, I'll report it here because some of if may find its way back into 12.x.

Firstly, if line numbering is requested and we're building from a SAX source, then I'm injecting a new filter into the document building pipeline that changes the location information from what SAX reports, which is the location of the end of the current event, to instead report the end of the previous event. That's working well except where the end of the previous event is in a different external entity. In that case SAX doesn't give us good enough information, so I'm having to approximate by saying that if the location for the current event has a different system ID from the location of the previous event, we use the current event in preference.

Next, I've added to the linked tree the ability to hold line/column information (in a compressed format) for text nodes. This is worth doing because the dominant usage of the linked tree is for stylesheets, and with the introduction of text value templates, text nodes are rather more "interesting" than they used to be for purposes such as tracing. Current progress is that the text node holds a correct line/column number, but this isn't finding its way into the instructions in the compiled stylesheet, so they aren't being traced properly.

Currently looking at how to record more precisely the location of an expression contained within curly braces within a text node within a stylesheet, now that we have a reliable datum for the location of the text node. We have some machinery for doing this kind of thing, but it doesn't quite handle this scenario.

After first injecting the trace instructions, the named template body looks like this:

<componentTracer>
 <traceExp name='var1' line='9' col='31'>
  <let baseUri='file:/Users/mike/bugs/2024/6415-Galtman/test.xslt' ns='xsl=~' line='9' var='Q{}var1' as='1ND' slot='-999'>
   <traceExp line='9' col='35'>
    <doc base='file:/Users/mike/bugs/2024/6415-Galtman/test.xslt' validation='preserve'>
     <elem name='a' nsuri='' flags='l'>
      <empty/>
     </elem>
    </doc>
   </traceExp>
   <traceExp name='var02' line='10' col='32'>
    <let line='10' var='Q{}var02' as='1ND' slot='-999'>
     <traceExp line='10' col='36'>
      <doc base='file:/Users/mike/bugs/2024/6415-Galtman/test.xslt' validation='preserve'>
       <elem name='b' nsuri='' flags='l'>
        <empty/>
       </elem>
      </doc>
     </traceExp>
     <traceExp name='var003' line='11' col='33'>
      <let line='11' var='Q{}var003' as='1ND' slot='-999'>
       <traceExp line='11' col='37'>
        <doc base='file:/Users/mike/bugs/2024/6415-Galtman/test.xslt' validation='preserve'>
         <elem name='c' nsuri='' flags='l'>
          <empty/>
         </elem>
        </doc>
       </traceExp>
       <traceExp name='root' line='12' col='12'>
        <elem line='12' name='root' nsuri=''>
         <empty/>
        </elem>
       </traceExp>
      </let>
     </traceExp>
    </let>
   </traceExp>
  </let>
 </traceExp>
</componentTracer>

After optimization, it looks like this:

<componentTracer>
 <traceExp name='var1' line='9' col='31'>
  <traceExp name='var02' line='10' col='32'>
   <traceExp name='var003' line='11' col='33'>
    <traceExp name='root' line='12' col='12'>
     <elem baseUri='file:/Users/mike/bugs/2024/6415-Galtman/test.xslt' ns='xsl=~' line='12' name='root' nsuri=''>
      <empty/>
     </elem>
    </traceExp>
   </traceExp>
  </traceExp>
 </traceExp>
</componentTracer>

So the line/column information on the trace instructions seems to be correct. But I think the trace listener, when a trace instruction is encountered, is being given position information for the instruction wrapped by that trace instruction, which in this case is another trace instruction.

Indeed, that's the explanation. The effect of the trace expression is to do

TraceListener.enter(body, properties, context)

where body is the child of the trace expression; and the trace listener takes the line/column information from the body expression.

I think that the answer to this is to suppress the relevant trace. Either during the optimization rewrite, we should eliminate a trace expression if its child is a trace expression; or at run-time, a trace expression should do nothing if its child is a trace expression.