Re: [MarkLogic Dev General] Definition for Shallow time and deep time
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 {r...@overstory.co.uk} +44 7879 358212
On Jun 17, 2014, at 11:22 AM, priya dharshni 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
> General@developer.marklogic.com
> http://developer.marklogic.com/mailman/listinfo/general
___
General mailing list
General@developer.marklogic.com
http://developer.marklogic.com/mailman/listinfo/general
Re: [MarkLogic Dev General] Definition for Shallow time and deep time
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 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 {r...@overstory.co.uk} +44 7879 358212
>
> On Jun 17, 2014, at 11:22 AM, priya dharshni
> 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.
> _
[MarkLogic Dev General] Definition for Shallow time and deep time
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 General@developer.marklogic.com http://developer.marklogic.com/mailman/listinfo/general
