Query Performance and Tuning Guide (PDF)

Query Performance and Tuning Guide — Chapter 5

« Previous chapter
Next chapter »

Profiling Requests to Evaluate Performance

This chapter describes how to use the Performance Profiler built-in functions to examine the evaluation characteristics of XQuery requests in MarkLogic Server, and includes the following sections:

Overview of MarkLogic Server Profiling

MarkLogic Server accepts XQuery requests on HTTP and XDBC servers, and those requests evaluate the XQuery program on the fly. To help understand the performance characteristics of these requests, MarkLogic Server includes an API to gather statistics about XQuery program evaluation. The statistics include time spent in various parts of the program and counts of how many times various expressions are called. The result of all of these statistics allow you to build a profile of the performance characteristics. This section provides an overview of the query profile capabilities in MarkLogic Server and includes the following subsections:

Definitions and Terminology

The following table lists some terms and their definitions used in describing the profile API.

Term Definition
XQuery Program The XQuery main module fully expanded with any XQuery library modules needed for its evaluation. An XQuery program is sometimes referred to as a query, a statement, or a request. For more details on this terminology, see Understanding Transactions in MarkLogic Server in the Application Developer's Guide.
profiler An application which measures the performance characteristics of a running program (in the case MarkLogic Server, of an XQuery program).
expression The basic parse element of an XQuery program. Expressions can represent literal values, arithmetic operations, functions, function calls, and so on. Expressions can contain other expressions.
shallow time The time spent evaluating a specific expression, not including time spent evaluating any expressions contained within the specific expression.
deep time The total time spent evaluating an expression, including time spent evaluating any expressions contained within the specific expression.
elapsed time Both shallow and deep time are expressed in elapsed wall clock time.
profile report An XML report containing statistics for all of the expressions evaluated while profiling was enabled. For a sample profile report, see Simple Enable and Disable Example.

MarkLogic Server Profiling Requirements Capabilities

The profile API in MarkLogic Server is not in itself a query profile application (a profiler), but you could use the profile API to build such a profiler application. Such an application would measure the performance characteristics of an XQuery program. You can also simply use the profile API to generate profile reports and then either manually analyze the reports or use XQuery to extract details and format the reports.

To use the profile API, you must first enable profiling on the App Server in which your XQuery program is serviced (or on the task server if you are profiling spawned queries). The profile allow option must be set to true.

Once profiling is enabled, you can use the prof:enable, prof:report, and other profile APIs to generate profiling statistics for the evaluation of individual XQuery programs.

Profiling helps you to see where a query is spending its processing time. The statistics are gathered for activity in the evaluation portion of the query, at the individual expression level. Time spent in the data node portion of the query (time spent gathering content from the forests) is included in the expression time for the expression that requested the content from the forest (for example, a cts:search). For each expression, the profile report shows the shallow time and the deep time (see Definitions and Terminology for these definitions).

All profiling information is gathered on a per-request basis; there is no notion of profiling a set of requests, although it is possible to write an application that performs that kind of aggregation.

Profile APIs

The following functions are included in the Performance Profiler APIs:

For details on the APIs and for their function signatures, see the MarkLogic XQuery and XSLT Function Reference. Note the following about the profile APIs.

  • If profiling is not enabled on the App Server and in the XQuery program (via prof:enable), then profile APIs do not do anything except return the empty sequence.
  • You can profile the currently running request (prof:enable(xdmp:request())), an evaluated request (prof:eval), or an invoked module (prof:invoke). To profile other requests, you need to debug the request; if you try to profile another request, MarkLogic Server throws the DBG-NOTSTOPPED exception.
  • Constants (for example, 47 or "hello") do not show up in the profile report.
  • Constructed elements do not show up in the profile report.
  • Profile time starts after the static analysis phase of query evaluation; it does not include the query parsing time.
  • All of the profile APIs are in the http://marklogic.com/xdmp/profile namespace. The prof prefix is bound to this namespace, and is pre-configured in MarkLogic Server (so there is no need to define this namespace in your XQuery prolog).
  • If you profile a request besides the currently running request, or if you start a new request for profiling using prof:eval or prof:invoke, you need one of the privileges http://marklogic.com/xdmp/privileges/profile-my-requests (to profile a request issued by the same user ID) or http://marklogic.com/xdmp/privileges/profile-any-requests (to profile a request issued by any user ID). If you are profiling the currently running request, no privileges are required.

Profiling Examples

The following are code examples showing some simple usage patterns for the profile API. For details on the APIs, see the MarkLogic XQuery and XSLT Function Reference. This section shows the following examples:

Simple Enable and Disable Example

The following examples show simple uses for the profile API.

let $req := xdmp:request()
let $dummy1 := prof:enable($req)
let $version := xdmp:version()
let $node := 
  <foo>
    <version>{$version}</version>
    <request>{$req}</request>
  </foo>
