I looked into the matter a bit more.
The difference in performance you observe is due to the fact that logback's size
based triggering policy track file size by calling file.getSize() whereas
log4j's implementation actually counts the number of bytes written. The latter
is faster but may be off for certain character sets.
If you try other appenders, or a rolling file appender with a different policy,
e.g. date based, the performance numbers should be comparable or in logback's favor.
Maverick Crank GRey wrote:
Hello guys,
I was trying to reproduce the Sébastien's result that he described in
this email
http://www.nabble.com/logback-performance-clarification-to9390741.html#a9451902
I made a few changes in original code, so now it looks like:
===
package net.academy.test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.apache.commons.logging.LogFactory;
import org.apache.commons.logging.Log;
public class PerformanceComparator {
static Logger slf4jLogger =
LoggerFactory.getLogger(PerformanceComparator.class);
static org.apache.log4j.Logger log4jLogger =
org.apache.log4j.Logger.getLogger(PerformanceComparator.class);
static Log jclLog = LogFactory.getLog(PerformanceComparator.class);
// How many times should we try to log:
static int loop = 1000000;
public static void main(String[] args) throws InterruptedException {
// Let's run once for Just In Time compiler
jcllogDirectDebugCall(1);
jcllogTestedDirectDebugCall(1);
log4jDirectDebugCall(1);
log4jTestedDebugCall(1);
slf4jDirectDebugCall(1);
slf4jTestedDebugCall(1);
slf4jParametrizedDebugCall(1);
// let's run the tests and display the results:
System.out.println("###############################################");
System.out.println("One JCL direct debug call: " +
jcllogDirectDebugCall(loop) + " nanoseconds");
System.out.println("One JCL tested (isDebugEnabled) debug call:
" + jcllogTestedDirectDebugCall(loop) + " nanoseconds");
System.out.println("One Log4j direct debug call: " +
log4jDirectDebugCall(loop) + " nanoseconds");
System.out.println("One Log4j tested (isDebugEnabled) debug
call: " + log4jTestedDebugCall(loop) + " nanoseconds");
System.out.println("One slf4j direct debug call: " +
slf4jDirectDebugCall(loop));
System.out.println("One slf4j tested (isDebugEnabled) debug
call: " + slf4jTestedDebugCall(loop) + " nanoseconds");
System.out.println("One slf4j parametrized debug call: " +
slf4jParametrizedDebugCall(loop) + " nanoseconds");
System.out.println("###############################################");
}
private static long jcllogDirectDebugCall(int loops) {
long start = System.nanoTime();
for (int i = 0; i < loops; i++) {
jclLog.debug("SEE IF THIS IS LOGGED " + i + ".");
}
return (System.nanoTime() - start) / loops;
}
private static long jcllogTestedDirectDebugCall(int loops) {
long start = System.nanoTime();
for (int i = 0; i < loops; i++) {
if (jclLog.isDebugEnabled()) {
jclLog.debug("SEE IF THIS IS LOGGED " + i + ".");
}
}
return (System.nanoTime() - start) / loops;
}
private static long log4jDirectDebugCall(int loops) {
long start = System.nanoTime();
for (int i = 0; i < loops; i++) {
log4jLogger.debug("SEE IF THIS IS LOGGED " + i + ".");
}
return (System.nanoTime() - start) / loops;
}
private static long log4jTestedDebugCall(int loops) {
long start = System.nanoTime();
for (int i = 0; i < loops; i++) {
if (log4jLogger.isDebugEnabled()) {
log4jLogger.debug("SEE IF THIS IS LOGGED " + i + ".");
}
}
return (System.nanoTime() - start) / loops;
}
private static long slf4jDirectDebugCall(int loops) {
long start = System.nanoTime();
for (int i = 0; i < loops; i++) {
slf4jLogger.debug("SEE IF THIS IS LOGGED " + i + ".");
}
return (System.nanoTime() - start) / loops;
}
private static long slf4jTestedDebugCall(int loops) {
long start = System.nanoTime();
for (int i = 0; i < loops; i++) {
if (slf4jLogger.isDebugEnabled())
slf4jLogger.debug("SEE IF THIS IS LOGGED " + i + ".");
}
return (System.nanoTime() - start) / loops;
}
private static long slf4jParametrizedDebugCall(int loops) {
long start = System.nanoTime();
for (int i = 0; i < loops; i++) {
slf4jLogger.debug("SEE IF THIS IS LOGGED {}.", i);
}
return (System.nanoTime() - start) / loops;
}
}
===
I switch both a logback and a log4j root loggers into DEBUG level. See
the config files below:
= logback.xml =
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug='true'>
<appender name="logfile"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>logback.log</File>
<BufferedIO>true</BufferedIO>
<ImmediateFlush>true</ImmediateFlush>
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>%d{HH:mm:ss} - %m%n</pattern>
</layout>
<rollingPolicy
class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<FileNamePattern>logback.%i.log</FileNamePattern>
<maxIndex>10</maxIndex>
</rollingPolicy>
<triggeringPolicy
class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<MaxFileSize>100MB</MaxFileSize>
</triggeringPolicy>
</appender>
<root>
<!--<level value="info"/>-->
<appender-ref ref="logfile"/>
</root>
</configuration>
===
and
= log4j.properties =
log4j.rootCategory=debug, logfile
log4j.appender.logfile=org.apache.log4j.RollingFileAppender
log4j.appender.logfile.File=log4j.log
log4j.appender.logfile.BufferedIO=true
log4j.appender.logfile.ImmediateFlush=true
log4j.appender.logfile.MaxFileSize=100MB
log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
log4j.appender.logfile.layout.ConversionPattern=%d{HH:mm:ss} - %m%n
===
The full maven project is attached.
In case I use 'ch.qos.logback:logback-classic' dependancy:
===
<!--
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-log4j12</artifactId>
<version>1.5.0-M0</version>
</dependency>
-->
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>0.9.9</version>
</dependency>
===
in the pom.xml the result of 'mvn test' looks like:
===
###############################################
One JCL direct debug call: 4323 nanoseconds
One JCL tested (isDebugEnabled) debug call: 4558 nanoseconds
One Log4j direct debug call: 5110 nanoseconds
One Log4j tested (isDebugEnabled) debug call: 4899 nanoseconds
*One slf4j direct debug call: 44609
One slf4j tested (isDebugEnabled) debug call: 45559 nanoseconds
One slf4j parametrized debug call: 46377 nanoseconds*
###############################################
===
Changing 'ch.qos.logback:logback-classic' to 'org.slf4j:slf4j-log4j12'
===
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-log4j12</artifactId>
<version>1.5.0-M0</version>
</dependency>
<!--
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>0.9.9</version>
</dependency>
-->
===
gives me the the following result:
===
###############################################
One JCL direct debug call: 3838 nanoseconds
One JCL tested (isDebugEnabled) debug call: 4416 nanoseconds
One Log4j direct debug call: 3663 nanoseconds
One Log4j tested (isDebugEnabled) debug call: 4147 nanoseconds
*One slf4j direct debug call: 3656**
One slf4j tested (isDebugEnabled) debug call: 3686 nanoseconds
One slf4j parametrized debug call: 4103 nanoseconds*
###############################################
===
Could you help me to understand the cause of 10 times difference between
log4j and logback?
And could you run this banchmark on your machine?
--
Be Happy!!!
UIN ICQ: 9487080
JUD: [EMAIL PROTECTED] <mailto:[EMAIL PROTECTED]>
------------------------------------------------------------------------
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
--
Ceki Gülcü
QOS.ch is looking to hire talented developers in Switzerland. If
interested, please contact c e k i @ q o s . c h
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
