Bug #5186
closed
Events received in XQuery Trace listener with Saxon 10
100%
Description
I'm working to make the Oxygen XML Debugger work with Saxon 10 exactly or close to how it worked with with Saxon 9. So there is an XML and an XQuery, I'm attaching them. The XQuery looks like this:
<BigBoss_subordinates>
{
for $person in doc("personal.xml")/personnel/person
let $link := $person/link
where (exists($link/@manager) and (compare($link/@manager, "Big.Boss") eq 0))
return
<person id="{$person/@id}">
<name>{$person/name/given/text(), " ", $person/name/family/text()}</name>
</person>
}
</BigBoss_subordinates>
We add a net.sf.saxon.lib.TraceListener, with Saxon 10 by default I get on the "net.sf.saxon.lib.TraceListener.enter(Traceable, Map<String, Object>, XPathContext)" callbacks these three initial events:
ENTER class net.sf.saxon.query.XQueryExpression ENTER class net.sf.saxon.expr.flwor.ClauseInfo ENTER class net.sf.saxon.expr.flwor.ClauseInfo
which correspond to the "QUERY" body and to the "FOR" loop inside it, then to the "LET" clause.
With Saxon 9, the same callbacks were with TraceExpression objects, there were more callbacks and one of them was for the "BigBoss_subordinates" element for which with Saxon 10 I receive no callback.
So I started to try and receive more events on the trace listener. I went to patch the method "net.sf.saxon.Configuration.setCompileWithTracing(boolean)" and by default for XQuery it uses a "net.sf.saxon.trace.TraceCodeInjector" which on the method "net.sf.saxon.trace.TraceCodeInjector.isApplicable(Expression)" returns false all the time. What I tried to do for XQuery debugging was to apply a trace code injector like this:
defaultStaticQueryContext.setCodeInjector(
new TraceCodeInjector() {
@Override
protected boolean isApplicable(Expression exp) {
boolean appl = exp.isInstruction() || exp instanceof LetExpression || exp instanceof FixedAttribute
|| exp instanceof FixedElement || exp instanceof FunctionCall;
return appl;
}
});
After this I get more callbacks on the trace listener, I am called for the element "BigBoss_subordinates", I am called for the doc() function call but I no longer receive callbacks for the "FOR", "LET" expressions for which I received callbacks when I did not set the custom trace code injector.
So somehow I do not know why this happens and how to proceed.
Files
Updated by Radu Coravu almost 3 years ago
Maybe it's more clear if I attach also a screenshot with the initial events we used to receive, "xquery-body", element bigboss_subbordinates, function call to doc(), "for" loop.
Updated by Radu Coravu almost 3 years ago
I have set the " tracecodeinjector.isApplicable" to return true for FixedElement. And inside that FixedElement there is a "for" expression which is not yet wrapped.
Looking more into this in the method "net.sf.saxon.expr.parser.ExpressionTool.injectCode(Expression, CodeInjector)"
the expression is a TraceExpression over a FixedElement, but the code:
else if (!(exp instanceof TraceExpression)){
for (Operand o : exp.operands()) {
o.setChildExpression(injectCode(o.getChildExpression(), injector));
}
goes deep only if the expression is not yet a trace expression, in my case there is already a trace expression over the FixedElement but I still want it to go deep, so I will probably patch it something like:
public static Expression injectCode(Expression exp, CodeInjector injector) {
if (exp instanceof FLWORExpression) {
((FLWORExpression)exp).injectCode(injector);
} else {
for (Operand o : exp.operands()) {
if (!(o.getChildExpression() instanceof TraceExpression)){
o.setChildExpression(injectCode(o.getChildExpression(), injector));
}
}
}
return injector.inject(exp);
}
Updated by Michael Kay almost 3 years ago
- Tracker changed from Support to Bug
- Category set to Diagnostics
- Assignee set to Michael Kay
- Priority changed from Low to Normal
- Applies to branch 10, 11, trunk added
Sorry for the delay in responding.
I've confirmed the problem and I'm working on it.
There seems to have been an attempt in 10.x to allow subclasses of TraceCodeInjector to determine where in the expression tree trace expressions would be inserted (whereas earlier, trace code was injected everywhere and the decision what to output was made at run-time). But this wasn't followed through by implementing a subclass of TraceCodeInjector specifically for XQuery -T tracing.
Updated by Michael Kay almost 3 years ago
There seem to be a number of separate but interacting problems here.
I think at some stage there was a change in strategy from injecting trace code at the time the expression tree is being built (i.e. during expression parsing), to injecting it during a recursive traversal of the tree after parsing is complete.
So Configuration.makeXQueryExpression() calls mainModule.getCodeInjector().process() which calls ExpressionTool.injectCode() which embarks on a recursive traversal; but the recursion stops if it hits an existing TraceExpression. This is going to happen, because the XPathParser and XQueryParser in many places call XPathParser.makeTracer which invokes the non-recursive TraceCodeInjector.inject().
ExpressionTool.injectCode() appears to be new in 10.x, and it looks as if it's primarily designed for XSLT, where it will successfully recurse down the XSLT-level instruction tree, until it hits an XPath expression, where it will find that the injection has already been done by the XPath parser. But in XQuery we don't get this two-language model, so it's less clear how this is intended to operate -- and it's clear that it hasn't been properly tested.
I think this is going to be a bit trickier to resolve than I first thought.
Updated by Radu Coravu almost 3 years ago
Right, I agree with everything, here are some things I did on my side to make this kind of work:
On the method "net.sf.saxon.Configuration.setCompileWithTracing(boolean)" I overwrote the injector for XQuery:
if (defaultStaticQueryContext != null) {
if (trace) {
defaultStaticQueryContext.setCodeInjector(new TraceCodeInjector() {
//////// OXYGEN PATCH START //////////////////
//EXM-49354 Create trace expressions over multiple XQuery constructs
@Override
protected boolean isApplicable(Expression exp) {
boolean appl = exp.isInstruction() || exp instanceof LetExpression || exp instanceof FixedAttribute
|| exp instanceof FixedElement || exp instanceof FunctionCall || exp instanceof Choose;
return appl;
}
/**
* @see net.sf.saxon.trace.TraceCodeInjector#process(net.sf.saxon.trace.TraceableComponent)
*/
@Override
public void process(TraceableComponent component) {
Expression newBody = ExpressionToolUtil.injectCodeXQuery(component.getBody(), this);
component.setBody(newBody);
ComponentTracer trace = new ComponentTracer(component);
component.setBody(trace);
}
//////// OXYGEN PATCH END //////////////////
});
I created a "ExpressionToolUtil.injectCodeXQuery" similar to "net.sf.saxon.expr.parser.ExpressionTool.injectCode" but which recurses all the way:
public static Expression injectCodeXQuery(Expression exp, CodeInjector injector) {
if (exp instanceof FLWORExpression) {
((FLWORExpression)exp).injectCode(injector);
} else {
if(exp instanceof TraceExpression) {
Expression child = ((TraceExpression) exp).getChild();
Iterable<Operand> childOps = child.operands();
for (Operand operand : childOps) {
operand.setChildExpression(injectCodeXQuery(operand.getChildExpression(), injector));
}
} else {
for (Operand o : exp.operands()) {
o.setChildExpression(injectCodeXQuery(o.getChildExpression(), injector));
}
}
}
return injector.inject(exp);
}
I called "net.sf.saxon.expr.parser.ExpressionToolUtil.injectCodeXQuery(Expression, CodeInjector)" also from the "net.sf.saxon.query.XQueryParser.parseFLWORExpression()" on the return expression because I would not get callbacks inside returns.
I still have problems, I do not get callbacks for the "return" token itself and looking at how the TraceExpression changed I will probably never will. The "XQueryParser.parseFLWORExpression()"" method used to wrap the return expression inside a "TraceExpression" with a specific RETURN type but now trace expressions can no longer with specific types.
I also do not get callbacks for "let" expressions inside function declarations but I will look more over this one today.
Updated by Radu Coravu almost 3 years ago
Oh and I also do not get cals for the "then" and "else" tokens, I get calls for what's inside them but not for the tokens themselves.
Updated by Radu Coravu almost 3 years ago
About let expressions inside function declarations not being wrapped in trace expressions, in the method "XQueryParser.parseFunctionDeclaration(AnnotationList)" after the body is parsed I call my "ExpressionToolUtil.injectCodeXQuery" method:
Expression body = parseExpression();
ExpressionTool.setDeepRetainedStaticContext(body, env.makeRetainedStaticContext());
//OXYGEN PATCH START FOR EXM-49354, inject trace information in body.
if(codeInjector != null) {
body = ExpressionToolUtil.injectCodeXQuery(body, codeInjector);
}
///OXYGEN PATCH END FOR EXM-49354
func.setBody(body);
Updated by Michael Kay almost 3 years ago
- Status changed from New to In Progress
I have obtained satisfactory results for the -T output for this query by making the following changes:
-
Add an XQueryTraceCodeInjector as a subclass of TraceCodeInjector and use this where appropriate
-
In Configuration.setCompileWithTracing(), force creation of the default static query context if it does not already exist
-
In Query (command-line) cut out the code that does compiler.setCompileWithTracing(true) -- it's redundant.
-
in flwor/Clause.java, add a method getTraceInfo() that decides what information to output in the trace. For FOR and LET clauses, it outputs the name of the variable; for WHERE clauses, it outputs the predicate.
-
in FLWORExpression.injectCode, if there is already a TraceClause in the list of clauses, exit without doing anything (to avoid duplication)
-
In FLWORExpression, when creating a WhereClause, ensure that its location information is set,
-
In the constructor for TraceClause, copy the location from the clause being traced
-
In ExpressionTool.injectCode(), ensure that the recursive processing of the tree continues past an existing TraceExpression
-
In TraceCodeInjector.inject(), handle a FLWORExpression
For the 11.x branch, I will consider eliminating the code injection that's done during parsing, and relying instead on doing it during the recursive processing of the expression tree in ExpressionTool.injectCode.
Updated by Michael Kay almost 3 years ago
Regarding "then" and "else", the tracing generally only traces the expressions that are executed, it doesn't attempt to identify their role within the parent expression. That's because we don't have this information readily available in a convenient place.
Updated by Michael Kay almost 3 years ago
With these changes, trace level "normal" is giving output:
<query line="-1" module="test.xq">
<element name="BigBoss_subordinates" line="1" column="1" module="test.xq">
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
</element>
</query>
</trace>
while trace level "high" gives:
<trace saxon-version="10.6" >
<query line="-1" module="test.xq">
<element name="BigBoss_subordinates" line="1" column="1" module="test.xq">
<FOR var="$person" line="3" column="8" module="test.xq">
<LET var="$link" line="4" column="8" module="test.xq">
</LET>
</FOR>
<FOR var="$person" line="3" column="8" module="test.xq">
<LET var="$link" line="4" column="8" module="test.xq">
<WHERE condition="fn:exists(...)" line="5" column="11" module="test.xq">
<WHERE condition="fn:compare(...) eq 0" line="5" column="11" module="test.xq">
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
</WHERE>
</WHERE>
</LET>
</FOR>
<FOR var="$person" line="3" column="8" module="test.xq">
<LET var="$link" line="4" column="8" module="test.xq">
<WHERE condition="fn:exists(...)" line="5" column="11" module="test.xq">
<WHERE condition="fn:compare(...) eq 0" line="5" column="11" module="test.xq">
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
</WHERE>
</WHERE>
</LET>
</FOR>
<FOR var="$person" line="3" column="8" module="test.xq">
<LET var="$link" line="4" column="8" module="test.xq">
<WHERE condition="fn:exists(...)" line="5" column="11" module="test.xq">
<WHERE condition="fn:compare(...) eq 0" line="5" column="11" module="test.xq">
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
</WHERE>
</WHERE>
</LET>
</FOR>
<FOR var="$person" line="3" column="8" module="test.xq">
<LET var="$link" line="4" column="8" module="test.xq">
<WHERE condition="fn:exists(...)" line="5" column="11" module="test.xq">
<WHERE condition="fn:compare(...) eq 0" line="5" column="11" module="test.xq">
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
</WHERE>
</WHERE>
</LET>
</FOR>
<FOR var="$person" line="3" column="8" module="test.xq">
<LET var="$link" line="4" column="8" module="test.xq">
<WHERE condition="fn:exists(...)" line="5" column="11" module="test.xq">
<WHERE condition="fn:compare(...) eq 0" line="5" column="11" module="test.xq">
<element name="person" line="7" column="11" module="test.xq">
<att name="id" line="7" column="11" module="test.xq">
</att>
<element name="name" line="9" column="14" module="test.xq">
</element>
</element>
</WHERE>
</WHERE>
</LET>
</FOR>
</element>
</query>
</trace>
Updated by Radu Coravu almost 3 years ago
- File functions.zip functions.zip added
Thanks for the investigation Michael. If I can get access to your changes on the Saxonica Git repo I will try after coming back from vacation in January to replace my small patches with your changes and run all our debugger tests. Maybe you can also try something with functions and LET expressions inside functions. For example with the initial code I did not get callbacks for the LET expression inside the function declaration. Attaching a small sample test case.
Updated by Michael Kay almost 3 years ago
These changes are now applied and committed on both the 10.x and 11.x branches.
Still to do: (a) on the 11.x branch, rationalise the way code injection is done, (b) add unit tests.
I've also looked at tracing within functions: to enable this, I've changed the code at XQueryFunction line 400 to read
if (staticContext.getUserQueryContext().isCompileWithTracing()) {
namespaceResolver = staticContext.getNamespaceResolver();
staticContext.getCodeInjector().process(compiledFunction);
body = compiledFunction.getBody();
}
Updated by Michael Kay almost 3 years ago
It turns out the unit tests for XQuery tracing in 10.x are reporting success for completely spurious reasons - the method containing the relevant assertions is never called. But it had been corrected for 11.x.
Updated by Michael Kay almost 3 years ago
- Status changed from In Progress to Resolved
- Fix Committed on Branch 10, trunk added
As proposed, on the 11.x branch trace expressions are no longer injected during parsing (method XPathParser.makeTracer), instead it's all now done using ExpressionTool.injectCode which is recursive and processes the whole tree.
Updated by O'Neil Delpratt almost 3 years ago
- % Done changed from 0 to 100
- Fixed in Maintenance Release 11.1 added
- Platforms .NET, Java added
Bug fix applied in the Saxon 11.1 release.
Updated by O'Neil Delpratt almost 3 years ago
Leaving bug as resolved until fix applied to the Saxon 10 maintenance release.
Updated by Debbie Lockett over 2 years ago
- Status changed from Resolved to Closed
- Fixed in Maintenance Release 10.7 added
- Fixed in Maintenance Release deleted (
11.1)
Bug fix applied in the Saxon 10.7 maintenance release.
Updated by Debbie Lockett over 2 years ago
- Fixed in Maintenance Release 11.1 added
Please register to edit this issue
.