let $dummy2 := prof:disable($req)
let $dummy3 := fn:current-dateTime()
let $dummy4 := prof:enable($req)
let $dummy5 := 47
let $dummy6 := $node/foo/request
let $dummy6 := prof:disable($req)

return 
prof:report($req)

This query returns the following report:

<prof:report 
  xsi:schemaLocation="http://marklogic.com/xdmp/profile profile.xsd"
  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xmlns:prof="http://marklogic.com/xdmp/profile">
  <prof:metadata>
    <prof:overall-elapsed>PT0S</prof:overall-elapsed>
    <prof:created>2014-03-19T14:20:18.763-07:00</prof:created>
    <prof:server-version>7.0-4</prof:server-version>
  </prof:metadata>
  <prof:histogram>
    <prof:expression>
      <prof:expr-id>6467258264555963988</prof:expr-id>
      <prof:expr-source>xdmp:version()</prof:expr-source>
      <prof:uri/>
      <prof:line>3</prof:line>
      <prof:count>1</prof:count>
      <prof:shallow-time>PT0S</prof:shallow-time>
      <prof:deep-time>PT0S</prof:deep-time>
    </prof:expression>
    <prof:expression>
      <prof:expr-id>127913224145561857</prof:expr-id>
      <prof:expr-source>prof:disable($req)</prof:expr-source>
      <prof:uri/>
      <prof:line>9</prof:line>
      <prof:count>1</prof:count>
      <prof:shallow-time>PT0S</prof:shallow-time>
      <prof:deep-time>PT0S</prof:deep-time>
    </prof:expression>
    <prof:expression>
      <prof:expr-id>8377097069965042614</prof:expr-id>
      <prof:expr-source>prof:disable($req)</prof:expr-source>
      <prof:uri/>
      <prof:line>14</prof:line>
      <prof:count>1</prof:count>
      <prof:shallow-time>PT0S</prof:shallow-time>
      <prof:deep-time>PT0S</prof:deep-time>
    </prof:expression>
    <prof:expression>
      <prof:expr-id>10959125668150171452</prof:expr-id>
      <prof:expr-source>prof:enable($req)</prof:expr-source>
      <prof:uri/>
      <prof:line>2</prof:line>
      <prof:count>1</prof:count>
      <prof:shallow-time>PT0S</prof:shallow-time>
      <prof:deep-time>PT0S</prof:deep-time>
    </prof:expression>
    <prof:expression>
      <prof:expr-id>1823871875827665493</prof:expr-id>
      <prof:expr-source>$node/child::foo/child::request
        </prof:expr-source>
      <prof:uri/>
      <prof:line>14</prof:line>
      <prof:count>1</prof:count>
      <prof:shallow-time>PT0S</prof:shallow-time>
      <prof:deep-time>PT0S</prof:deep-time>
    </prof:expression>
    <prof:expression>
      <prof:expr-id>16669888445989754369</prof:expr-id>
      <prof:expr-source>prof:enable($req)</prof:expr-source>
      <prof:uri/>
      <prof:line>11</prof:line>
      <prof:count>1</prof:count>
      <prof:shallow-time>PT0S</prof:shallow-time>
      <prof:deep-time>PT0S</prof:deep-time>
    </prof:expression>
  </prof:histogram>
</prof:report>

You might note that the times are all zero. That is because this example does a trivial amount of work, and each expression took less than a millisecond to complete. But it does illustrate some things that are useful when looking at the report:

  • The fn:current-dateTime() function does not appear in the report, because profiling was disabled at this stage of the XQuery program.
  • The expressions are not necessarily in the order they are in the XQuery program. If you want them in order, you can take the prof:expression elements and order them by the prof:line element (or one of the time elements, or whatever makes sense for your reports).
  • While the expression 47 occurs while profiling is enabled, it does not show up in the output because it is just a constant, and constants do not appear in the profile report.

Returning a Part of the Profile Report

Because the profile report is XML, you can use XQuery to manipulate the report to suit your needs. The following example returns only a expression elements of the profile report, wraps it in an element, and orders it by the deep time element.

xquery version "1.0-ml";

let $req := xdmp:request()
let $dummy := prof:enable($req)
let $foo := for $i in fn:doc() return xdmp:node-uri($i)
let $dummy2 := prof:disable($req)
return <foo>{
   for $j in prof:report($req)//*:expression
     order by xs:dayTimeDuration($j/*:deep-time)
     return $j
}</foo>

To see the results, copy the code and run it against MarkLogic Server. You will need to enable profiling on the HTTP Server Configuration page, otherwise the report will be empty.

« Previous chapter
Next chapter »
Powered by MarkLogic Server | Terms of Use | Privacy Policy