[slf4j-user] Formatted logs and benchmarks

[Sebastien Pennec]

Martin,

Sorry for the misreading of your code.

Measuring a complete log is actually a good idea. I was pointing this because you 
mentionned that you had trouble obtaining consistent results, which I had not using 
my code. This and the first "dry" run were the two main differences between your code 
and mine.

Cheers,

Sébastien

Martin Gilday wrote:
> Sébastien,
> 
> I was trying to see how much slower a complete log would be including
> the formatting.  What you say about debugf is not fully correct.  Inside
> the debugf method I have an isDebugEnabled check before any formatting
> takes place.
> 
> Martin.
> 
> 
> ----- Original message -----
> From: "Sebastien Pennec" <sebastien at qos.ch>
> To: "User list for the slf4j project" <user at slf4j.org>
> Date: Fri, 19 Jan 2007 10:45:43 +0100
> Subject: Re: [slf4j-user] Formatted logs and benchmarks
> 
> 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/