[slf4j-dev] [Bug 204] New: Android only: 'format' being called for log statements at all log levels.

[bugzilla-daemon at pixie.qos.ch]

http://bugzilla.slf4j.org/show_bug.cgi?id=204

           Summary: Android only: 'format' being called for log statements
                    at all log levels.
           Product: SLF4J
           Version: unspecified
          Platform: Other
        OS/Version: other
            Status: NEW
          Severity: major
          Priority: P2
         Component: slf4j-android
        AssignedTo: slf4j-dev at qos.ch
        ReportedBy: darrin501 at gmail.com


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


-- 
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.