Uploaded image for project: 'SLF4J'
  1. SLF4J
  2. SLF4J-195

Android only: 'format' being called for log statements at all log levels.

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Unresolved
    • None
    • None
    • slf4j-android
    • None
    • Operating System: other
      Platform: Other

    Description

      I'm on android and seeing some disturbing behavior - that the fully formatted log string is being calculated for every call to the various Logger methods - even if the log level will not cause the formatted message to be printed. The fact that slf4j doesn't generally do this was one of my primary motivators for going with slf4j so I hope it'll be fixed soon... here are the details and the fix:

      I stumbled across this as I was trying to do some optimization under android. I was finding that there were extraneous calls to 'toString'. For example this line of code is evaluating 'toString' on 'currentObject':

      logger.trace(" Finished Processing : {}", currentObject);

      The first thing I checked is Android's log level:
      Log.isLoggable(name, Log.DEBUG) = false
      Log.isLoggable(name, Log.INFO) = true
      ... meaning that Android is set to log at 'Log.INFO' level. But since I wasn't seeing these logs in Android's logcat I was pretty sure this was the case.

      Next, I grabbed the source and tracked this issue to this code in the 1.6.1 release candidate for Android (though it was a problem at least as far back to 1.5.8 so it's probably always been a problem):

      /* @see org.slf4j.Logger#trace(java.lang.String, java.lang.Object) */
      public void trace(final String format, final Object param1)

      { Log.v(name, format(format, param1, null)); }

      The problem is that in the above statement 'format' will ALWAYS BE EVALUATED and in turn will always cause toString to be evaluated even if the result will not be used. To fix this each of the various logger methods will need to be enclosed in a Log.isLoggable conditionals... so the fix for the trace method above is something like this:

      /* @see org.slf4j.Logger#trace(java.lang.String, java.lang.Object) */
      public void trace(final String format, final Object param1)
      {
      if (Log.isLoggable(name, Log.VERBOSE))

      { Log.v(name, format(format, param1, null)); }

      }

      As painful as it is - the workaround is of course to surround each time expensive log operations with the relevant test. For the example above I have to use this:

      if (logger.isTraceEnabled()) {
      logger.trace("populateWebListView with url = '{}'", ami);
      }

      I see this as an easy fix - and I'm hoping we can see it in the 1.6.1 release... I may put together a patch to resolve this locally soon and if I do - I'll add it here.

      Thanks in advance,
      -Darrin

      Attachments

        Activity

          People

            slf4j-dev SLF4J developers list
            darrin501@gmail.com darrin
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

              Created:
              Updated: