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

[Srinivasan Raguraman]

Thanks for a quick reply.

With that performance figures while using logback, I agree this is not an
improvement.

The other best we can do is to have a convenience method in logback api
which accepts format, and args directly; in addition to the current api
which just accepts a msgStr.

Maybe this clutters api, with more methods. Considering improved performance
with logback, I think what we have is fine.

Regards,
Srini

>
>
> Message: 1
> Date: Thu, 23 Oct 2008 19:20:52 +0200
> From: Ceki Gulcu <listid at qos.ch>
> Subject: Re: [slf4j-user] Double Checking log level when logging with
>        log4j
> To: User list for the slf4j project <user at slf4j.org>
> Message-ID: <4900B274.9020309 at qos.ch>
> Content-Type: text/plain; charset=UTF-8; format=flowed
>
> 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
>
>
> ------------------------------
>
> _______________________________________________
> user mailing list
> user at slf4j.org
> http://www.slf4j.org/mailman/listinfo/user
>
> End of user Digest, Vol 26, Issue 12
> ************************************
>



-- 
Regards,
Srini
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://qos.ch/pipermail/slf4j-user/attachments/20081024/b937bccc/attachment.htm>