Solr
  1. Solr
  2. SOLR-6650

Add optional slow request logging at WARN level

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 5.0
    • Component/s: None
    • Labels:

      Description

      At super high request rates, logging all the requests can become a bottleneck and therefore INFO logging is often turned off. However, it is still useful to be able to set a latency threshold above which a request is considered "slow" and log that request at WARN level so we can easily identify slow queries.

        Activity

        Hide
        ASF GitHub Bot added a comment -

        GitHub user mewmewball opened a pull request:

        https://github.com/apache/lucene-solr/pull/101

        SOLR-6650 - Add optional slow request logging at WARN level

        You can merge this pull request into a Git repository by running:

        $ git pull https://github.com/mewmewball/lucene-solr trunk

        Alternatively you can review and apply these changes as the patch at:

        https://github.com/apache/lucene-solr/pull/101.patch

        To close this pull request, make a commit to your master/trunk branch
        with (at least) the following in the commit message:

        This closes #101


        commit 8096b200187b81de78862ca71026a13d6a793650
        Author: Jessica Cheng <jessica_cheng@apple.com>
        Date: 2014-10-23T23:07:31Z

        SOLR-6650 - Add optional slow request logging at WARN level

        commit c25993724e48343d8cc941cc0228312e9ff4f3ab
        Author: Jessica Cheng <jessica_cheng@apple.com>
        Date: 2014-10-23T23:08:25Z

        Merge branch 'trunk' of https://github.com/mewmewball/lucene-solr into trunk

        1. By Jan Høydahl
        2. Via Jan Høydahl

        Show
        ASF GitHub Bot added a comment - GitHub user mewmewball opened a pull request: https://github.com/apache/lucene-solr/pull/101 SOLR-6650 - Add optional slow request logging at WARN level You can merge this pull request into a Git repository by running: $ git pull https://github.com/mewmewball/lucene-solr trunk Alternatively you can review and apply these changes as the patch at: https://github.com/apache/lucene-solr/pull/101.patch To close this pull request, make a commit to your master/trunk branch with (at least) the following in the commit message: This closes #101 commit 8096b200187b81de78862ca71026a13d6a793650 Author: Jessica Cheng <jessica_cheng@apple.com> Date: 2014-10-23T23:07:31Z SOLR-6650 - Add optional slow request logging at WARN level commit c25993724e48343d8cc941cc0228312e9ff4f3ab Author: Jessica Cheng <jessica_cheng@apple.com> Date: 2014-10-23T23:08:25Z Merge branch 'trunk' of https://github.com/mewmewball/lucene-solr into trunk By Jan Høydahl Via Jan Høydahl 'trunk' of https://github.com/mewmewball/lucene-solr: SOLR-6647 : Bad error message when missing resource from ZK when parsing Schema
        Hide
        Yonik Seeley added a comment -

        +1, great idea!

        Show
        Yonik Seeley added a comment - +1, great idea!
        Hide
        Timothy Potter added a comment -

        Just doing some basic testing and then will commit.

        Show
        Timothy Potter added a comment - Just doing some basic testing and then will commit.
        Hide
        ASF subversion and git services added a comment -

        Commit 1634086 from Timothy Potter in branch 'dev/trunk'
        [ https://svn.apache.org/r1634086 ]

        SOLR-6650: Add optional slow request logging at WARN level; this closes #101

        Show
        ASF subversion and git services added a comment - Commit 1634086 from Timothy Potter in branch 'dev/trunk' [ https://svn.apache.org/r1634086 ] SOLR-6650 : Add optional slow request logging at WARN level; this closes #101
        Hide
        ASF subversion and git services added a comment -

        Commit 1634088 from Timothy Potter in branch 'dev/branches/branch_5x'
        [ https://svn.apache.org/r1634088 ]

        SOLR-6650: Add optional slow request logging at WARN level; this closes #101

        Show
        ASF subversion and git services added a comment - Commit 1634088 from Timothy Potter in branch 'dev/branches/branch_5x' [ https://svn.apache.org/r1634088 ] SOLR-6650 : Add optional slow request logging at WARN level; this closes #101
        Hide
        ASF GitHub Bot added a comment -

        Github user asfgit closed the pull request at:

        https://github.com/apache/lucene-solr/pull/101

        Show
        ASF GitHub Bot added a comment - Github user asfgit closed the pull request at: https://github.com/apache/lucene-solr/pull/101
        Hide
        ASF GitHub Bot added a comment -

        GitHub user mewmewball opened a pull request:

        https://github.com/apache/lucene-solr/pull/102

        SOLR-6650 - Add optional slow request logging at WARN level

        Based on discussion with Chris Hostetter, make the slow warn logging an if condition on its own rather than an else for the info logging. Also, add "slow: " prefix to the log message so it's easy to spot redundancy with info level.

        You can merge this pull request into a Git repository by running:

        $ git pull https://github.com/mewmewball/lucene-solr trunk

        Alternatively you can review and apply these changes as the patch at:

        https://github.com/apache/lucene-solr/pull/102.patch

        To close this pull request, make a commit to your master/trunk branch
        with (at least) the following in the commit message:

        This closes #102


        commit 8096b200187b81de78862ca71026a13d6a793650
        Author: Jessica Cheng <jessica_cheng@apple.com>
        Date: 2014-10-23T23:07:31Z

        SOLR-6650 - Add optional slow request logging at WARN level

        commit c25993724e48343d8cc941cc0228312e9ff4f3ab
        Author: Jessica Cheng <jessica_cheng@apple.com>
        Date: 2014-10-23T23:08:25Z

        Merge branch 'trunk' of https://github.com/mewmewball/lucene-solr into trunk

        1. By Jan Høydahl
        2. Via Jan Høydahl

        commit 5c69624555b4f3f4aa21627efd57772dfa0a477c
        Author: Jessica Cheng <jessica_cheng@apple.com>
        Date: 2014-10-24T18:23:37Z

        Merge branch 'trunk' of https://github.com/apache/lucene-solr into trunk

        commit ba2a87b22dbc4355e663fb68a6dd4de16b42ff47
        Author: Jessica Cheng <jessica_cheng@apple.com>
        Date: 2014-10-24T20:06:21Z

        SOLR-6650 - Add optional slow request logging at WARN level - Based on discussion with Chris Hostetter, make the slow warn logging an if condition on its own rather than an else for the info logging. Also, add "slow: " prefix to the log message so it's easy to spot redundancy with info level.


        Show
        ASF GitHub Bot added a comment - GitHub user mewmewball opened a pull request: https://github.com/apache/lucene-solr/pull/102 SOLR-6650 - Add optional slow request logging at WARN level Based on discussion with Chris Hostetter, make the slow warn logging an if condition on its own rather than an else for the info logging. Also, add "slow: " prefix to the log message so it's easy to spot redundancy with info level. You can merge this pull request into a Git repository by running: $ git pull https://github.com/mewmewball/lucene-solr trunk Alternatively you can review and apply these changes as the patch at: https://github.com/apache/lucene-solr/pull/102.patch To close this pull request, make a commit to your master/trunk branch with (at least) the following in the commit message: This closes #102 commit 8096b200187b81de78862ca71026a13d6a793650 Author: Jessica Cheng <jessica_cheng@apple.com> Date: 2014-10-23T23:07:31Z SOLR-6650 - Add optional slow request logging at WARN level commit c25993724e48343d8cc941cc0228312e9ff4f3ab Author: Jessica Cheng <jessica_cheng@apple.com> Date: 2014-10-23T23:08:25Z Merge branch 'trunk' of https://github.com/mewmewball/lucene-solr into trunk By Jan Høydahl Via Jan Høydahl 'trunk' of https://github.com/mewmewball/lucene-solr: SOLR-6647 : Bad error message when missing resource from ZK when parsing Schema commit 5c69624555b4f3f4aa21627efd57772dfa0a477c Author: Jessica Cheng <jessica_cheng@apple.com> Date: 2014-10-24T18:23:37Z Merge branch 'trunk' of https://github.com/apache/lucene-solr into trunk commit ba2a87b22dbc4355e663fb68a6dd4de16b42ff47 Author: Jessica Cheng <jessica_cheng@apple.com> Date: 2014-10-24T20:06:21Z SOLR-6650 - Add optional slow request logging at WARN level - Based on discussion with Chris Hostetter, make the slow warn logging an if condition on its own rather than an else for the info logging. Also, add "slow: " prefix to the log message so it's easy to spot redundancy with info level.
        Hide
        Shawn Heisey added a comment -

        I like this idea. I can turn off INFO logging, set a threshold, and chances are good that whatever I need to look at is something that will be logged, but the file will not be clogged with every request.

        My look at the patch was very quick, so I have not noticed every detail. It looks like this defaults to enabled with a threshold of 1 second. If that's the case, I don't think that's a good idea. It should default to disabled.

        Hopefully it will log all queries if I set the threshold to zero. A negative number in the setting (or the setting not present) would be a good way to turn it off. Will this only log queries, or would it log all slow requests, including calls to /update?

        Show
        Shawn Heisey added a comment - I like this idea. I can turn off INFO logging, set a threshold, and chances are good that whatever I need to look at is something that will be logged, but the file will not be clogged with every request. My look at the patch was very quick, so I have not noticed every detail. It looks like this defaults to enabled with a threshold of 1 second. If that's the case, I don't think that's a good idea. It should default to disabled. Hopefully it will log all queries if I set the threshold to zero. A negative number in the setting (or the setting not present) would be a good way to turn it off. Will this only log queries, or would it log all slow requests, including calls to /update?
        Hide
        Tomás Fernández Löbbe added a comment -

        It looks like this defaults to enabled with a threshold of 1 second. If that's the case, I don't think that's a good idea. It should default to disabled.

        +1 Specially now that the idea is to log WARN in addition to INFO. People that don't have this setting in the solrconfig (upgrading?) will start logging twice for many queries.

        Show
        Tomás Fernández Löbbe added a comment - It looks like this defaults to enabled with a threshold of 1 second. If that's the case, I don't think that's a good idea. It should default to disabled. +1 Specially now that the idea is to log WARN in addition to INFO. People that don't have this setting in the solrconfig (upgrading?) will start logging twice for many queries.
        Hide
        Timothy Potter added a comment -

        FWIW - the original patch didn't have that problem in that it either logged as INFO if INFO was enabled for SolrCore's logger OR logged at WARN if the threshold was breached if SolrCore's logger was set to WARN ... re-opening the issue to pull in these additional changes

        Show
        Timothy Potter added a comment - FWIW - the original patch didn't have that problem in that it either logged as INFO if INFO was enabled for SolrCore's logger OR logged at WARN if the threshold was breached if SolrCore's logger was set to WARN ... re-opening the issue to pull in these additional changes
        Hide
        Jessica Cheng Mallet added a comment -

        Updated the PR to have this be disabled by default.

        Show
        Jessica Cheng Mallet added a comment - Updated the PR to have this be disabled by default.
        Hide
        Timothy Potter added a comment -

        hmmm ... can you post the URL of the pull request here (or just post an updated patch to this ticket)? When I click on the 102 link above, it doesn't look like the latest code ...

        Show
        Timothy Potter added a comment - hmmm ... can you post the URL of the pull request here (or just post an updated patch to this ticket)? When I click on the 102 link above, it doesn't look like the latest code ...
        Hide
        Jessica Cheng Mallet added a comment -

        Hi Tim,

        It should be the latest. Do you see the default being changed for 1000 to -1 (https://github.com/apache/lucene-solr/pull/102/files)?

        Show
        Jessica Cheng Mallet added a comment - Hi Tim, It should be the latest. Do you see the default being changed for 1000 to -1 ( https://github.com/apache/lucene-solr/pull/102/files)?
        Hide
        Timothy Potter added a comment -

        Yes, see that now ... the patch link doesn't have the latest (which I was I looked at earlier) https://github.com/apache/lucene-solr/pull/102.patch

        Show
        Timothy Potter added a comment - Yes, see that now ... the patch link doesn't have the latest (which I was I looked at earlier) https://github.com/apache/lucene-solr/pull/102.patch
        Hide
        ASF subversion and git services added a comment -

        Commit 1634621 from Timothy Potter in branch 'dev/trunk'
        [ https://svn.apache.org/r1634621 ]

        SOLR-6650: disabled by default

        Show
        ASF subversion and git services added a comment - Commit 1634621 from Timothy Potter in branch 'dev/trunk' [ https://svn.apache.org/r1634621 ] SOLR-6650 : disabled by default
        Hide
        ASF subversion and git services added a comment -

        Commit 1634628 from Timothy Potter in branch 'dev/branches/branch_5x'
        [ https://svn.apache.org/r1634628 ]

        SOLR-6650: disabled by default

        Show
        ASF subversion and git services added a comment - Commit 1634628 from Timothy Potter in branch 'dev/branches/branch_5x' [ https://svn.apache.org/r1634628 ] SOLR-6650 : disabled by default
        Hide
        Anshum Gupta added a comment -

        Bulk close after 5.0 release.

        Show
        Anshum Gupta added a comment - Bulk close after 5.0 release.

          People

          • Assignee:
            Timothy Potter
            Reporter:
            Jessica Cheng Mallet
          • Votes:
            0 Vote for this issue
            Watchers:
            9 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development