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