log4j 与 logback 性能对比
2011-08-02 10:49
176 查看
代码来自 :
logback performance clarification
机器配置
Win XP SP3
双核 Intel(R) Core(TM)2 Duo CPU E7400 @ 2.80GHz
2GB内存
结果:
引用
###################### 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
###############################################
log4j测试代码
Java代码
/**
* $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代码
<?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>
logback测试代码
Java代码
/**
* $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代码
<?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>
jdbc.properties
Properties代码
# 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
10线程模式
Java代码
/**
* $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;
}
}
}
Java代码
/**
* $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;
}
}
}
logback performance clarification
机器配置
Win XP SP3
双核 Intel(R) Core(TM)2 Duo CPU E7400 @ 2.80GHz
2GB内存
结果:
引用
###################### 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
###############################################
log4j测试代码
Java代码
/**
* $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");
}
}
/** * $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代码
<?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>
<?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>
logback测试代码
Java代码
/**
* $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");
}
}
/** * $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代码
<?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>
<?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>
jdbc.properties
Properties代码
# 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
# 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
10线程模式
Java代码
/**
* $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.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; } } }
Java代码
/**
* $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;
}
}
}
相关文章推荐
- logback 和 log4j对比,及相关配置
- logback log4j log4j2 性能实测
- Logback、Log4J及slf4J日志框架分析对比及在Spring Boot中的使用
- 日志处理Log4j 与 logback对比、及使用配置
- Log4j 与 logback对比、及使用配置
- Log4J与LogBack的性能比较
- Log4j 与 logback对比、及使用配置
- Log4J与LogBack的性能比较
- logback log4j log4j2 性能实测
- logback log4j log4j2 性能实测
- Log4j 与 logback对比、及使用配置
- nginx折腾记(HTTP性能能测试,与Apache对比)
- oracle 使用递归的性能提示测试对比
- 来一次 memcache,redis 性能测试大对比,分别测试大字节数和小字节数
- (Mina的ByteBuffer和java.nio.ByteBuffer性能对比)Performance comparision of Mina's ByteBuffer VS java.nio.ByteBuffer use.
- (编辑整理) NetBeans vs Eclipse 之性能参数对比
- list 、set 、map 粗浅性能对比分析
- 【Flink】流计算框架Flink与Storm的性能对比
- golang与node.js的http模块性能对比测试(go1)
- ASP.NET Core 性能对比评测(ASP.NET,Python,Java,NodeJS)