[slf4j-user] Formatted logs and benchmarks

[Martin Gilday]

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