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
