2.7 Debug and Profile Facilities

Sedna provides several tracing, debug and perfomance profiling tools that can help to monitor and analyze queries and update statements:

• Trace – provides a query execution trace intended to be used in debugging queries (section 2.7.1);
• Debug Mode – provides stack of physical operations when error is raised (section 2.7.2);
• Explain Query – shows complete physical execution plan of the query or update statement (section 2.7.3);
• Profile Query – creates complete physical execution plan of the query or update statement with profile information (execution time, number of calls, etc) for each physical operation (section 2.7.4).

2.7.1 Trace

Sedna 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:

Output:

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 Mode

In 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:

• localize error in the query’s source code;
• obtain information of the query execution process.

Let us consider the following query to illustrate execution in the debug mode:

Query:

Output:

As you can see in the output above each item of the operations stack list consists of the following parts:

• operation name (PPCast and PPFunCall in the example);
• calls counter - number of calls of the operation;
• corresponding query and column numbers;
• optional additional information (qualified name of the function in the example).

2.7.3 Explain Query

The explain statement has the following syntax:

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:

Output:

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 Query

The profile statement has the following syntax:

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:

Output:

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:

Output: