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" <[EMAIL PROTECTED]> > To: "User list for the slf4j project" <[email protected]> > 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" <[EMAIL PROTECTED]> >> To: "User list for the slf4j project" <[email protected]> >> 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 >>> [email protected] >>> http://www.slf4j.org/mailman/listinfo/user >>> > -- Sébastien Pennec [EMAIL PROTECTED] Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch/ _______________________________________________ user mailing list [email protected] http://www.slf4j.org/mailman/listinfo/user
