[MarkLogic Dev General] Timing in snippet extension module

[Micah Dubinko]

Yes, that will work great. The profiler in Query Console is also very helpful.

Thanks, -m

On Feb 22, 2012, at 4:58 PM, Will Thompson wrote:

> 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: general-bounces at developer.marklogic.com [mailto:general-bounces at developer.marklogic.com] 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
>> General at developer.marklogic.com
>> http://developer.marklogic.com/mailman/listinfo/general
> 
> _______________________________________________
> General mailing list
> General at developer.marklogic.com
> http://developer.marklogic.com/mailman/listinfo/general
> _______________________________________________
> General mailing list
> General at developer.marklogic.com
> http://developer.marklogic.com/mailman/listinfo/general