Solr
  1. Solr
  2. SOLR-2615

Have LogUpdateProcessor log each command (add, delete, ...) at debug/FINE level

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 3.4, 4.0-ALPHA
    • Component/s: update
    • Labels:
      None

      Description

      It would be great if the LogUpdateProcessor logged each command (add, delete, ...) at debug ("Fine") level. Presently it only logs a summary of 8 commands and it does so at the very end.

      The attached patch implements this.

      • I moved the LogUpdateProcessor ahead of RunUpdateProcessor so that the debug level log happens before Solr does anything with it. It should not affect the ordering of the existing summary log which happens at finish().
      • I changed UpdateRequestProcessor's static log variable to be an instance variable that uses the current class name. I think this makes much more sense since I want to be able to alter logging levels for a specific processor without doing it for all of them. This change did require me to tweak the factory's detection of the log level which avoids creating the LogUpdateProcessor.
      • There was an NPE bug in AddUpdateCommand.getPrintableId() in the event there is no schema unique field. I fixed that.

      You may notice I use SLF4J's nifty log.debug("message blah {} blah", var) syntax, which is both performant and concise as there's no point in guarding the debug message with an isDebugEnabled() since debug() will internally check this any way and there is no string concatenation if debug isn't enabled.

        Activity

        Hide
        Robert Muir added a comment -

        bulk close for 3.4

        Show
        Robert Muir added a comment - bulk close for 3.4
        Hide
        Yonik Seeley added a comment -

        Thanks for the tips David, hopefully when SOLR-2616 is committed we can fix this oddity.
        I've committed this patch to trunk and will backport.

        Show
        Yonik Seeley added a comment - Thanks for the tips David, hopefully when SOLR-2616 is committed we can fix this oddity. I've committed this patch to trunk and will backport.
        Hide
        David Smiley added a comment -

        Yonik,
        In JDK14 logging, the console logger has a default threshold of INFO. This makes the out-of-the-box use of Solr's logging admin page a little deceiving since it more detailed logging appears to do nothing. To quickly configure the threshold, look at SOLR-2616 which includes a logging config file with a commented threshold adjustment.

        Bill,
        I'm not sure about the log output of the DIH with threads=2; it would appear to be specific to the DIH based on your description and unrelated to the files involved in this patch.

        Show
        David Smiley added a comment - Yonik, In JDK14 logging, the console logger has a default threshold of INFO. This makes the out-of-the-box use of Solr's logging admin page a little deceiving since it more detailed logging appears to do nothing. To quickly configure the threshold, look at SOLR-2616 which includes a logging config file with a commented threshold adjustment. Bill, I'm not sure about the log output of the DIH with threads=2; it would appear to be specific to the DIH based on your description and unrelated to the files involved in this patch.
        Hide
        Bill Bell added a comment -

        If I use the DIH handler and turn on threads=2 I get more debugging output than if I don't use threads... It actually outputs EVERY add to Solr...

        Is this something that should be fixes here too?

        Show
        Bill Bell added a comment - If I use the DIH handler and turn on threads=2 I get more debugging output than if I don't use threads... It actually outputs EVERY add to Solr... Is this something that should be fixes here too?
        Hide
        Yonik Seeley added a comment -

        I was trying to test this patch (actually see what the new logging output looked like) and when trying to change the log level from http://localhost:8983/solr/admin/logging
        I can't seem to get anything above the "INFO" level. For example, changing "root" to SEVERE works to suppress messages at the INFO level, but changing it to "FINEST" doesn't get me anything more than "INFO". Any clues?

        Show
        Yonik Seeley added a comment - I was trying to test this patch (actually see what the new logging output looked like) and when trying to change the log level from http://localhost:8983/solr/admin/logging I can't seem to get anything above the "INFO" level. For example, changing "root" to SEVERE works to suppress messages at the INFO level, but changing it to "FINEST" doesn't get me anything more than "INFO". Any clues?
        Hide
        Yonik Seeley added a comment -

        Yonik, if I instead use a doDebug boolean flag initialized in the constructor, would that sufficiently satisfy you to commit this?

        Yep, I think so...

        Show
        Yonik Seeley added a comment - Yonik, if I instead use a doDebug boolean flag initialized in the constructor, would that sufficiently satisfy you to commit this? Yep, I think so...
        Hide
        David Smiley added a comment -

        Yonik, if I instead use a doDebug boolean flag initialized in the constructor, would that sufficiently satisfy you to commit this?

        Show
        David Smiley added a comment - Yonik, if I instead use a doDebug boolean flag initialized in the constructor, would that sufficiently satisfy you to commit this?
        Hide
        David Smiley added a comment -

        I traced the code from SLF4J thru JDK14 Logging and indeed there is a volatile-read at the end. I didn't see any hierarchy traversal. Isn't this a bit of a micro-optimization concern? These log calls are on a per-indexed document basis, not a per-term/token or low level detail basis. My personal code taste eschews verbosity.

        But I'm not going to fight it further, so if you still don't agree then I'm not going to object to any log-level cache & check modifications when you commit it.

        Show
        David Smiley added a comment - I traced the code from SLF4J thru JDK14 Logging and indeed there is a volatile-read at the end. I didn't see any hierarchy traversal. Isn't this a bit of a micro-optimization concern? These log calls are on a per-indexed document basis, not a per-term/token or low level detail basis. My personal code taste eschews verbosity. But I'm not going to fight it further, so if you still don't agree then I'm not going to object to any log-level cache & check modifications when you commit it.
        Hide
        Yonik Seeley added a comment -

        You may notice I use SLF4J's nifty log.debug("message blah {} blah", var) syntax, which is both performant and concise as there's no point in guarding the debug message with an isDebugEnabled() since debug() will internally check this any way and there is no string concatenation if debug isn't enabled.

        I think there is still a point to caching isDebugEnabled() though. The implementation most likely involves checking volatile variables, and can involve checking a hierarchy of loggers. I assume the cost may be different for different logging implementations too. Better to just cache if you can and not worry about it.

        Show
        Yonik Seeley added a comment - You may notice I use SLF4J's nifty log.debug("message blah {} blah", var) syntax, which is both performant and concise as there's no point in guarding the debug message with an isDebugEnabled() since debug() will internally check this any way and there is no string concatenation if debug isn't enabled. I think there is still a point to caching isDebugEnabled() though. The implementation most likely involves checking volatile variables, and can involve checking a hierarchy of loggers. I assume the cost may be different for different logging implementations too. Better to just cache if you can and not worry about it.

          People

          • Assignee:
            Yonik Seeley
            Reporter:
            David Smiley
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development