Solr
  1. Solr
  2. SOLR-6039

debug=track causes debug=query info to be suppressed when no results found

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 4.7
    • Fix Version/s: 4.8.1, 4.9, 6.0
    • Component/s: None
    • Labels:
      None

      Description

      Shamik Bandopadhyay noted on the mailing list that debugQuery=true wasn't returning info about how the query was being parsed in SolrCloud.

      Steps to reproduce...


      The work around, for people who want don't care about the newer "debug tracking" and what the same debug information as pre-4.7, is to enumerate the debug options (ie: debug=query&debug=timing&debug=results) instead of relying on the shorthand: debugQuery=true

      1. SOLR-6039.patch
        18 kB
        Tomás Fernández Löbbe
      2. SOLR-6039.patch
        13 kB
        Hoss Man
      3. SOLR-6039.patch
        9 kB
        Tomás Fernández Löbbe
      4. SOLR-6039.patch
        6 kB
        Tomás Fernández Löbbe

        Issue Links

          Activity

          Hide
          Shawn Heisey added a comment -

          I had noticed this with a non-cloud distributed search on Solr 4.7. It was causing problems when trying to figure out why a search wasn't returning results. I sent the query directly to a shard to get the info, and put the problem in the mental category of "Report it later when there's time."

          Show
          Shawn Heisey added a comment - I had noticed this with a non-cloud distributed search on Solr 4.7. It was causing problems when trying to figure out why a search wasn't returning results. I sent the query directly to a shard to get the info, and put the problem in the mental category of "Report it later when there's time."
          Hide
          Tomás Fernández Löbbe added a comment -

          I'm looking into this issue. This patch would fix the problem described in the users list with the query explain, but not yet the with the timing.
          I kind of see where the timing issue is too, but I'm wondering if this is expected. Seems like the timing info should be merged in DebugComponent.finishStage(...), but as it is now, it would only consider the time spent in the phases with GET_DEBUG purpose. This purpose is only included in in the GET_FIELDS phase, we would not be considering time in parts of the request?
          In addition, once it gets the timing information from the shards it adds it. I think it would be better if it get the max value instead? after all, the time in each phase will be the time the slowest shard took, right?

          Show
          Tomás Fernández Löbbe added a comment - I'm looking into this issue. This patch would fix the problem described in the users list with the query explain, but not yet the with the timing. I kind of see where the timing issue is too, but I'm wondering if this is expected. Seems like the timing info should be merged in DebugComponent.finishStage(...), but as it is now, it would only consider the time spent in the phases with GET_DEBUG purpose. This purpose is only included in in the GET_FIELDS phase, we would not be considering time in parts of the request? In addition, once it gets the timing information from the shards it adds it. I think it would be better if it get the max value instead? after all, the time in each phase will be the time the slowest shard took, right?
          Hide
          Tomás Fernández Löbbe added a comment -

          This patch adds the timing info in all phases. The times responded by shards are still being added

          Show
          Tomás Fernández Löbbe added a comment - This patch adds the timing info in all phases. The times responded by shards are still being added
          Hide
          Hoss Man added a comment -

          This patch adds the timing info in all phases. The times responded by shards are still being added

          Yeah ... i think for now it makes sense to just "fix" the bug relating ot wether the info comes back - but leave the definition the same as it's been and leave the question for wether the timing info should be "merged" differnetly for another issue (i can see different advantages to both sum vs max)

          I didnt' fully understand the changes you made when skimming your patch – but i did understand your test, and it looks good & fairly ccomprehensive and fills me with confidence that the fix is correct. One thing i thing i noticed was still missing though is some testing of picking multiple options (ie: "debug=query&debug=timing") so i've added a randomized testing method that accounts for that case 9among other things)

          Show
          Hoss Man added a comment - This patch adds the timing info in all phases. The times responded by shards are still being added Yeah ... i think for now it makes sense to just "fix" the bug relating ot wether the info comes back - but leave the definition the same as it's been and leave the question for wether the timing info should be "merged" differnetly for another issue (i can see different advantages to both sum vs max) I didnt' fully understand the changes you made when skimming your patch – but i did understand your test, and it looks good & fairly ccomprehensive and fills me with confidence that the fix is correct. One thing i thing i noticed was still missing though is some testing of picking multiple options (ie: "debug=query&debug=timing") so i've added a randomized testing method that accounts for that case 9among other things)
          Hide
          Tomás Fernández Löbbe added a comment -

          i think for now it makes sense to just "fix" the bug relating ot wether the info comes back

          I agree now. When I started to think how to use max vs sum in some situations I saw the changes were not trivial, better to leave that for a different Jira.

          I was about to upload a new patch with some more changes and tests, please give me some time until I merge with your changes before committing.

          Show
          Tomás Fernández Löbbe added a comment - i think for now it makes sense to just "fix" the bug relating ot wether the info comes back I agree now. When I started to think how to use max vs sum in some situations I saw the changes were not trivial, better to leave that for a different Jira. I was about to upload a new patch with some more changes and tests, please give me some time until I merge with your changes before committing.
          Hide
          Tomás Fernández Löbbe added a comment -

          I didnt' fully understand the changes you made when skimming your patch

          Besides adding the query section when there are no "GET_DEBUG_PURPOSE" requests (that it's on on the GET_FIELDS phase), one thing that changes with the patch is that the shard requests for all phases will require "debug=timing" if timing is needed. Then after the final phase those times are added.
          Before this change, the timing section didn't come back on queries with no docs (this is I think a previous than SOLR-5399), now it does.
          Another implication with this change is that all shard requests will be considered, and not only the last phase (will now show higher times). As I say before, the times for all shard responses are being added, and because many of those requests are sent in parallel, this means that the timing displayed may be higher than the clock time of the request. I think this is useful information anyway and should be considered more as a metric of how much each component is taking in all the request.

          Show
          Tomás Fernández Löbbe added a comment - I didnt' fully understand the changes you made when skimming your patch Besides adding the query section when there are no "GET_DEBUG_PURPOSE" requests (that it's on on the GET_FIELDS phase), one thing that changes with the patch is that the shard requests for all phases will require "debug=timing" if timing is needed. Then after the final phase those times are added. Before this change, the timing section didn't come back on queries with no docs (this is I think a previous than SOLR-5399 ), now it does. Another implication with this change is that all shard requests will be considered, and not only the last phase (will now show higher times). As I say before, the times for all shard responses are being added, and because many of those requests are sent in parallel, this means that the timing displayed may be higher than the clock time of the request. I think this is useful information anyway and should be considered more as a metric of how much each component is taking in all the request.
          Hide
          ASF subversion and git services added a comment -

          Commit 1592605 from hossman@apache.org in branch 'dev/trunk'
          [ https://svn.apache.org/r1592605 ]

          SOLR-6039: fixed debug output when no results in response

          Show
          ASF subversion and git services added a comment - Commit 1592605 from hossman@apache.org in branch 'dev/trunk' [ https://svn.apache.org/r1592605 ] SOLR-6039 : fixed debug output when no results in response
          Hide
          ASF subversion and git services added a comment -

          Commit 1592609 from hossman@apache.org in branch 'dev/branches/branch_4x'
          [ https://svn.apache.org/r1592609 ]

          SOLR-6039: fixed debug output when no results in response (merge r1592605)

          Show
          ASF subversion and git services added a comment - Commit 1592609 from hossman@apache.org in branch 'dev/branches/branch_4x' [ https://svn.apache.org/r1592609 ] SOLR-6039 : fixed debug output when no results in response (merge r1592605)
          Hide
          Hoss Man added a comment -

          thanks Tomas

          I'll let jenkins hammer this for a day or so and then look into back-porting for 4.8.1

          Show
          Hoss Man added a comment - thanks Tomas I'll let jenkins hammer this for a day or so and then look into back-porting for 4.8.1
          Hide
          ASF subversion and git services added a comment -

          Commit 1592821 from hossman@apache.org in branch 'dev/branches/lucene_solr_4_8'
          [ https://svn.apache.org/r1592821 ]

          Merge back several "low hanging" bug fixes into the 4.8 branch...
          SOLR-6029: r1590867
          SOLR-6030: r1591555
          SOLR-6037: r1591800
          SOLR-6023: r1592195
          SOLR-5090: r1592591
          SOLR-6039: r1592605
          SOLR-5993: r1588415
          SOLR-5904: r1587702

          Show
          ASF subversion and git services added a comment - Commit 1592821 from hossman@apache.org in branch 'dev/branches/lucene_solr_4_8' [ https://svn.apache.org/r1592821 ] Merge back several "low hanging" bug fixes into the 4.8 branch... SOLR-6029 : r1590867 SOLR-6030 : r1591555 SOLR-6037 : r1591800 SOLR-6023 : r1592195 SOLR-5090 : r1592591 SOLR-6039 : r1592605 SOLR-5993 : r1588415 SOLR-5904 : r1587702

            People

            • Assignee:
              Tomás Fernández Löbbe
              Reporter:
              Hoss Man
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development