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
