log4j 与 logback 性能对比

代码来自 : [url=http://old.nabble.com/logback-performance-clarification-td9390741.html]logback performance clarification[/url]
[b]机器配置[/b]
Win XP SP3
双核 Intel(R) Core(TM)2 Duo CPU E7400 @ 2.80GHz
2GB内存
[b]结果:[/b]
[quote]
###################### loop 10w #########################
Log4j direct debug call: 250
Log4j direct warn call: 44381
Log4j tested (isDebugEnabled) debug call: 17
###############################################
###################### loop 100w # perfiles 500KB 2000files#########################
Log4j direct debug call: 250
Log4j direct warn call: 45664
Log4j tested (isDebugEnabled) debug call: 13
###############################################
######################## loop 100w # perfiles 500KB 2000files#######################
Log4j direct debug call: 239
Log4j direct warn call: 62462
Log4j tested (isDebugEnabled) debug call: 13
###############################################
################### loop 1000000 # perfiles 10MB 2000files############################
Log4j direct debug call: 236
Log4j direct warn call: 44482
Log4j tested (isDebugEnabled) debug call: 13
###############################################
################### loop 1000000 # perfiles 100MB 2000files############################
Log4j direct debug call: 240
Log4j direct warn call: 44305
Log4j tested (isDebugEnabled) debug call: 13
###############################################
################### loop 1000000 # perfiles 200MB 2000files############################
Log4j direct debug call: 236
Log4j direct warn call: 45445
Log4j tested (isDebugEnabled) debug call: 13
###############################################

########################### 异步模式 ########################################
################### loop 100000 #ASYNC 10线程 500KB 2000files############################
Log4j direct debug call: 938
Log4j direct warn call: 623017
Log4j tested (isDebugEnabled) debug call: 12
###############################################
################### loop 100000 #ASYNC 10线程 500KB 2000files############################
Log4j direct debug call: 989
Log4j direct warn call: 636342
Log4j tested (isDebugEnabled) debug call: 12
###############################################
################### loop 100000 #ASYNC 10线程 10MB 2000files############################
Log4j direct debug call: 954
Log4j direct warn call: 498409
Log4j tested (isDebugEnabled) debug call: 12
###############################################
################### loop 100000 #ASYNC 10线程 100MB 2000files############################
Log4j direct debug call: 961
Log4j direct warn call: 517658
Log4j tested (isDebugEnabled) debug call: 12
###############################################
################### loop 100000 #ASYNC 10线程 200MB 2000files############################
Log4j direct debug call: 994
Log4j direct warn call: 521485
Log4j tested (isDebugEnabled) debug call: 11
###############################################


##################### loop 10w ##########################
Logback direct debug call: 224
Logback direct warn call: 10649
Logback tested (isDebugEnabled) debug call: 16
Logback tested (isWarnEnabled) warn call: 10754
Logback parametrized debug call: 25
Logback parametrized warn call: 11544
###############################################
###############################################
Logback direct debug call: 205
Logback direct warn call: 10634
Logback tested (isDebugEnabled) debug call: 12
Logback tested (isWarnEnabled) warn call: 10886
Logback parametrized debug call: 20
Logback parametrized warn call: 11521
###############################################
################## loop 1000000 # perfiles 500KB and zip#############################
Logback direct debug call: 214
Logback direct warn call: 22342
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 11079
Logback parametrized debug call: 22
Logback parametrized warn call: 11959
###############################################
################## loop 1000000 # perfiles 500KB and zip#############################
Logback direct debug call: 203
Logback direct warn call: 10297
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 10585
Logback parametrized debug call: 20
Logback parametrized warn call: 10884
###############################################
################## loop 1000000 # perfiles 200MB and zip#############################
Logback direct debug call: 206
Logback direct warn call: 8472
Logback tested (isDebugEnabled) debug call: 12
Logback tested (isWarnEnabled) warn call: 8600
Logback parametrized debug call: 21
Logback parametrized warn call: 8707
###############################################
################## loop 1000000 # perfiles 100MB and zip#############################
Logback direct debug call: 395
Logback direct warn call: 40629
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 40417
Logback parametrized debug call: 20
Logback parametrized warn call: 40687
Count Times(ms) : 122156
###############################################
################## loop 1000000 # perfiles 100MB and zip#############################
Logback direct debug call: 236
Logback direct warn call: 8489
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 8535
Logback parametrized debug call: 21
Logback parametrized warn call: 9042
###############################################
################## loop 1000000 # perfiles 50MB and zip#############################
Logback direct debug call: 217
Logback direct warn call: 8508
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 8695
Logback parametrized debug call: 20
Logback parametrized warn call: 8757
###############################################
################## loop 1000000 # perfiles 10MB and zip#############################
Logback direct debug call: 208
Logback direct warn call: 8499
Logback tested (isDebugEnabled) debug call: 12
Logback tested (isWarnEnabled) warn call: 8578
Logback parametrized debug call: 22
Logback parametrized warn call: 8741
###############################################
################## loop 100000 # jdbc(c3p0) #############################
Logback direct debug call: 355
Logback direct warn call: 3937399
Logback tested (isDebugEnabled) debug call: 27
Logback tested (isWarnEnabled) warn call: 4040561
Logback parametrized debug call: 40
Logback parametrized warn call: 4004411
###############################################
################## loop 2000000 # 1 Main Thread 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 406
Logback direct warn call: 40168
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 40212
Logback parametrized debug call: 20
Logback parametrized warn call: 40562
Count Times(ms) : 242765
###############################################
################## loop 1000000 # 1 Main Thread 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 389
Logback direct warn call: 39958
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 40440
Logback parametrized debug call: 20
Logback parametrized warn call: 40335
Count Times(ms) : 121156
###############################################
################## loop 1000000 # socket 1 client 1 Main Thread 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 401
Logback direct warn call: 117924
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 118562
Logback parametrized debug call: 19
Logback parametrized warn call: 128202
Count Times(ms) : 365110
###############################################
################## loop 100000 # socket 1 client 1 Main Thread 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 148301
Logback direct warn call: 152806
Logback tested (isDebugEnabled) debug call: 150971
Logback tested (isWarnEnabled) warn call: 141062
Logback parametrized debug call: 158658
Logback parametrized warn call: 153140
Count Times(ms) : 90500
###############################################
################## loop 1000000 # socket 1 client 1 Main Thread 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 388
Logback direct warn call: 144331
Logback tested (isDebugEnabled) debug call: 10
Logback tested (isWarnEnabled) warn call: 96334
Logback parametrized debug call: 20
Logback parametrized warn call: 92826
Count Times(ms) : 333907
###############################################
################## loop 1000000 # socket 1 client 1 Main Thread 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 392
Logback direct warn call: 166776
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 216869
Logback parametrized debug call: 141
Logback parametrized warn call: 156749
Count Times(ms) : 540969
###############################################


################## loop 100000 # 10thread 20queueSize 500KB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 885
Logback direct warn call: 451863
Logback tested (isDebugEnabled) debug call: 9
Logback tested (isWarnEnabled) warn call: 451750
Logback parametrized debug call: 21
Logback parametrized warn call: 449805
###############################################
################## loop 100000 # 10 Thread 20 QueueSize 10MB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 918
Logback direct warn call: 450027
Logback tested (isDebugEnabled) debug call: 9
Logback tested (isWarnEnabled) warn call: 452299
Logback parametrized debug call: 22
Logback parametrized warn call: 437268
###############################################
################## loop 100000 # 10 Thread 20 QueueSize 100MB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 808
Logback direct warn call: 445219
Logback tested (isDebugEnabled) debug call: 10
Logback tested (isWarnEnabled) warn call: 449316
Logback parametrized debug call: 20
Logback parametrized warn call: 431124
###############################################
################## loop 100000 # 10 Thread 20 QueueSize 200MB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 851
Logback direct warn call: 445867
Logback tested (isDebugEnabled) debug call: 10
Logback tested (isWarnEnabled) warn call: 450838
Logback parametrized debug call: 21
Logback parametrized warn call: 440028
###############################################
################## loop 100000 # 50 Thread 50 QueueSize 100MB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 8719
Logback direct warn call: 2358846
Logback tested (isDebugEnabled) debug call: 10
Logback tested (isWarnEnabled) warn call: 2346821
Logback parametrized debug call: 20
Logback parametrized warn call: 2329942
###############################################
################## loop 100000 # 4 Thread 20 QueueSize 100MB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 1299
Logback direct warn call: 195412
Logback tested (isDebugEnabled) debug call: 14
Logback tested (isWarnEnabled) warn call: 194969
Logback parametrized debug call: 24
Logback parametrized warn call: 192029
###############################################
################## loop 100000 # 3 Thread 20 QueueSize 100MB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 915
Logback direct warn call: 145027
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 140793
Logback parametrized debug call: 21
Logback parametrized warn call: 143145
###############################################
################## loop 100000 # 2 Thread 20 QueueSize 100MB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 961
Logback direct warn call: 95941
Logback tested (isDebugEnabled) debug call: 10
Logback tested (isWarnEnabled) warn call: 96473
Logback parametrized debug call: 20
Logback parametrized warn call: 96345
###############################################
################## loop 100000 # 1 Thread 20 QueueSize 100MB and zip #per LogSize 286 Byte#############################
Logback direct debug call: 414
Logback direct warn call: 44408
Logback tested (isDebugEnabled) debug call: 9
Logback tested (isWarnEnabled) warn call: 44709
Logback parametrized debug call: 18
Logback parametrized warn call: 45287
###############################################
################## loop 100000 # 1 Thread 20 QueueSize 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 403
Logback direct warn call: 43233
Logback tested (isDebugEnabled) debug call: 10
Logback tested (isWarnEnabled) warn call: 43490
Logback parametrized debug call: 19
Logback parametrized warn call: 43935
Count Times(ms) : 270000
###############################################
################## loop 100000 # 1 Thread 20 QueueSize 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 410
Logback direct warn call: 43172
Logback tested (isDebugEnabled) debug call: 9
Logback tested (isWarnEnabled) warn call: 43314
Logback parametrized debug call: 19
Logback parametrized warn call: 43751
Count Times(ms) : 283812
###############################################
################## loop 100000 # 2 Thread 20 QueueSize 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 511
Logback direct warn call: 92970
Logback tested (isDebugEnabled) debug call: 12
Logback tested (isWarnEnabled) warn call: 90352
Logback parametrized debug call: 20
Logback parametrized warn call: 92044
Count Times(ms) : 304656
###############################################
################## loop 100000 # 3 Thread 20 QueueSize 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 619
Logback direct warn call: 136300
Logback tested (isDebugEnabled) debug call: 10
Logback tested (isWarnEnabled) warn call: 146003
Logback parametrized debug call: 20
Logback parametrized warn call: 109449
Count Times(ms) : 294078
###############################################
################## loop 100000 # 4 Thread 20 QueueSize 100MB #per LogSize 286 Byte#############################
Logback direct debug call: 702
Logback direct warn call: 171259
Logback tested (isDebugEnabled) debug call: 11
Logback tested (isWarnEnabled) warn call: 178437
Logback parametrized debug call: 21
Logback parametrized warn call: 187121
Count Times(ms) : 293609
###############################################
[/quote]

[b]log4j测试代码[/b]

/**
 * $Id$
 */
package perfTest.ch.qos.logback;

import org.apache.log4j.Logger;
import org.apache.log4j.xml.DOMConfigurator;

/**
 * @author Last changed by: $Author$
 * @version $Revision$ $Date$
 */
public class PerformanceLog4j {
	static Logger log4jlogger = Logger.getLogger(PerformanceLog4j.class);

	// How many times should we try to log:
	static int loop = 1000000;

	public static void main(String[] args) throws InterruptedException {
		initConfig();

		// Let's run once for Just In Time compiler
		log4jDirectDebugCall();
		log4jDirectWarnCall();
		log4jTestedDebugCall();

		// let's run the tests and display the results:
		long result1 = log4jDirectDebugCall();
		long result2 = log4jDirectWarnCall();
		long result3 = log4jTestedDebugCall();

		System.out.println("################### loop " + loop + " ############################");
		System.out.println("Log4j direct debug call: " + result1);
		System.out.println("Log4j direct warn call: " + result2);
		System.out.println("Log4j tested (isDebugEnabled) debug call: " + result3);
		System.out.println("###############################################");
	}

	private static long log4jDirectDebugCall() {
		Integer j = new Integer(1);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			log4jlogger.debug("SEE IF THIS IS LOGGED log4jDirectDebugCall() " + j + ".");
		}
		return (System.nanoTime() - start) / loop;
	}

	private static long log4jDirectWarnCall() {
		Integer j = new Integer(2);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			log4jlogger.warn("SEE IF THIS IS LOGGED  log4jDirectWarnCall()" + j + ".");
		}
		return (System.nanoTime() - start) / loop;
	}

	private static long log4jTestedDebugCall() {
		Integer j = new Integer(3);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			if (log4jlogger.isDebugEnabled()) {
				log4jlogger.debug("SEE IF THIS IS LOGGED log4jTestedDebugCall() " + j + ".");
			}
		}
		return (System.nanoTime() - start) / loop;
	}

	private static void initConfig() {
		DOMConfigurator.configure("src/main/resource/log4j.xml");

		// create the loggers
		org.apache.log4j.Logger.getLogger("perfTest");
		org.apache.log4j.Logger.getLogger("perfTest.ch");
		org.apache.log4j.Logger.getLogger("perfTest.ch.qos");
		org.apache.log4j.Logger.getLogger("perfTest.ch.qos.logback");
	}
}

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/'>

