Category: xquery

MarkLogic profiler

When investigating slow XQuery or XSLT queries in MarkLogic, one of the tools it provides is a query profiler. In this post I’ll explain how to make use of the profiler and how to interpret the results.

There are 3 ways you can make use of the profiler:

  1. use the MarkLogic QConsole;
  2. use an IDE that supports the profiler like IntelliJ with the XQuery and XSLT plugin;
  3. use the MarkLogic profiler API.

Using the QConsole

In the MarkLogic QConsole you can enable profiling by clicking on the Profile tab next to the Results tab and pressing the Run button. This will display a table with the profiling results. The profile can be saved by clicking on the download button on the right.

The profile result table contains the following information:

  1. Module:Line No.: Col No. – This is where the expression being profiled starts;
  2. Count – This is the number of times the expression was evaluated;
  3. Shallow %/Shallow ms – This is how long the expression took to run on its own across all Count times it was evaluated;
  4. Deep %/Deep ms – This is how long the expression took to run in addition to the time subexpessions took to evaluate;
  5. Expression – This is the string representation of the query expression being evaluated.

NOTE: Here, ms is microseconds not milliseconds.

If you want to do further processing on the downloaded profile:report XML, you can load that XML by using:

let $data := xdmp:filesystem-file("C:\profiling\profile.xml")
let $profile := xdmp:unquote($data)/prof:report

Analysing Profile Results

Sorting by shallow time is useful for identifying the expressions that take a long time to evaluate. This can identify places where you should modify the query or add indices.

The count column is also useful. It can indicate places where you have nested loops that result in quadratic time queries.

When making optimizations, it can be tricky to know if a change results in a speed up of the query or is not significant, but shows up in the normal time variation when running a query multiple times. To handle this, I like to use a spreadsheet and measure the average (mean) time and standard deviation over 5 or 10 runs.

This can also be useful when varying the number of items being processed (e.g. documents) in order to identify if the query scales with that item, and whether the scaling is linear, quadratic, or some other curve. For this, you can use line graphs to visualise the performance and linear or quadratic regression formulae to check what shape the graph is.

The stock chart graph is useful for comparing the variation between runs. Here, the mininum and maximum times form the extents (low, high) of the chart, and the mean +/- one standard deviation form the inner bar (open, close) of the chart.

Using the Profiler API

Using the profiler API you can use the following to collect the profile data from a query expression:

let $_ := prof:enable(xdmp:request())
(: code to profile, e.g. -- let $_ := local:test() :)
let $_ := prof:disable(xdmp:request())
let $profile := prof:report(xdmp:request())

NOTE: If you are running this from an XQuery 1.0 query instead of a 1.0-ml query then you need to declare the prof namespace:

declare namespace prof = "http://marklogic.com/xdmp/profile";

You can then either save the profile to a file, e.g.:

let $_ := xdmp:save("C:\profiling\profile.xml", $profile)

or process the resulting profile:report XML in the XQuery script.

Alternatively you can use one of the prof:eval or prof:xslt-eval to evaluate an in memory query, or prof:invoke or prof:xslt-invoke to evaluate a module file. These return the profile data as the first item and the result as the remaining items, so you can use the following:

let $ret := prof:eval("for $x in 1 to 10 return $x")
let $profile := $ret[1]
let $results := $ret[position() != 1]

With the profile report XML, you can then process it as you need. For example, to create a CSV version of the QConsole profile table you can use the following query:

declare function local:to-seconds($value) {
  ($value cast as xs:dayTimeDuration) div xs:dayTimeDuration("PT1S")
};

let $overall-elapsed := local:to-seconds($profile/prof:metadata/prof:overall-elapsed)
for $expression in $profile/prof:histogram/prof:expression
let $source := $expression/prof:expr-source/string()
let $uri := string(($expression/prof:uri/text(), "main")[1])
let $line := $expression/prof:line cast as xs:integer
let $column := ($expression/prof:column cast as xs:integer) + 1
let $count := $expression/prof:count cast as xs:integer
let $shallow-time := local:to-seconds($expression/prof:shallow-time)
let $deep-time := local:to-seconds($expression/prof:deep-time)
order by $shallow-time descending
return
  string-join((
    $uri, $line, $column, $count,
    $shallow-time, ($shallow-time div $overall-elapsed) * 100,
    $deep-time, ($deep-time div $overall-elapsed) * 100,
    $source
  ) ! string(.), ",")

NOTE: This does not handle escaping of commas in the $source string.