Home | Getting Started | Documentation | Demo | Download | Support |
2.7 Debug and Profile FacilitiesSedna provides several tracing, debug and perfomance profiling tools that can help to monitor and analyze queries and update statements:
2.7.1 TraceSedna supports standard XQuery function fn:trace [4] providing user helper facility to trace queries. While executing XQuery query using fn:trace function intermediate results are shown to the user. For example in Sedna Terminal the query with fn:trace function will provide the following output. Trace information is marked with ## string: Query:
let $r:= trace(doc("region")/regions/*, "## ")
return $r[id_region="afr"]
Output:
## <africa><id_region>afr</id_region></africa>
<africa> <id_region>afr</id_region> </africa> ## <asia><id_region>asi</id_region></asia> ## <australia><id_region>aus</id_region></australia> ## <europe><id_region>eur</id_region></europe> ## <namerica><id_region>nam</id_region></namerica> ## <samerica><id_region>sam</id_region></samerica>
If you want to use trace facility in your application working through Sedna API you should set your own debug handler as it is shown in 1.2.6 section.
2.7.2 Debug ModeIn addition to trace facility provided by standard XQuery fn:trace function (see previous section, 2.7.1 ) debug mode can be turned on in Sedna Terminal (for details see ”Sedna Terminal” section of the Sedna’s Administration Guide) or in your application using corresponding Sedna API functions (see 1.2.3 section). Each query in Sedna is represented and executed internally as a tree of the physical operations. Debug mode is mechanism that allows to get stack of the physical operations after dynamic error was raised. It serves two goals:
Let us consider the following query to illustrate execution in the debug mode: Query:
(: In this query dynamic error will be raised :)
(: due to "aaaa" is not castable to xs:integer. :) declare function local:f($i as item()) as xs:integer { $i cast as xs:integer }; for $i in (1,2,3,"aaaa") return local:f($i)
Output:
1
2 3 <stack xmlns=’http://www.modis.ispras.ru/sedna’> <operation name=’PPCast’ line=’3’ column=’4’ calls=’7’/> <operation name=’PPFunCall’ line=’7’ column=’8’ calls=’7’/> <operation name=’PPReturn’ line=’6’ column=’5’ calls=’4’/> <operation name=’PPQueryRoot’ calls=’4’/> </stack> SEDNA Message: ERROR FORG0001 Invalid value for cast/constructor. Details: Cannot convert to xs:integer type Query line: 3, column:4
As you can see in the output above each item of the operations stack list consists of the following parts:
2.7.3 Explain QueryThe explain statement has the following syntax:
EXPLAIN
{XQuery or Update statement to explain} Each query in Sedna is represented and executed internally as a tree of the physical operations. With the help of EXPLAIN statement you can obtain detailed query execution plan which shows how Sedna executes this query. The following query illustrates EXPLAIN statement execution: Query:
explain
declare function local:fact($i as xs:integer) as xs:integer { if ($i <= 1) then 1 else $i * local:fact($i - 1) }; local:fact(10)
Output:
<prolog xmlns="http://www.modis.ispras.ru/sedna">
<function id="0" function-name="local:fact" type="xs:integer"> <arguments> <argument descriptor="0" type="xs:integer"/> </arguments> <operation name="PPIf" position="2:5"> <operation name="PPLMGeneralComparison" comparison="le" position="2:12"> <operation name="PPVariable" descriptor="0" variable-name="i" position="2:9"/> <operation name="PPConst" type="xs:integer" value="1" position="2:15"/> </operation> <operation name="PPConst" type="xs:integer" value="1" position="3:10"/> <operation name="PPCalculate" position="4:10"> <operation name="BinaryOp" operation="*"> <operation name="LeafAtomOp"> <operation name="PPVariable" descriptor="0" variable-name="i" position="4:10"/> </operation> <operation name="LeafAtomOp"> <operation name="PPFunCall" id="0" function-name="local:fact" position="4:15"> <operation name="PPCalculate" position="4:26"> <operation name="BinaryOp" operation="-"> <operation name="LeafAtomOp"> <operation name="PPVariable" descriptor="0" variable-name="i" position="4:26"/> </operation> <operation name="LeafAtomOp"> <operation name="PPConst" type="xs:integer" value="1" position="4:31"/> </operation> </operation> </operation> </operation> </operation> </operation> </operation> </operation> </function> </prolog> <query xmlns="http://www.modis.ispras.ru/sedna"> <operation name="PPQueryRoot"> <operation name="PPFunCall" id="0" function-name="local:fact" position="7:1"> <operation name="PPConst" type="xs:integer" value="10" position="7:12"/> </operation> </operation> </query>
Explain output consists of two parts (just like any XQuery query): prolog and query body explanations. Prolog part includes complete information about all declarations: namespaces, functions, global variables with complete physical plan for each user defined function and global variable. Query body explanation part describes physical tree of the query. For each physical operation EXPLAIN returns: name of the operation (PPConst, PPFunCall, etc), corresponding position in the source query (e.g. 4:31 means that operation PPConst corresponds to the ’1’ atomic at the line 4, column 26). Output may also contain additional information depending on the operation type (for example, variable name for some PPVariable operations).
2.7.4 Profile QueryThe profile statement has the following syntax:
PROFILE
{XQuery or Update statement to profile} Each query in Sedna is represented and executed internally as a tree of the physical operations. With the help of PROFILE statement you can obtain detailed tree of physical operation and execution time for each of them. The following query illustrates PROFILE statement execution: Query:
profile fn:doc(’TestSources/XMarkAuction.xml’)//
person[@id = "person0"]/name
Output:
<operation name="PPQueryRoot" time="13.426" calls="1">
<operation name="PPAxisChild" step="child::element(name)" time="13.426" calls="2"> <operation name="PPReturn" time="13.426" calls="2"> <operation name="PPAbsPath" root="document(auction)" path="descendant-or-self::node()" time="12.772" calls="85405"/> <operation name="PPPred1" time="0.530" calls="85405"> <operation name="PPAxisChild" step="child::element(person)" time="0.461" calls="86168"> <operation name="PPVariable" descr="0" time="0.380" calls="170808"/> </operation> <operation name="PPEQLGeneralComparison" comparison="eq" time="0.013" calls="1528"> <operation name="PPAxisAttribute" step="attribute::attribute(id)" time="0.001" calls="1527"> <operation name="PPVariable" descr="1" time="0.001" calls="1527"/> </operation> <operation name="PPConst" type="xs:string" value="person0" time="0.001" calls="1527"/> </operation> </operation> </operation> </operation> </operation> Profiling output consists of two parts (just like any XQuery query): prolog and query body explanations. Prolog part includes complete profile information for global variables and user defined functions. Query body profile part describes physical tree of the query and provides execution time and number of calls for each physical operation. For each physical operation PROFILE returns: name of the operation (PPConst, PPFunCall, etc), corresponding position in the source query (e.g. 4:31 means that operation PPConst corresponds to the ’1’ atomic at the line 4, column 26), execution time of this operation and number of calls. Output may also contain additional information depending on the operation type (for example, variable name for some PPVariable operations). In above example you can see that PPAbsPath operation takes almost all time (12.772 seconds of 13.426 total) and was called 12772 times. Profiling in this case shows that // may be very hard to execute and it is much better to use ”single” XPath steps everywhere it is possible: Query:
profile fn:doc(’TestSources/XMarkAuction.xml’)/
site/people/person[@id = "person0"]/name
Output:
<operation name="PPQueryRoot" time="0.018" calls="1">
<operation name="PPAxisChild" step="child::element(name)" time="0.018" calls="2"> <operation name="PPReturn" time="0.018" calls="2"> <produces> <variable descriptor="0"/> </produces> <operation name="PPAbsPath" root="document(auction)" path="child::element(site)/child::element(people)" time="0.001" calls="2"/> <operation name="PPPred1" time="0.017" calls="2"> <produces> <variable descriptor="1"/> </produces> <operation name="PPAxisChild" step="child::element(person)" time="0.001" calls="765"> <operation name="PPVariable" descr="0" time="0.000" calls="2"/> </operation> <operation name="PPEQLGeneralComparison" comparison="eq" time="0.013" calls="1528"> <operation name="PPAxisAttribute" step="attribute::attribute(id)" time="0.005" calls="1527"> <operation name="PPVariable" descr="1" time="0.003" calls="1527"/> </operation> <operation name="PPConst" type="xs:string" value="person0" time="0.000" calls="1527"/> </operation> </operation> </operation> </operation> </operation>
|