<!--	<appender name="ASYNC" class="org.apache.log4j.AsyncAppender">-->
<!--		<appender-ref ref="STDOUT" />-->
<!--	</appender>-->

	<appender name="STDOUT" class="org.apache.log4j.ConsoleAppender">
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="%d (%t) [%24F:%-3L:%-5p]%x %m%n" />
		</layout>
	</appender>

	<appender name="FILE" class="org.apache.log4j.RollingFileAppender">
		<param name="File" value="logs/log4j-test.log" />
		<param name="BufferSize" value="8129" />
		<param name="Append" value="true" />
		<param name="MaxFileSize" value="200MB"/>
		<param name="MaxBackupIndex" value="2000"/>
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="%d (%t) [%24F:%-3L:%-5p]%x %m%n" />
		</layout>
	</appender>


	<root>
		<priority value="INFO" />
<!--		<appender-ref ref="STDOUT" />-->
		 <appender-ref ref="FILE"/> 
	</root>

</log4j:configuration>

[b]logback测试代码[/b]

/**
 * $Id$
 */
package perfTest.ch.qos.logback;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.joran.JoranConfigurator;
import ch.qos.logback.core.joran.spi.JoranException;
import ch.qos.logback.core.util.StatusPrinter;

/**
 * @author Last changed by: $Author$
 * @version $Revision$ $Date$
 */
public class PerformanceLogback {
	static Logger logbacklogger = LoggerFactory.getLogger(PerformanceLogback.class);

	// How many times should we try to log:
	static int loop = 1000000;

	public static void main(String[] args) throws InterruptedException {
		// initConfig();

		// Let's run once for Just In Time compiler
		logbackDirectDebugCall();
		logbackDirectWarnCall();
		logbackTestedDebugCall();
		logbackTestedWarnCall();
		logbackParametrizedDebugCall();
		logbackParametrizedWarnCall();

		// let's run the tests and display the results:
		long result4 = logbackDirectDebugCall();
		long result5 = logbackDirectWarnCall();
		long result6 = logbackTestedDebugCall();
		long result7 = logbackTestedWarnCall();
		long result8 = logbackParametrizedDebugCall();
		long result9 = logbackParametrizedWarnCall();

		System.out.println("################## loop " + loop + " #############################");
		System.out.println("Logback direct debug call: " + result4);
		System.out.println("Logback direct warn call: " + result5);
		System.out.println("Logback tested (isDebugEnabled) debug call: " + result6);
		System.out.println("Logback tested (isWarnEnabled) warn call: " + result7);
		System.out.println("Logback parametrized debug call: " + result8);
		System.out.println("Logback parametrized warn call: " + result9);
		System.out.println("###############################################");
	}

