[slf4j-user] Formatted logs and benchmarks

[Sebastien Pennec]

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/