How do I read and interpret QConsole profile output?
19 March 2015 06:32 PM
This article is intended to give you enough information to enable you to understand the output from query console's profiler.
Consider the following XQuery:
This FLWOR expression will load an xml file into memory, then find each MedlineCitation element and insert it as a document in the database. Although this example is very simple, it should give us enough information to understand what the profiler does and how to understand the output.
Scenario / Walkthrough
Profile the query
Now run the same query again, only this time, ensure "Profile" is selected before you hit the run button.
You should see something like this (click image to view it in a separate window):
The header shows overall statistics for the query:
The table shows the profiler results for the expressions evaluated in the request, one row for each expression:
Shallow time vs deep time
In profiler output you will usually want to pay the most attention to expressions that have a large shallow time. These expressions are doing the most work, exclusive of work done in sub-expressions.
If an expression has a very large deep time, but almost no shallow time, then most of the time is being spent in sub-expressions.
For example, in the profiler output shown, the FLWOR expression at .main:2:0 has the most deep time since it has includes the other expressions, but not a lot of shallow time since it doesn't do much work itself. The expression at .main:3:45 has a lot of deep time, but that all comes from the subexpression at .main:3:18, which takes the most time.
The default sorting of the table is by Shallow % descending. This a generally a good view as it will bring the expressions taking the most shallow time to the top. You can sort on a different column by clicking on the column header.
Cold vs warm
Timings may change for a query if you execute it more than once, due to the caching performed by MarkLogic. A query will be slower if it needs data that is not available in the caches (cold) vs where much of the information is available from caches (warm). This is by design and gives better performance as the system runs and caches frequently used information.
Another characteristic of MarkLogic Server is its use of lazy evaluation. A relatively expensive evaluation may return quickly without performing the work necessary to produce results. Then, when the results are needed, the work will actually be performed and the evaluation time will be assigned at that point. This can give surprising results.
Wrapping an expression in