Solr
  1. Solr
  2. SOLR-176

Add detailed timing data to query response output

    Details

    • Type: New Feature New Feature
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 1.2
    • Fix Version/s: 1.3
    • Component/s: search
    • Labels:
      None
    1. dtiming.patch
      9 kB
      Mike Klaas
    2. dtiming.patch
      9 kB
      Mike Klaas
    3. RequesthandlerBase.patch
      1 kB
      Will Johnson
    4. dtiming.patch
      12 kB
      Ryan McKinley
    5. dtiming.patch
      13 kB
      Mike Klaas
    6. RequesthandlerBase.patch
      7 kB
      Will Johnson

      Issue Links

        Activity

        Hide
        Ryan McKinley added a comment -

        If possible, it would also be nice to include the change in cache sizes from the beginning to the end of the request. This would help optimize cache sizes for faceting.

        thanks

        Show
        Ryan McKinley added a comment - If possible, it would also be nice to include the change in cache sizes from the beginning to the end of the request. This would help optimize cache sizes for faceting. thanks
        Hide
        Mike Klaas added a comment -

        Well, we could provide deltas of all the solr statistics, but I'm not sure if it provides much benefit over watching the stats page before and after executing a query.

        What might be more useful if for the facet code to detect facet-cache-thrashing (evictions ~= insertions), and emit a performance warning in the logfile.

        Show
        Mike Klaas added a comment - Well, we could provide deltas of all the solr statistics, but I'm not sure if it provides much benefit over watching the stats page before and after executing a query. What might be more useful if for the facet code to detect facet-cache-thrashing (evictions ~= insertions), and emit a performance warning in the logfile.
        Hide
        Mike Klaas added a comment -

        A quick version for people to play with. Includes a new timing class, plus timing data inserted into the dismax handler.

        Show
        Mike Klaas added a comment - A quick version for people to play with. Includes a new timing class, plus timing data inserted into the dismax handler.
        Hide
        Mike Klaas added a comment -

        Same version with ASF license. Output format looks like:

        <lst name="timing">
        <double name="debug">13.0</double>
        <double name="main query">1.0</double>
        <double name="time">19.0</double>
        <double name="setup/query parsing">5.0</double>
        <double name="pre fetch">0.0</double>
        </lst>

        (Note that RTimer supports aritrary nesting of timers)

        Show
        Mike Klaas added a comment - Same version with ASF license. Output format looks like: <lst name="timing"> <double name="debug">13.0</double> <double name="main query">1.0</double> <double name="time">19.0</double> <double name="setup/query parsing">5.0</double> <double name="pre fetch">0.0</double> </lst> (Note that RTimer supports aritrary nesting of timers)
        Hide
        Ryan McKinley added a comment -

        works great for me. thanks!

        nesting timers is really nice.

        Show
        Ryan McKinley added a comment - works great for me. thanks! nesting timers is really nice.
        Hide
        Mike Klaas added a comment -

        Anyone else have an opinion on timing? It would be easy for me to wrap StandardRequestHandler similarly and commit.

        If I add a test or two and put a warning about RTimer being not part of the official solr programmable api, then backward concerns should be limited to the response output. (Otherwise it is likely necessary to think about the design of the RTimer api).

        Show
        Mike Klaas added a comment - Anyone else have an opinion on timing? It would be easy for me to wrap StandardRequestHandler similarly and commit. If I add a test or two and put a warning about RTimer being not part of the official solr programmable api, then backward concerns should be limited to the response output. (Otherwise it is likely necessary to think about the design of the RTimer api).
        Hide
        Hoss Man added a comment -

        i don't have any strong opinions, but i agree with your plan about putting some warnings in the RTTimer javadocs.

        Random thought: it might be cleaner/easier in the long run to create/register a hog Handler that records timing differences and add calls to Logger.entering and Logger.exiting on the various methods.

        someone may have already implemented such a Handler

        Show
        Hoss Man added a comment - i don't have any strong opinions, but i agree with your plan about putting some warnings in the RTTimer javadocs. Random thought: it might be cleaner/easier in the long run to create/register a hog Handler that records timing differences and add calls to Logger.entering and Logger.exiting on the various methods. someone may have already implemented such a Handler
        Hide
        Will Johnson added a comment -

        added some average stats to RequestHandlerBase. all of the same info can be obtained by parsing the log files but having it show up on the admin screens and jmx is simple and nice to have. stats added: avgTimePerRequest and avgRequestsPerSecond.

        Show
        Will Johnson added a comment - added some average stats to RequestHandlerBase. all of the same info can be obtained by parsing the log files but having it show up on the admin screens and jmx is simple and nice to have. stats added: avgTimePerRequest and avgRequestsPerSecond.
        Hide
        Ryan McKinley added a comment -
        • applies with trunk.
        • added timing info to StandardRequestHandler

        I think this will make lots of sense in the context of search components:
        http://www.nabble.com/search-components-%28plugins%29-tf3898040.html

        Show
        Ryan McKinley added a comment - applies with trunk. added timing info to StandardRequestHandler I think this will make lots of sense in the context of search components: http://www.nabble.com/search-components-%28plugins%29-tf3898040.html
        Hide
        Mike Klaas added a comment -

        Might it then make sense to wait until the search component thing is done? Auto-timing everything would be easy.

        Show
        Mike Klaas added a comment - Might it then make sense to wait until the search component thing is done? Auto-timing everything would be easy.
        Hide
        Ryan McKinley added a comment -

        Will's RequesthandlerBase.patch addition is simple, straightforward, useful - i will add that now.

        Show
        Ryan McKinley added a comment - Will's RequesthandlerBase.patch addition is simple, straightforward, useful - i will add that now.
        Hide
        Ryan McKinley added a comment -

        >
        > Might it then make sense to wait until the search component thing is done? Auto-timing everything would be easy.
        >

        Yes, i think so. but this is still useful for debuging in the meantime. (as a patch)

        Will's addition is independent, it adds average timing info to RequestHandler statistics

        Show
        Ryan McKinley added a comment - > > Might it then make sense to wait until the search component thing is done? Auto-timing everything would be easy. > Yes, i think so. but this is still useful for debuging in the meantime. (as a patch) Will's addition is independent, it adds average timing info to RequestHandler statistics
        Hide
        Mike Klaas added a comment -

        added javadocs for RTimer.java, and removed a superfluous line from SRH.java

        Show
        Mike Klaas added a comment - added javadocs for RTimer.java, and removed a superfluous line from SRH.java
        Hide
        Will Johnson added a comment -

        a slightly more ambitious patch that tracks:

        • total number of requests/errors
        • requests/errors in the current interval (interval defined in solrconfig)
        • requets/errors as of the start of the last interval
        • avg requet times for total / current interval
        Show
        Will Johnson added a comment - a slightly more ambitious patch that tracks: total number of requests/errors requests/errors in the current interval (interval defined in solrconfig) requets/errors as of the start of the last interval avg requet times for total / current interval
        Hide
        Ryan McKinley added a comment -

        Committed as part of SOLR-281

        Show
        Ryan McKinley added a comment - Committed as part of SOLR-281

          People

          • Assignee:
            Mike Klaas
            Reporter:
            Mike Klaas
          • Votes:
            2 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development