Michah,
Ah, I think so. Then would subtracting a finished elapsed-time from a start
elapsed time be a reasonable way to calculate an individual function call's
time? For example:
declare function s:do-snippet(
$result as node(),
$ctsquery as schema-element(cts:query),
$options as element(search:transform-results)?
) as element(search:snippet)
{
let $x := s:do-stuff($result//a)
let $y := s:do-more-stuff($result//b)
return
s:package-it-up($x,$y)
};
declare function s:do-stuff(
$x as element(a)
) as xs:string*
{
let $start := xdmp:elapsed-time()
return
(
*do work*,
xdmp:log(concat("do-stuff time: ",xdmp:elapsed-time() - $start))
)
};
Best,
Will
-----Original Message-----
From: [email protected]
[mailto:[email protected]] On Behalf Of Micah Dubinko
Sent: Wednesday, February 22, 2012 4:43 PM
To: MarkLogic Developer Discussion
Subject: Re: [MarkLogic Dev General] Timing in snippet extension module
Hi Will,
xdmp:elapsed-time measures the overall elapsed time for the request, at the
instant it is called.
Inside Search API, at the start of processing the specific search we record
$t-minus-zero then subtract that from the elapsed-time at the end to produce
the total-time value. This is to avoid measuring the time taken by other things
happening in that request but outside of Search API.
I don't know the details of your log statement from the listing below, but if
the first happened at 0.392 and the last at 0.704 then in that case the elapsed
is
( 0.704 - 0.392 = 0.312 seconds) well within the reported total-time value.
Does this make sense?
Thanks, -m
On Feb 22, 2012, at 4:22 PM, Will Thompson wrote:
> xdmp:elapsed-time() is reporting some confusing numbers from my Search API
> snippet extension module. I have a function (actually several) that I would
> like to time so I can target the slower parts for optimization. I am logging
> the times, and they look like this:
>
> 2012-02-22 15:45:11.629 Info: HTTP-server: snippet
> 2012-02-22 15:45:11.639 Info: HTTP-server: func() time: PT0.392S
> 2012-02-22 15:45:11.639 Info: HTTP-server: func() time: PT0.392S
> 2012-02-22 15:45:11.640 Info: HTTP-server: func() time: PT0.393S
> 2012-02-22 15:45:11.640 Info: HTTP-server: func() time: PT0.393S
> 2012-02-22 15:45:11.641 Info: HTTP-server: func() time: PT0.394S
> 2012-02-22 15:45:11.642 Info: HTTP-server: func() time: PT0.395S
> 2012-02-22 15:45:11.655 Info: HTTP-server: snippet
> 2012-02-22 15:45:11.659 Info: HTTP-server: func() time: PT0.412S
> 2012-02-22 15:45:11.659 Info: HTTP-server: func() time: PT0.412S
> 2012-02-22 15:45:11.668 Info: HTTP-server: snippet
> 2012-02-22 15:45:11.672 Info: HTTP-server: func() time: PT0.425S
> 2012-02-22 15:45:11.672 Info: HTTP-server: func() time: PT0.425S
> 2012-02-22 15:45:11.673 Info: HTTP-server: func() time: PT0.426S
> 2012-02-22 15:45:11.683 Info: HTTP-server: snippet
> ...
> 2012-02-22 15:45:11.942 Info: HTTP-server: func() time: PT0.695S
> 2012-02-22 15:45:11.942 Info: HTTP-server: func() time: PT0.695S
> 2012-02-22 15:45:11.942 Info: HTTP-server: func() time: PT0.695S
> 2012-02-22 15:45:11.945 Info: HTTP-server: func() time: PT0.698S
> 2012-02-22 15:45:11.946 Info: HTTP-server: func() time: PT0.699S
> 2012-02-22 15:45:11.946 Info: HTTP-server: func() time: PT0.699S
> 2012-02-22 15:45:11.947 Info: HTTP-server: func() time: PT0.7S
> 2012-02-22 15:45:11.947 Info: HTTP-server: func() time: PT0.7S
> 2012-02-22 15:45:11.947 Info: HTTP-server: func() time: PT0.7S
> 2012-02-22 15:45:11.949 Info: HTTP-server: func() time: PT0.702S
> 2012-02-22 15:45:11.950 Info: HTTP-server: func() time: PT0.703S
> 2012-02-22 15:45:11.951 Info: HTTP-server: func() time: PT0.704S
> 2012-02-22 15:45:11.951 Info: HTTP-server: func() time: PT0.704S
>
> Execution time is increasing, and I assume this is related to concurrent
> execution of snippets. But I can't square this with the metrics I get back
> from the search call:
>
> <search:metrics>
> <search:query-resolution-time>PT0.012S</search:query-resolution-time>
> <search:facet-resolution-time>PT0.011S</search:facet-resolution-time>
> <search:snippet-resolution-time>PT0S</search:snippet-resolution-time>
> <search:total-time>PT0.656S</search:total-time>
> </search:metrics>
>
> Total time is reported as less than the longest func() time
> (snippet-resolution-time returning 0 is a known bug). Also, func() is
> probably not even the most expensive operation in my snippet module, so it
> seems like I just can't trust these times at all.
>
> Any ideas?
>
> Best,
>
> Will
>
>
> _______________________________________________
> 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
