Hello,
Sebastien tests that you quoted are intended to compare performance for disabled
log statements. For enabled log statements, there is no noticeable difference
between calling log4j directly, via slf4j or via JCL.
Therefore, assuming you wish to test the enabled case, I suggest that the tests
be simplified for the slf4j case only. You tests log4j's performance compared to
logback for enabled statements, i.e. when there is some I/O involved.
The warm up phase with a loop of length 1 is very low. It should be a much
bigger number, 10'000 or more.
Does the above make sense?
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?
--
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
