Try changing your code to loop 10,000 times or so before you start the real
test. This will make sure the JVMs are warmed up and all systems are
configured properly. That should drop the difference even more in theory.
On Fri, 29 Mar 2002 21:48, Ceki Gülcü wrote:
> The interesting case is of course measuring performance when logging is
> turned off. Here is a little experiment.
>
> My CLASSPATH:
>
> CLASSPATH=.;/java/jdk1.3.1/jre/lib/rt.jar;/home/cgu/ASF/jakarta-log4j-1.2be
>ta4/dist/lib/log4j-1.2beta4.jar;commons-logging-1.0/commons-logging.jar
>
>
> I have written two short programs that log in a loop. One called
> Direct.java log that directly uses log4j. The other, called Indirect.java,
> logs indirectly using commons-logging.
>
> -----------------------------------------------------
> import org.apache.log4j.Logger;
> import org.apache.log4j.Level;
>
> public class Direct {
>
> public static void main(String args[]) {
>
> if(args.length != 1) {
> System.err.println("Usage: java Direct runLength\n" +
> " where runLength is an int representing the run length of
> loops\n"+ "I suggest a runLength of at least 100'000.");
> }
>
> int runLength = Integer.parseInt(args[0]);
>
> Logger logger = Logger.getLogger("bandicoot");
>
> // disable all logging below INFO.
> logger.getLoggerRepository().setThreshold(Level.INFO);
>
> long begin = System.currentTimeMillis();
> for(int i = 0; i < runLength; i++) {
> if(logger.isDebugEnabled()) {
> logger.debug("This is message "+ i);
> }
> }
>
> long end = System.currentTimeMillis();
> double totalMicros = (end-begin)*1000.0;
> System.out.println("Average time: "+totalMicros/runLength+" in
> microseconds.");
> }
> }
> ---------------------------------------------------------------
>
> Here is Indirect.java
>
> ---------------------------------------------------------------
> import org.apache.commons.logging.LogFactory;
> import org.apache.commons.logging.Log;
>
> public class Indirect {
>
> public static void main(String args[]) {
>
> if(args.length != 1) {
> System.err.println("Usage: java Indirect runLength\n" +
> " where runLength is an int representing the run length of
> loops\n"+ "I suggest a runLength of at least 100'000.");
> }
>
> int runLength = Integer.parseInt(args[0]);
>
> Log log = LogFactory.getFactory().getInstance("bandicoot");
>
> // notice that in this example there is no code to set the level
> // of the repository.
>
> long begin = System.currentTimeMillis();
> for(int i = 0; i < runLength; i++) {
> if(log.isDebugEnabled()) {
> log.debug("This is message "+ i);
> }
> }
>
> long end = System.currentTimeMillis();
> double totalMicros = (end-begin)*1000.0;
> System.out.println("Average time: "+totalMicros/runLength+" in
> microseconds.");
> }
> }
> ---------------------------------------------------------------
>
> Running Direct I get:
>
> ~/> java Direct 100000000
> Average time: 0.01903 in microseconds.
>
> Running Indirect I get:
>
> ~/> java Indirect 100000000
> log4j:WARN No appenders could be found for logger (bandicoot).
> log4j:WARN Please initialize the log4j system properly.
> Average time: 1.15155 in microseconds.
>
> That's a factor of 60 and not in percents!
>
> Of course, I cheated because Indirect.java does not configure
> the repository threshold.
>
> Placing a file called "log4j.properties" with the following contents
>
> log4j.threshold=WARN
> log4j.debug=true
>
> in the *current* directory (remember I have '.' as the first entry in
> my CLASSPATH) and running Indirect java I get:
>
> ~/> java Indirect 100000000
> log4j: Parsing threshold string [WARN]
> log4j: Could not find root logger information. Is this OK?
> log4j: Finished configuring.
> Average time: 0.02854 in microseconds.
>
> That's an increase of 50, but in percents this time. Interestingly,
> enough the results are very similar in JDK 1.2.2; the numbers change
> but the proportions don't.
>
> Moral of the story? You are essentially right if the user knows what
> she is doing.
>
> It would be interesting to see if changing
>
> private Category category = null;
>
> to
>
> final private Category category;
>
> in org.apache.commons.logging.impl.Log4JCategoryLog would
> change anything. It would be a nice experiment.
>
> At 12:46 29.03.2002 +1100, you wrote:
> >On Fri, 29 Mar 2002 12:38, Ceki Gülcü wrote:
> > > 1) logging calls are made thousands of times so the indirection through
> > > an equalizer API (like commons-logging) has a performance impact
> >
> >Not in modern JVMs (read most almost all jdk1.3 impls).
> >
> >As long as the underlying indirection (ie between commons and Log4j) is
> > done via a final variable then the cost is zero due to JVM optimizations.
> > Theres still the cost of the dynamic dispatch between user land code and
> > commons code but that cost is very very minimal compared to the rest of
> > the logging operations.
> >
> >The cost comes in constructing the string objects (which is literally
> >thousands times more expensive than a dynamic dispatch) and routing the
> > log message.
> >
> >As long as the API supports functions like isDebugEnabled() (which I
> > believe commons does? or at least did) then the performance cost is so
> > negligable to be unimportant.
>
> In one word? Yes.
--
Cheers,
Pete
-----------------------------------------------------------------------
| I thought there was a knob on the TV to turn up the intelligence. |
| There's a knob called "brightness", but it doesn't work. |
-----------------------------------------------------------------------
--
To unsubscribe, e-mail: <mailto:[EMAIL PROTECTED]>
For additional commands, e-mail: <mailto:[EMAIL PROTECTED]>
