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

[Ceki Gulcu]

Hello Srinivasan,

The logger.isEnabledFor(...) operation takes about 25 nanoseconds with log4j and
about 10 nanoseconds with logback. new InterpolatedMessage probably takes longer 
than that..

Srinivasan Raguraman wrote:
> 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?
>           o 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
> 
> 
> ------------------------------------------------------------------------
> 
> _______________________________________________
> user mailing list
> user at slf4j.org
> http://www.slf4j.org/mailman/listinfo/user

-- 
Ceki Gülcü
Logback: The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch