[slf4j-user] Double Checking log level when logging with log4j

[Srinivasan Raguraman]

When we are using log4j as underlying logger, sl4j actually does double
checking of 'isErrorEnabled()' for every Log, if that LEVEL is enabled.



public void error(String format, Object arg) {

    if (logger.isEnabledFor(Level.ERROR)) {

      String msgStr = MessageFormatter.format(format, arg);

      logger.log(FQCN, Level.ERROR, msgStr, null);

    }

  }



This is because, once we pass the message to log4j



logger.log(FQCN, Level.ERROR, msgStr, null);





log4j library again does the check isErrorEnabled() before the actual
logging. This code is the same as the isErrorEnabled check.



*public*

  *void* log(String callerFQCN, Priority level, Object message, Throwable t)
{

    *if*(repository.isDisabled(level.level)) {

      *return*;

    }

    *if*(level.isGreaterOrEqual(*this*.getEffectiveLevel())) {

      forcedLog(callerFQCN, level, message, t);

    }

  }



To avoid this double checking why don't we wrap the format, arguments inside
an Object, and use log4j renderer for that object to generate the final
message? Or even override toString() method of that object to return the
formatted message.





Instead of this:



logger.log(FQCN, Level.ERROR, msgStr, null);



It could be something like:



public void error(String format, Object arg) {

      logger.log(FQCN, Level.ERROR, new InterpolatedMessage(formate,
arg), null);

}





Where



public final class InterpolatedMessage {



            private final String format;

            private final Object arg;



            public InterpolatedMessage(final String format, final Object
arg) {

                        this.format = format;

                        this.arg = arg;

            }



            @Override

            public String toString() {

                        return MessageFormatter.format(this.format,
this.arg);

            }



}





As you see, this will



   - Delay the message construction unless it really going to be used.
   - Avoid double checking with if LevelEnabled, when that level is actually
   enabled



The negatives are



   - Creation of InterpolatedMessage Object for every log statement – since
   the object is just going to hold the reference of the format and args, this
   may not be expensive?
      - as it avoids construction of log message
   - Using toString() method of interpolated message is a trick!  - Yes, for
   that we can otherwise add log4j renderer for objects of InterpolatedMessage
   type.





I just gave my thoughts here; let me know what you guys think. I could
follow up or help to verify if this will really gives us performance
advantage.



Regards,

Srini
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://qos.ch/pipermail/slf4j-user/attachments/20081023/ba3bc2bf/attachment.htm>