Further to what Ron Hutchins explains: The lazy evaluation in MarkLogic can sometimes cause confusion in results of the profiler (and actually as well as some error messages).
To get more granular results in the profiler, you can make MarkLogic less lazy by wrapping xdmp:eager around some of your expressions. Kind Regards, David Ennis On 17 June 2014 14:35, Ron Hitchens <[email protected]> wrote: > > In XQuery, everything is an expression: values, sequences of values, > functions, function calls, etc. An XQuery "program" is a tree of > expressions, where some expressions are composed of other expressions. > Here is an example of a main module which is a FLWOR expression: > > for $book := /book[@status = 'pre pub'] > let $title := $book/metadata/title > let $authors := $book/metadata/author > let $author-list := format-author-list ($authors) > return book-summary ($title, $author-list, $book/abstract) > > This FLWOR is made up of several sub-expressions: the XPath > ' /book[@status = 'pre pub']', the function call 'format-author-list()', > etc. Each sub-expresson may be further composed of an expression tree. > > The profiler is hooked into the low-level expression evaluator in > MarkLogic. It records time information when each expression begins > evaluation and when the evaluation completes. As a given expression is > evaluated, there is time spent working on that expression (shallow time) > and time spent waiting for sub-expressions to to be evaluated. > > Deep time: The "wall clock" time elapsed between when an expression > begins evaluation and the time it finishes. > Shallow time: Time spent evaluating an expression when not waiting for > sub-expressions. > > There are a few special cases in the numbers that I remember (things > may have changed since I wrote the profiler several years ago). For > example, recursive calls are not measured as sub-expressions (but they are > counted), they accumulate as a single shallow time. And calls to builtin > functions never have a shallow/deep breakdown because they are atomic > expressions at the profiler level. Time spent waiting for data from > d-nodes will show as shallow time against a builtin (such as cts:search) or > an XPath expression. > > Another thing to keep in mind is that MarkLogic makes heavy use of lazy > evaluation. This means that expressions may not be evaluated in the same > order as shown in the code. For example, assigning the value of an > expensive function call to a variable may show as taking almost no time, > but at a later point, when that variable is referenced, that is where the > deep time will be assigned. This is because the expensive function may not > actually be invoked until the value of the variable is finally needed to > satisfy evaluation of another expression. > > Later versions of MarkLogic also make greater use of concurrency, which > can shift things around as well. This is because, since XQuery is a > functional language, multiple sub-expressions could be evaluated at the > same time. This could potentially yield a deep time that is less than the > sum of the deep times of the sub-expressions. > > In the profiler output, it's typically the expressions with the larger > shallow times that you want to look at. If an expression has a very large > deep time, but almost no shallow time, then it's not actually doing very > much work. All the work is being done in the sub-expressions (this is true > of many FLWOR expressions, for example). Go look at those sub-expressions > to see where the time is being spent. This is why profiler output is > typically ordered by shallow time descending. > > One last thing to note: on Windows, the time resolution is pretty poor, > which tends to make the time measurements somewhat inaccurate. What you > typically see is that things that run fairly quickly will round to zero, > which effectively make it useless for fine-grained measurement. It's still > useful for analyzing things that are slow, but gets frustrating when you > are making improvements. This is where deep time can help by measuring the > elapsed time of a compound expression even when you can't see the micro > effects. I don't know if this has improved in ML7 or with some flavors of > Windows, but it was still an issue for me about a year ago. > > Hope that helps. > > --- > Ron Hitchens {[email protected]} +44 7879 358212 > > On Jun 17, 2014, at 11:22 AM, priya dharshni <[email protected]> > wrote: > > Hi All , > > Please let me know the exact definition for shallow and deep time shown > while profiling the xquery in qconsole. > > On mouse hover it shows me - > > Shallow time is - Time spent in the expression > > deep time is - Combined time spent in expression and Sub expression. > > What is meant by sub expression here? Is that the query invoked from one > module to other module? > > Also in many occurrences the deep time is greater than the shallow time. > > Please clarify. > _______________________________________________ > General mailing list > [email protected] > http://developer.marklogic.com/mailman/listinfo/general > > > > _______________________________________________ > General mailing list > [email protected] > http://developer.marklogic.com/mailman/listinfo/general > >
_______________________________________________ General mailing list [email protected] http://developer.marklogic.com/mailman/listinfo/general
