Solr
  1. Solr
  2. SOLR-4547

Commit logging - move index filenames to DEBUG.

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 4.1
    • Fix Version/s: 4.4, Trunk
    • Component/s: update
    • Labels:
      None

      Description

      When an index commit is done (at least with MMap/NRT, haven't checked other Directory implementations), all of the filenames in the index are logged three times at INFO. I think the information has value to someone if they are debugging, but not to most users.

      I propose that we move this part of the log to DEBUG and provide text that allows the person/program viewing the log to link the smaller INFO log entry with the new one, probably the directory path.

      1. SOLR-4547.patch
        5 kB
        Shawn Heisey
      2. SOLR-4547.patch
        5 kB
        Hoss Man
      3. SOLR-4547.patch
        5 kB
        Shawn Heisey
      4. SOLR-4547.patch
        5 kB
        Shawn Heisey
      5. SOLR-4547.patch
        4 kB
        Shawn Heisey
      6. SOLR-4547.patch
        5 kB
        Shawn Heisey
      7. solr-4547-insanity.txt
        23 kB
        Shawn Heisey

        Activity

        Hide
        Shawn Heisey added a comment -

        Right this minute I don't have any cycles, but I plan to look at this soon and try to cook up a starter patch.

        Show
        Shawn Heisey added a comment - Right this minute I don't have any cycles, but I plan to look at this soon and try to cook up a starter patch.
        Hide
        Shawn Heisey added a comment -

        DOS format text file showing the log results of one commit. All the index filenames are listed three times.

        As far as I can tell, my SolrJ code is only sending one commit, though I do see commits:num=2 in the log.

        Show
        Shawn Heisey added a comment - DOS format text file showing the log results of one commit. All the index filenames are listed three times. As far as I can tell, my SolrJ code is only sending one commit, though I do see commits:num=2 in the log.
        Hide
        Hoss Man added a comment -

        I think the crux of the issue is that some objects are kind of verbose in their toString, so when they are referred to in the log messages ... boom.

        -0 on making these toString messages less verbose, because i do think those are handy in some cases, but +1 to making hte INFO messages less verbose (probably by eliminating these objects from them messages) and adding subsequent debug messages that have all the details

        Show
        Hoss Man added a comment - I think the crux of the issue is that some objects are kind of verbose in their toString, so when they are referred to in the log messages ... boom. -0 on making these toString messages less verbose, because i do think those are handy in some cases, but +1 to making hte INFO messages less verbose (probably by eliminating these objects from them messages) and adding subsequent debug messages that have all the details
        Hide
        Shawn Heisey added a comment -

        -0 on making these toString messages less verbose, because i do think those are handy in some cases, but +1 to making hte INFO messages less verbose (probably by eliminating these objects from them messages) and adding subsequent debug messages that have all the details

        I will stick to these constraints when I start poking around.

        Show
        Shawn Heisey added a comment - -0 on making these toString messages less verbose, because i do think those are handy in some cases, but +1 to making hte INFO messages less verbose (probably by eliminating these objects from them messages) and adding subsequent debug messages that have all the details I will stick to these constraints when I start poking around.
        Hide
        Shawn Heisey added a comment -

        Patch for this issue. I did rename and modify a couple of existing methods, but I did not have to touch any common methods like toString().

        I do realize that this is sticking to the letter of Hoss' advice rather than the spirit, so I hope the patch is clean.

        I included a CHANGES.txt update that assumes Hoss will be the committer.

        Everything compiles with the patch, but I still have to run tests and precommit, plus give it an actual test run to see what I get.

        Show
        Shawn Heisey added a comment - Patch for this issue. I did rename and modify a couple of existing methods, but I did not have to touch any common methods like toString(). I do realize that this is sticking to the letter of Hoss' advice rather than the spirit, so I hope the patch is clean. I included a CHANGES.txt update that assumes Hoss will be the committer. Everything compiles with the patch, but I still have to run tests and precommit, plus give it an actual test run to see what I get.
        Hide
        Shawn Heisey added a comment -

        Patch is against 4.x, but I will make sure trunk is covered too.

        Show
        Shawn Heisey added a comment - Patch is against 4.x, but I will make sure trunk is covered too.
        Hide
        Shawn Heisey added a comment -

        Patch does apply cleanly to trunk, the CHANGES.txt hunk is offset by 18 lines. Solr tests on 4.x pass. The resulting logs look good to me at INFO and DEBUG.

        I did find some other verbose logs. These dump all the segments, but not all the individual filenames. The toString() method is involved here, so fixing these will require more thought. Perhaps a toStringTerse() or similar method? Should that be in a separate patch/issue?

        INFO  - 2013-03-13 15:50:09.560; org.apache.solr.core.QuerySenderListener; QuerySenderListener sending requests to Searcher@7c881bd6 main{StandardDirectoryReader(segments_d3c:40659 _d2i(4.3):C338038/27 _d2j(4.3):C61 _d2k(4.3):C47/2 _d2l(4.3):C66 _d2m(4.3):C56 _d2n(4.3):C63 _d2o(4.3):C38/1 _d2p(4.3):C36/1 _d2q(4.3):C46 _d2r(4.3):C59 _d2s(4.3):C46/1 _d2t(4.3):C44 _d2u(4.3):C49 _d2v(4.3):C35 _d2w(4.3):C40 _d2x(4.3):C42/1 _d2y(4.3):C52 _d2z(4.3):C48 _d30(4.3):C34 _d31(4.3):C39/1 _d32(4.3):C61 _d33(4.3):C55 _d34(4.3):C38/1 _d35(4.3):C56 _d36(4.3):C54 _d37(4.3):C61/1 _d38(4.3):C32 _d39(4.3):C55/1 _d3a(4.3):C55 _d3b(4.3):C30 _d3c(4.3):C53/1 _d3d(4.3):C49/1 _d3e(4.3):C35/1 _d3f(4.3):C63 _d3g(4.3):C68 _d3h(4.3):C54 _d3i(4.3):C31/1 _d3j(4.3):C75 _d3k(4.3):C71 _d3l(4.3):C31)}
        
        INFO  - 2013-03-13 15:50:09.563; org.apache.solr.core.SolrCore; [inclive] Registered new searcher Searcher@7c881bd6 main{StandardDirectoryReader(segments_d3c:40659 _d2i(4.3):C338038/27 _d2j(4.3):C61 _d2k(4.3):C47/2 _d2l(4.3):C66 _d2m(4.3):C56 _d2n(4.3):C63 _d2o(4.3):C38/1 _d2p(4.3):C36/1 _d2q(4.3):C46 _d2r(4.3):C59 _d2s(4.3):C46/1 _d2t(4.3):C44 _d2u(4.3):C49 _d2v(4.3):C35 _d2w(4.3):C40 _d2x(4.3):C42/1 _d2y(4.3):C52 _d2z(4.3):C48 _d30(4.3):C34 _d31(4.3):C39/1 _d32(4.3):C61 _d33(4.3):C55 _d34(4.3):C38/1 _d35(4.3):C56 _d36(4.3):C54 _d37(4.3):C61/1 _d38(4.3):C32 _d39(4.3):C55/1 _d3a(4.3):C55 _d3b(4.3):C30 _d3c(4.3):C53/1 _d3d(4.3):C49/1 _d3e(4.3):C35/1 _d3f(4.3):C63 _d3g(4.3):C68 _d3h(4.3):C54 _d3i(4.3):C31/1 _d3j(4.3):C75 _d3k(4.3):C71 _d3l(4.3):C31)}
        
        Show
        Shawn Heisey added a comment - Patch does apply cleanly to trunk, the CHANGES.txt hunk is offset by 18 lines. Solr tests on 4.x pass. The resulting logs look good to me at INFO and DEBUG. I did find some other verbose logs. These dump all the segments, but not all the individual filenames. The toString() method is involved here, so fixing these will require more thought. Perhaps a toStringTerse() or similar method? Should that be in a separate patch/issue? INFO - 2013-03-13 15:50:09.560; org.apache.solr.core.QuerySenderListener; QuerySenderListener sending requests to Searcher@7c881bd6 main{StandardDirectoryReader(segments_d3c:40659 _d2i(4.3):C338038/27 _d2j(4.3):C61 _d2k(4.3):C47/2 _d2l(4.3):C66 _d2m(4.3):C56 _d2n(4.3):C63 _d2o(4.3):C38/1 _d2p(4.3):C36/1 _d2q(4.3):C46 _d2r(4.3):C59 _d2s(4.3):C46/1 _d2t(4.3):C44 _d2u(4.3):C49 _d2v(4.3):C35 _d2w(4.3):C40 _d2x(4.3):C42/1 _d2y(4.3):C52 _d2z(4.3):C48 _d30(4.3):C34 _d31(4.3):C39/1 _d32(4.3):C61 _d33(4.3):C55 _d34(4.3):C38/1 _d35(4.3):C56 _d36(4.3):C54 _d37(4.3):C61/1 _d38(4.3):C32 _d39(4.3):C55/1 _d3a(4.3):C55 _d3b(4.3):C30 _d3c(4.3):C53/1 _d3d(4.3):C49/1 _d3e(4.3):C35/1 _d3f(4.3):C63 _d3g(4.3):C68 _d3h(4.3):C54 _d3i(4.3):C31/1 _d3j(4.3):C75 _d3k(4.3):C71 _d3l(4.3):C31)} INFO - 2013-03-13 15:50:09.563; org.apache.solr.core.SolrCore; [inclive] Registered new searcher Searcher@7c881bd6 main{StandardDirectoryReader(segments_d3c:40659 _d2i(4.3):C338038/27 _d2j(4.3):C61 _d2k(4.3):C47/2 _d2l(4.3):C66 _d2m(4.3):C56 _d2n(4.3):C63 _d2o(4.3):C38/1 _d2p(4.3):C36/1 _d2q(4.3):C46 _d2r(4.3):C59 _d2s(4.3):C46/1 _d2t(4.3):C44 _d2u(4.3):C49 _d2v(4.3):C35 _d2w(4.3):C40 _d2x(4.3):C42/1 _d2y(4.3):C52 _d2z(4.3):C48 _d30(4.3):C34 _d31(4.3):C39/1 _d32(4.3):C61 _d33(4.3):C55 _d34(4.3):C38/1 _d35(4.3):C56 _d36(4.3):C54 _d37(4.3):C61/1 _d38(4.3):C32 _d39(4.3):C55/1 _d3a(4.3):C55 _d3b(4.3):C30 _d3c(4.3):C53/1 _d3d(4.3):C49/1 _d3e(4.3):C35/1 _d3f(4.3):C63 _d3g(4.3):C68 _d3h(4.3):C54 _d3i(4.3):C31/1 _d3j(4.3):C75 _d3k(4.3):C71 _d3l(4.3):C31)}
        Hide
        Shawn Heisey added a comment -

        I'd like to commit and close this, but not without making sure that it's reviewed.

        This comment is part of an effort to close old issues that I have reported. Search tag: elyograg2013springclean

        Show
        Shawn Heisey added a comment - I'd like to commit and close this, but not without making sure that it's reviewed. This comment is part of an effort to close old issues that I have reported. Search tag: elyograg2013springclean
        Hide
        Hoss Man added a comment -

        Shawn: my previous comment was based on the mistaken impression that these log messages were leveraging the toString() of the IndexCommit and List<IndexCommit> objects ... looking at your patch, i realize now that these ugly "str()" methods were doing the work. sorry for the confusion

        specific concerns i have about your patch...

        1) in the case of logging a List<IndexCommit>, the existing code does a single INFO message with the details of each commit, but in your patch each commit gets it's own log message (x2, INFO and DEBUG) because of how you've got logCommits() looping and delegating to logCommit(). This seems like a bad idea since in the case of multiple SolrCores these can easily get interleaved and hard to coalesce.

        2) both the existing str functions and your new logCommit/logCommits functions suffer from the problem of doing a lot of String building even in the case where hte logging level is so high the messages will be ignored.

        3) i'm not a fan of the the dual INFO/DEBUG logging going on inside of logCommit/logCommits ... i can't really explain it well, but it strikes me as being too "hidden" from the flow of the methods that call it, i'd rather see the log.info and log.debug calls inside each method where it happens so it's more obvious we are infact logging two different ways there.

        My suggestion for dealing with this would probably be...

        a) introduce some private static inner classes that are really cheap to construct and can wrap a List<IndexCommit> and have toString() methods that render out all the details we want
        b) use these new cheap classes directly in info & debug calls that leverage placeholder markers

        something along the lines of (not fully thought through)...

        log.info("SolrDeletionPolicy.onCommit: commits: {}", new CommitsLoggingInfo(commits));
        log.info("SolrDeletionPolicy.onCommit: commits: {}", new CommitsLoggingDebug(commits));
        ...
        private static class CommitsLoggingInfo {
          ...
          public final String toString() {
            StringBuilder sb;
            ...
            for (IndexCommit c : commits) {
              appendDetails(sb, c));
            }
            ...
            return sb.toString();
          }
          protected void appendDetails(StringBuilder s, IndexCommit c) {
            // add summary details, ie: not all the freaking files.
          }
        }
        private static class CommitsLoggingDebug extends CommitsLoggingInfo {
          ...
          protected void appendDetails(StringBuilder s, IndexCommit c) {
            super.appendDetails(s, c);
            s.append(c.getFileNames());
          }
        }
        

        (of course, another way to go would be to sprinkly a bunch of "if (log.isDebugEnabled())" and "if (log.isInfoEnabled())" arround your existing patch, but that would still leave concern #1)

        Show
        Hoss Man added a comment - Shawn: my previous comment was based on the mistaken impression that these log messages were leveraging the toString() of the IndexCommit and List<IndexCommit> objects ... looking at your patch, i realize now that these ugly "str()" methods were doing the work. sorry for the confusion specific concerns i have about your patch... 1) in the case of logging a List<IndexCommit>, the existing code does a single INFO message with the details of each commit, but in your patch each commit gets it's own log message (x2, INFO and DEBUG) because of how you've got logCommits() looping and delegating to logCommit(). This seems like a bad idea since in the case of multiple SolrCores these can easily get interleaved and hard to coalesce. 2) both the existing str functions and your new logCommit/logCommits functions suffer from the problem of doing a lot of String building even in the case where hte logging level is so high the messages will be ignored. 3) i'm not a fan of the the dual INFO/DEBUG logging going on inside of logCommit/logCommits ... i can't really explain it well, but it strikes me as being too "hidden" from the flow of the methods that call it, i'd rather see the log.info and log.debug calls inside each method where it happens so it's more obvious we are infact logging two different ways there. My suggestion for dealing with this would probably be... a) introduce some private static inner classes that are really cheap to construct and can wrap a List<IndexCommit> and have toString() methods that render out all the details we want b) use these new cheap classes directly in info & debug calls that leverage placeholder markers something along the lines of (not fully thought through)... log.info("SolrDeletionPolicy.onCommit: commits: {}", new CommitsLoggingInfo(commits)); log.info("SolrDeletionPolicy.onCommit: commits: {}", new CommitsLoggingDebug(commits)); ... private static class CommitsLoggingInfo { ... public final String toString() { StringBuilder sb; ... for (IndexCommit c : commits) { appendDetails(sb, c)); } ... return sb.toString(); } protected void appendDetails(StringBuilder s, IndexCommit c) { // add summary details, ie: not all the freaking files. } } private static class CommitsLoggingDebug extends CommitsLoggingInfo { ... protected void appendDetails(StringBuilder s, IndexCommit c) { super.appendDetails(s, c); s.append(c.getFileNames()); } } (of course, another way to go would be to sprinkly a bunch of "if (log.isDebugEnabled())" and "if (log.isInfoEnabled())" arround your existing patch, but that would still leave concern #1)
        Hide
        Shawn Heisey added a comment -

        New patch using recommendations from Hoss. It has not been tested yet. I am working on that.

        Show
        Shawn Heisey added a comment - New patch using recommendations from Hoss. It has not been tested yet. I am working on that.
        Hide
        Shawn Heisey added a comment -

        Updated patch. The filenames were being logged AGAIN in the updateCommits method. This method is only called from places that have just done logging that includes the filenames at DEBUG, so I just removed the filenames from that log entry, which also removed a try/catch block.

        Show
        Shawn Heisey added a comment - Updated patch. The filenames were being logged AGAIN in the updateCommits method. This method is only called from places that have just done logging that includes the filenames at DEBUG, so I just removed the filenames from that log entry, which also removed a try/catch block.
        Hide
        Shawn Heisey added a comment -

        Another updated patch. Added comments.

        Show
        Shawn Heisey added a comment - Another updated patch. Added comments.
        Hide
        Shawn Heisey added a comment -

        Patch appears to be doing the right thing. Precommit passes. I have run into test failures, need to take a closer look to see if they could be caused by this change.

        Show
        Shawn Heisey added a comment - Patch appears to be doing the right thing. Precommit passes. I have run into test failures, need to take a closer look to see if they could be caused by this change.
        Hide
        Hoss Man added a comment -

        Shawn: minor tweaks to your patch...

        • add the "num=" of commits back to hte log message
        • fixed the placement of hte curly braces so they wrap all the details of the commit (including hte filenames)
        Show
        Hoss Man added a comment - Shawn: minor tweaks to your patch... add the "num=" of commits back to hte log message fixed the placement of hte curly braces so they wrap all the details of the commit (including hte filenames)
        Hide
        Shawn Heisey added a comment -

        I've been testing with the updated patch Hoss included. I've satisfied myself that the failures I'm seeing are existing failures that I've seen in email from jenkins. Does anyone want to take a look before I commit this evening (my timezone is MDT, UTC-6)?

        Show
        Shawn Heisey added a comment - I've been testing with the updated patch Hoss included. I've satisfied myself that the failures I'm seeing are existing failures that I've seen in email from jenkins. Does anyone want to take a look before I commit this evening (my timezone is MDT, UTC-6)?
        Hide
        Shawn Heisey added a comment -

        The CHANGES.txt entry is not correct, unless Simon Willnauer is OK with including this in the 4.3 release. If necessary, I will fix that just before I commit.

        Show
        Shawn Heisey added a comment - The CHANGES.txt entry is not correct, unless Simon Willnauer is OK with including this in the 4.3 release. If necessary, I will fix that just before I commit.
        Hide
        Shawn Heisey added a comment -

        New patch, will commit momentarily. Moves the CHANGES.txt entry to 4.4.0 and makes a minor clarification in the updateCommits log message.

        Show
        Shawn Heisey added a comment - New patch, will commit momentarily. Moves the CHANGES.txt entry to 4.4.0 and makes a minor clarification in the updateCommits log message.
        Hide
        Commit Tag Bot added a comment -

        [trunk commit] elyograg
        http://svn.apache.org/viewvc?view=revision&revision=1471105

        SOLR-4547: Move logging of filenames on commit from INFO to DEBUG.

        Show
        Commit Tag Bot added a comment - [trunk commit] elyograg http://svn.apache.org/viewvc?view=revision&revision=1471105 SOLR-4547 : Move logging of filenames on commit from INFO to DEBUG.
        Hide
        Commit Tag Bot added a comment -

        [branch_4x commit] elyograg
        http://svn.apache.org/viewvc?view=revision&revision=1471106

        SOLR-4547: Move logging of filenames on commit from INFO to DEBUG. (merge trunk r1471105)

        Show
        Commit Tag Bot added a comment - [branch_4x commit] elyograg http://svn.apache.org/viewvc?view=revision&revision=1471106 SOLR-4547 : Move logging of filenames on commit from INFO to DEBUG. (merge trunk r1471105)
        Hide
        Steve Rowe added a comment -

        Bulk close resolved 4.4 issues

        Show
        Steve Rowe added a comment - Bulk close resolved 4.4 issues

          People

          • Assignee:
            Shawn Heisey
            Reporter:
            Shawn Heisey
          • Votes:
            1 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development