	private static long logbackDirectDebugCall() {
		Integer j = new Integer(5);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			logbacklogger.debug("SEE IF THIS IS LOGGED " + j + ".");
		}
		return (System.nanoTime() - start) / loop;
	}

	private static long logbackDirectWarnCall() {
		Integer j = new Integer(6);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			logbacklogger.warn("SEE IF THIS IS LOGGED logbackDirectWarnCall()" + j + ".");
		}
		return (System.nanoTime() - start) / loop;
	}

	private static long logbackTestedDebugCall() {
		Integer j = new Integer(7);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			if (logbacklogger.isDebugEnabled())
				logbacklogger.debug("SEE IF THIS IS LOGGED " + j + ".");
		}
		return (System.nanoTime() - start) / loop;
	}

	private static long logbackTestedWarnCall() {
		Integer j = new Integer(8);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			if (logbacklogger.isWarnEnabled())
				logbacklogger.warn("SEE IF THIS IS LOGGED logbackTestedWarnCall()" + j + ".");
		}
		long end = System.nanoTime();
		long result = (end - start) / loop;
		System.out.println("start = " + start + "end = " + end + "result = " + result);
		return result;
	}

	private static long logbackParametrizedDebugCall() {
		Integer j = new Integer(9);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			logbacklogger.debug("SEE IF THIS IS LOGGED {}.", j);
		}
		return (System.nanoTime() - start) / loop;
	}

	private static long logbackParametrizedWarnCall() {
		Integer j = new Integer(10);
		long start = System.nanoTime();
		for (int i = 0; i < loop; i++) {
			logbacklogger.warn("SEE IF THIS IS LOGGED logbackParametrizedWarnCall() {}.", j);
		}
		long end = System.nanoTime();
		long result = (end - start) / loop;
		System.out.println("start = " + start + "end = " + end + "result = " + result);
		return result;
	}

	private static void initConfig() {
		// assume SLF4J is bound to logback in the current environment
		LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();

		try {
			JoranConfigurator configurator = new JoranConfigurator();
			configurator.setContext(lc);
			// the context was probably already configured by default configuration
			// rules
			lc.reset();
			configurator.doConfigure("src/main/resource/logback.xml");
		} catch (JoranException je) {
			// StatusPrinter will handle this
		}
		StatusPrinter.printInCaseOfErrorsOrWarnings(lc);

		// create the loggers
		LoggerFactory.getLogger("perfTest");
		LoggerFactory.getLogger("perfTest.ch");
		LoggerFactory.getLogger("perfTest.ch.qos");
		LoggerFactory.getLogger("perfTest.ch.qos.logback");
	}
}

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
	<property file="src/main/resource/jdbc.properties" />

	<appender name="DB" class="ch.qos.logback.classic.db.DBAppender">
		<connectionSource class="ch.qos.logback.core.db.DataSourceConnectionSource">
			<dataSource class="com.mchange.v2.c3p0.ComboPooledDataSource">
				<driverClass>${jdbc.driver.class}</driverClass>
				<jdbcUrl>${jdbc.url}</jdbcUrl>
				<!--				<serverName>${serverName}</serverName>-->
				<!--         <databaseName>${databaseName}</databaseName>-->
				<user>${jdbc.username}</user>
				<password>${jdbc.password}</password>
				<param name="minPoolSize" value="30" />
				<param name="maxPoolSize" value="60" />
				<param name="initialPoolSize" value="30" />
				<param name="acquireIncrement" value="3" />
				<param name="acquireRetryAttempts" value="30" />
				<param name="acquireRetryDelay" value="1000" />
				<param name="autoCommitOnClose" value="false" />
				<param name="breakAfterAcquireFailure" value="false" />
				<param name="checkoutTimeout" value="0" />
				<param name="maxIdleTime" value="60" />
				<param name="maxStatements" value="100" />
			</dataSource>

		</connectionSource>
	</appender>
	<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<file>logs/logback-test.log</file>
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<!-- rollover daily -->
			<fileNamePattern>logs/logback-%d{yyyy-MM-dd}.%i.zip</fileNamePattern>
			<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
				<!-- or whenever the file size reaches 100MB -->
				<maxFileSize>10MB</maxFileSize>
			</timeBasedFileNamingAndTriggeringPolicy>
		</rollingPolicy>
		<encoder>
			<pattern>%date{ISO8601} [%thread] [%24file:%M:%-3line:%-5level] - %msg%n</pattern>
		</encoder>
	</appender>

	<root level="INFO">
<!--		<appender-ref ref="DB" />-->
		<appender-ref ref="FILE" />
	</root>
</configuration>

[b]jdbc.properties[/b]

# mysql config
jdbc.driver.class=com.mysql.jdbc.Driver
jdbc.url=jdbc:mysql://localhost/logs?autoReconnect=true&useUnicode=true&characterEncoding=utf8
jdbc.username=root
jdbc.password=root

[b]10线程模式[/b]

/**
 * $Id$
 */
package perfTest.ch.qos.logback;

import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

import org.apache.log4j.Logger;
import org.apache.log4j.xml.DOMConfigurator;

/**
 * @author Last changed by: $Author$
 * @version $Revision$ $Date$
 */
public class PerformanceLog4j {

	// How many times should we try to log:
	static int loop = 100000;

	static ConcurrentMap<Integer, Long> result = new ConcurrentHashMap<Integer, Long>();

	static int RESULT_1 = 1;
	static int RESULT_2 = 2;
	static int RESULT_3 = 3;
	static int countThread = 20;

	public PerformanceLog4j() {

	}

	public void start() {
		initConfig();
		result.put(RESULT_1, 0L);
		result.put(RESULT_2, 0L);
		result.put(RESULT_3, 0L);
		int countT = countThread;
		ExecutorService executor = Executors.newFixedThreadPool(10);

		for (int i = 0; i < countThread; i++) {
			executor.execute(new Log4jRun());
		}

		while (countThread > 0) {
			try {
				Thread.sleep(10000);
			} catch (InterruptedException e) {
				e.printStackTrace();
			}
		}
		executor.shutdown();

		System.out.println("################### loop " + loop + " #ASYNC ############################");
		System.out.println("Log4j direct debug call: " + result.get(RESULT_1) / countT);
		System.out.println("Log4j direct warn call: " + result.get(RESULT_2) / countT);
		System.out.println("Log4j tested (isDebugEnabled) debug call: " + result.get(RESULT_3) / countT);
		System.out.println("###############################################");

	}

	public static void main(String[] args) throws InterruptedException {
		new PerformanceLog4j().start();
	}

	private static void initConfig() {
		DOMConfigurator.configure("src/main/resource/log4j.xml");

		// create the loggers
		org.apache.log4j.Logger.getLogger("perfTest");
		org.apache.log4j.Logger.getLogger("perfTest.ch");
		org.apache.log4j.Logger.getLogger("perfTest.ch.qos");
		org.apache.log4j.Logger.getLogger("perfTest.ch.qos.logback");
	}

	static class Log4jRun implements Runnable {
		static Logger log4jlogger = Logger.getLogger(Log4jRun.class);

		static {
			// Let's run once for Just In Time compiler
			log4jDirectDebugCall();
			log4jDirectWarnCall();
			log4jTestedDebugCall();
		}

		public Log4jRun() {

		}

		/*
		 * (non-Javadoc)
		 * @see java.lang.Runnable#run()
		 */
		@Override
		public void run() {
			System.out.println("start " + Thread.currentThread());
			// let's run the tests and display the results:
			long result1 = log4jDirectDebugCall();
			long result2 = log4jDirectWarnCall();
			long result3 = log4jTestedDebugCall();
			synchronized (result) {
				result.put(RESULT_1, result.get(RESULT_1) + result1);
				result.put(RESULT_2, result.get(RESULT_2) + result2);
				result.put(RESULT_3, result.get(RESULT_3) + result3);
			}
			countThread--;
			System.out.println("count " + countThread + " end " + Thread.currentThread());
		}

		private static long log4jDirectDebugCall() {
			Integer j = new Integer(1);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				log4jlogger.debug("SEE IF THIS IS LOGGED log4jDirectDebugCall() " + j + ".");
			}
			return (System.nanoTime() - start) / loop;
		}

		private static long log4jDirectWarnCall() {
			Integer j = new Integer(2);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				log4jlogger.warn("SEE IF THIS IS LOGGED  log4jDirectWarnCall()" + j + ".");
			}
			return (System.nanoTime() - start) / loop;
		}

		private static long log4jTestedDebugCall() {
			Integer j = new Integer(3);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				if (log4jlogger.isDebugEnabled()) {
					log4jlogger.debug("SEE IF THIS IS LOGGED log4jTestedDebugCall() " + j + ".");
				}
			}
			return (System.nanoTime() - start) / loop;
		}

	}
}

/**
 * $Id$
 */
package perfTest.ch.qos.logback;

import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * @author Last changed by: $Author$
 * @version $Revision$ $Date$
 */
public class PerformanceLogback {

	// How many times should we try to log:
	static int loop = 100000;

	static ConcurrentMap<Integer, Long> result = new ConcurrentHashMap<Integer, Long>();

	static int RESULT_4 = 1;
	static int RESULT_5 = 2;
	static int RESULT_6 = 3;
	static int RESULT_7 = 4;
	static int RESULT_8 = 5;
	static int RESULT_9 = 6;
	static int countThread = 20;

	public PerformanceLogback() {

	}

	public void start() {
		result.put(RESULT_4, 0L);
		result.put(RESULT_5, 0L);
		result.put(RESULT_6, 0L);
		result.put(RESULT_7, 0L);
		result.put(RESULT_8, 0L);
		result.put(RESULT_9, 0L);

		int countT = countThread;
		ExecutorService executor = Executors.newFixedThreadPool(10);

		for (int i = 0; i < countThread; i++) {
			executor.execute(new LogbackRun());
		}

		while (countThread > 0) {
			try {
				Thread.sleep(10000);
			} catch (InterruptedException e) {
				e.printStackTrace();
			}
		}
		executor.shutdown();

		System.out.println("################## loop " + loop + " #############################");
		System.out.println("Logback direct debug call: " + result.get(RESULT_4) / countT);
		System.out.println("Logback direct warn call: " + result.get(RESULT_5) / countT);
		System.out.println("Logback tested (isDebugEnabled) debug call: " + result.get(RESULT_6) / countT);
		System.out.println("Logback tested (isWarnEnabled) warn call: " + result.get(RESULT_7) / countT);
		System.out.println("Logback parametrized debug call: " + result.get(RESULT_8) / countT);
		System.out.println("Logback parametrized warn call: " + result.get(RESULT_9) / countT);
		System.out.println("###############################################");
	}

	public static void main(String[] args) throws InterruptedException {
		new PerformanceLogback().start();
	}

	static class LogbackRun implements Runnable {
		static Logger logbacklogger = LoggerFactory.getLogger(LogbackRun.class);

		static {
			// Let's run once for Just In Time compiler
			logbackDirectDebugCall();
			logbackDirectWarnCall();
			logbackTestedDebugCall();
			logbackTestedWarnCall();
			logbackParametrizedDebugCall();
			logbackParametrizedWarnCall();
		}
		/*
		 * (non-Javadoc)
		 * @see java.lang.Runnable#run()
		 */
		@Override
		public void run() {
			System.out.println("start " + Thread.currentThread());
			// let's run the tests and display the results:
			long result4 = logbackDirectDebugCall();
			long result5 = logbackDirectWarnCall();
			long result6 = logbackTestedDebugCall();
			long result7 = logbackTestedWarnCall();
			long result8 = logbackParametrizedDebugCall();
			long result9 = logbackParametrizedWarnCall();
			synchronized (result) {
				result.put(RESULT_4, result.get(RESULT_4) + result4);
				result.put(RESULT_5, result.get(RESULT_5) + result5);
				result.put(RESULT_6, result.get(RESULT_6) + result6);
				result.put(RESULT_7, result.get(RESULT_7) + result7);
				result.put(RESULT_8, result.get(RESULT_8) + result8);
				result.put(RESULT_9, result.get(RESULT_9) + result9);
			}
			countThread--;
			System.out.println("count " + countThread + " end " + Thread.currentThread());

		}

		private static long logbackDirectDebugCall() {
			Integer j = new Integer(5);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				logbacklogger.debug("SEE IF THIS IS LOGGED " + j + ".");
			}
			return (System.nanoTime() - start) / loop;
		}

		private static long logbackDirectWarnCall() {
			Integer j = new Integer(6);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				logbacklogger.warn("SEE IF THIS IS LOGGED logbackDirectWarnCall()" + j + ".");
			}
			return (System.nanoTime() - start) / loop;
		}

		private static long logbackTestedDebugCall() {
			Integer j = new Integer(7);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				if (logbacklogger.isDebugEnabled())
					logbacklogger.debug("SEE IF THIS IS LOGGED " + j + ".");
			}
			return (System.nanoTime() - start) / loop;
		}

		private static long logbackTestedWarnCall() {
			Integer j = new Integer(8);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				if (logbacklogger.isWarnEnabled())
					logbacklogger.warn("SEE IF THIS IS LOGGED logbackTestedWarnCall()" + j + ".");
			}
			long end = System.nanoTime();
			long result = (end - start) / loop;
			// System.out.println("start = " + start + "end = " + end + "result = " + result);
			return result;
		}

		private static long logbackParametrizedDebugCall() {
			Integer j = new Integer(9);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				logbacklogger.debug("SEE IF THIS IS LOGGED {}.", j);
			}
			return (System.nanoTime() - start) / loop;
		}

		private static long logbackParametrizedWarnCall() {
			Integer j = new Integer(10);
			long start = System.nanoTime();
			for (int i = 0; i < loop; i++) {
				logbacklogger.warn("SEE IF THIS IS LOGGED logbackParametrizedWarnCall() {}.", j);
			}
			long end = System.nanoTime();
			long result = (end - start) / loop;
			// System.out.println("start = " + start + "end = " + end + "result = " + result);
			return result;
		}
	}
}