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.2beta4/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.
--
Ceki
My link of the month: http://java.sun.com/aboutJava/standardization/
--
To unsubscribe, e-mail: <mailto:[EMAIL PROTECTED]>
For additional commands, e-mail: <mailto:[EMAIL PROTECTED]>
