[slf4j-user] Formatted logs and benchmarks

[Sebastien Pennec]

Hello Martin,

The first run changes the figures quite a bit. If you add a first unmeasured run, 
your results will probably be changed in a rather visible manner.

Also, by looking at your test class, you seem to measure the time it takes to log, 
not to format only. In your FormattedLogger class, the debugf() method redirects the 
logging to a usual debug method. Depending on the components that are called after 
this method, the results may vary in an important fashion, given that the StopWatch 
is started and stopped at the beginning and the end of the for loop.

Another thing that might be important here is the time it takes *not to log*. Quite 
often, the logger.xxxx() method will not result in an actual logging message output 
somewhere. For example, a call to the debug() method when a filter denies all events 
whose level is INFO and below will not produce any output. In that case, the use of a 
String.format() method before the actual call to the logger method will cost the time 
of formatting the message even if the request is not processed any further.

Admittedly, the advanced formatting provided by String.format() is certainly not used 
by many people in such a situation.

Hope this helps,

Sébastien

Martin Gilday wrote:
> Hi Sébastien,
> 
> Thank you for your detailed reply.  For my test[1] I used the StopWatch
> class from the Spring framework.  I then had a loop which ran 1000 log
> calls.  I didn't have a second run as you have, but I think I should add
> it to mine as well.  I founda a similar increase in the time taken. 
> This suggests that String.format is probably too slow to be used in a
> production system.  The advanced formatting it provides is possibly not
> needed in most cases.
> 
> [1]
> http://www.martingilday.org/svn/repos/FormattedLogger/trunk/src/test/java/org/martingilday/formattedLogger/FormattedLoggerUnitTest.java
> 
> Regards,
> Martin
> 
> 
> ----- Original message -----
> From: "Sebastien Pennec" <sebastien at qos.ch>
> To: "User list for the slf4j project" <user at slf4j.org>
> Date: Thu, 18 Jan 2007 18:54:10 +0100
> Subject: Re: [slf4j-user] Formatted logs and benchmarks
> 
> Hello Martin,
> 
> I've run some tests, comparing org.slf4j.impl.MessageFormatter
> and String.format() with java.util.Formatter.
> 
> Every test was run in a 10'000 loop. The figures are averages of the
> formatting 
> duration measured 10'000 times. Also, every test looped twice not to be
> influenced by 
> the just in time compiler. Only the second time is measured. I measured
> only the time 
> it took to format the message, by using Long variables that were fed
> with 
> System.nanoTime() right before and after the call to the formatting
> method.
> 
> Here are the results:
> 
> MessageFormatter.arrayFormat(String message, Object[] argArray);
> 1 param: 1318 nanos on average.
> 2 params: 1724 nanos on average.
> 3 params: 2150 nanos on average.
> 
> Arguments for String.format(String format, Object ... args):
> %d int
> %s String
> %tc Date, Calender or millis
> 
> No formatting:
> 1 param: %d: 9943 nanos on average
> 2 params: %d: 12500 nanos on average
> 3 params: %d: 14993 nanos on average
> 
> 1 param %s: 8588 nanos on average
> 2 params %s: 11383 nanos on average
> 3 params %s: 13164 nanos on average
> 
> 2 params: %s and %d: 12747 nanos on average
> 2 params: %s and %tc: 26650 nanos on average with a Date object
> 
> With formatting:
> 1 param: %,.2f 22842 nanos on average
> 
> Empty array:
> MessageFormatter: 1598 on average
> String.format: 8930 on average
> 
> I ran each tests several times, and the values where always rather close
> to the ones 
> above. I didn't expect them to be equal each time, since we're measuring
> nanoseconds...
> 
> These values give a clear advantage to the MessageFormatter.
> 
> As far as I know, there is no official way of recording this kind of
> benchmarks on 
> the SLF4J project. The method I used might not be the best one, although
> I think it 
> gives a rather precise result.
> 
> How did you run your tests? Did you find results that are close to the
> ones above?
> 
> Cheers,
> 
> Sébastien
> 
> 
> Martin Gilday wrote:
>> There has previously been a discussion on this mailing list about the
>> possibility of adding varargs to slf4j.  Since then I have made an
>> attempt to tidy up some of my projects by writing a wrapper for the
>> log4j Logger class.[1][2]
>> As part of this I took what someone suggested on the mailing list of
>> using java.util.Formatter for building up the log messages inside the
>> log call.  In slf4j a similar substitution into the log message takes
>> place.  I have found it reasonably difficult to achieve a consistant
>> benchmark of the effect of this String.format call, ranging from almost
>> equal to over 3 times slower.  
>>
>> Are there any existing benchmarks on the effect of your substitutions in
>> slf4j, or any effective ways of recording them?
>>
>> Thank you for your time,
>> Martin Gilday
>>
>> [1] http://www.martingilday.org/updates/Formatted+Logger
>> [2]
>> http://www.martingilday.org/svn/repos/FormattedLogger/trunk/src/main/java/org/martingilday/formattedLogger/FormattedLogger.java
>> _______________________________________________
>> user mailing list
>> user at slf4j.org
>> http://www.slf4j.org/mailman/listinfo/user
>>
> 

-- 
Sébastien Pennec
sebastien at qos.ch

Logback: The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch/