logback异步性能测试
日志通常来说都以文件形式记录到磁盘，例如使用，这样的话一次写日志就会发生一次磁盘IO，这对于性能是一种损耗，因此更多的，对于每次请求必打的日志（例如请求日志，记录请求API、参数、请求时间），我们会采取异步写日志的方式而不让此次写日志发生磁盘IO，阻塞线程从而造成不必要的性能损耗。（不要小看这个点，可以网上查一下服务端性能优化的文章，只是因为将日志改为异步写，整个QPS就有了大幅的提高）。
接下来，我们对logback进行下性能测试，分为同步和异步；
单线程&同步
测试代码
/**
* 测试单线程同步
*
* @param
* @return void
* @auther lay
* @Date 10:49 2019/3/21
*/
@Test
public void testSingleAndSync() {
long start = System.currentTimeMillis();
for (int i = 0; i < 50; i++) {
long singleStart = System.currentTimeMillis();
for (int y = 0; y < 10000; y++) {
log.info("this is info message");
}
System.out.print(System.currentTimeMillis() - singleStart + " ");
}
System.out.println("\n spend time: " + (System.currentTimeMillis() - start));
}
我们分50组，1组打印1W次，一共输出50W条日志
配置文件（简单格式）
<configuration>
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>d:/log.out</file>
<append>true</append>
<encoder>
<pattern>%msg%n</pattern>
<charset>utf-8</charset>
</encoder>
</appender>
<root level="info">
<appender-ref ref="FILE" />
</root>
</configuration>
测试结果（简单格式）
72 48 41 39 38 39 26 24 22 25 24 23 26 24 26 24 24 24 24 26 25 26 23 27 24 23 25 23 24 22 23 24 24 23 24 23 25 22 24 25 25 25 25 26 27 26 30 31 23 25
spend time: 1363
注意这里日志输出的格式，只有简单的日志信息。
现在我们更改下配置文件，采用默认格式
<!-- 其他同上不变-->
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36}:%L- %msg%n</pattern>
测试代码不变，测试结果如下
591 477 485 484 479 472 486 508 486 478 479 480 476 475 486 486 487 472 495 487 480 476 471 479 474 484 486 474 480 476 490 484 478 474 476 479 488 479 476 483 492 474 478 477 477 480 489 506 477 484
spend time: 24190
可以发现，发现日志格式化对性能的影响很大，花费时间为24s，近乎是之前的20倍，所以这点值得注意，尽量少输出不必要的信息。
多线程&同步
测试代码
/**
* 测试多线程同步
*
* @param
* @return void
* @auther lay
* @Date 10:49 2019/3/21
*/
@Test
public void testMultiAndSync() throws InterruptedException {
long start = System.currentTimeMillis();
// 使用了CountDownLatch对象，可以计算出50个线程执行完毕后所花费的总时间。
CountDownLatch countDownLatch = new CountDownLatch(50);
for (int x = 0; x < 50; x++) {
new Thread(() -> {
long singleStart = System.currentTimeMillis();
for (int y = 0; y < 10000; y++) {
log.info("this is info message");
}
System.out.print(System.currentTimeMillis() - singleStart + " ");
countDownLatch.countDown();
}).start();
}
countDownLatch.await();
System.out.println("\n spend time: " + (System.currentTimeMillis() - start));
}
配置文件（简单格式）
<!-- 同上-->
<pattern>%msg%n</pattern>
测试结果（简单格式）
1187 1260 1356 1355 1416 1421 1423 1427 1445 1447 1459 1513 1556 1574 1600 1604 1614 1644 1657 1659 1674 1674 1677 1683 1685 1685 1688 1696 1703 1701 1704 1706 1711 1712 1716 1720 1720 1724 1727 1728 1739 1737 1738 1740 1746 1747 1747 1750 1753 1754
spend time: 1761
配置文件（默认格式）
<!-- 更改日志格式， 其他同上不变-->
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36}:%L- %msg%n</pattern>
测试结果（默认格式）
3685 3676 3684 3697 3689 3700 3696 3702 3703 3707 3705 3714 3716 3718 3713 3708 3716 3719 3721 3730 3736 3729 3733 3730 3739 3737 3740 3725 3735 3739 3742 3738 3726 3739 3744 3745 3741 3739 3747 3740 3746 3746 3739 3740 3739 3750 3735 3745 3751 3735
spend time: 3754
可以看出，由于线程创建和日志总量太小的原因，在简单格式测试中多线程的情况下并没有体现出更优秀的性能，甚至比单线程还要慢0.4s。
但是在使用默认格式输出时间、线程、类名等补充信息后，由于字符流的变多，相比单线程，多线程所需的时间从24s缩短到了只有4s不到。
单线程&异步
测试代码
/**
* 测试单线程异步
*
* @param
* @return void
* @auther lay
* @Date 10:49 2019/3/21
*/
@Test
public void testSingleAndAsync() {
long start = System.currentTimeMillis();
for (int i = 0; i < 50; i++) {
long singleStart = System.currentTimeMillis();
for (int y = 0; y < 10000; y++) {
log.info("this is info message");
}
System.out.print(System.currentTimeMillis() - singleStart + " ");
}
System.out.println("\n spend time: " + (System.currentTimeMillis() - start));
}
配置文件（简单格式）
<configuration>
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>e:/log.out</file>
<append>true</append>
<encoder>
<pattern>%msg%n</pattern>
</encoder>
</appender>
<appender name ="ASYNC" class= "ch.qos.logback.classic.AsyncAppender">
<discardingThreshold>0</discardingThreshold>
<queueSize>512</queueSize>
<appender-ref ref ="FILE"/>
</appender>
<root level="info">
<appender-ref ref="ASYNC" />
</root>
</configuration>
测试结果（简单格式）
75 52 52 51 49 48 54 54 52 44 41 43 35 39 36 30 30 30 31 30 31 32 31 30 31 31 29 30 29 28 29 28 26 30 27 27 34 28 28 29 30 27 31 34 34 34 34 35 33 34
spend time: 1792
配置文件（默认格式）
<!-- 更改日志格式， 其他同上不变-->
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36}:%L- %msg%n</pattern>
测试结果（默认格式）
244 252 224 224 173 173 169 170 162 170 167 164 180 190 170 168 166 165 165 166 167 169 169 165 164 164 164 165 174 173 165 166 164 171 173 174 169 168 167 181 173 179 166 169 168 170 168 182 173 167
spend time: 8754
在简单格式的测试中，我们发现结果和多线程同步时类似的用了1.79s，甚至比单线程同步还要慢，很可能是创建线程的开销时间。但是在默认格式的测试中，只用了8s多，相比原先的24s多提高了整整三倍。
多线程&异步
测试代码
/**
* 测试多线程异步
*
* @param
* @return void
* @auther lay
* @Date 10:49 2019/3/21
*/
@Test
public void testMultiAndAsync() {
long start = System.currentTimeMillis();
// 使用了CountDownLatch对象，可以计算出50个线程执行完毕后所花费的总时间。
CountDownLatch countDownLatch = new CountDownLatch(50);
for (int x = 0; x < 50; x++) {
new Thread(() -> {
long singleStart = System.currentTimeMillis();
for (int y = 0; y < 10000; y++) {
log.info("this is info message");
}
System.out.print(System.currentTimeMillis() - singleStart + " ");
countDownLatch.countDown();
}).start();
}
countDownLatch.await();
System.out.println("\n spend time: " + (System.currentTimeMillis() - start));
}
配置文件（简单格式）
<!-- 同上-->
<pattern>%msg%n</pattern>
测试结果（简单格式）
2072 2100 2106 2118 2126 2147 2183 2191 2194 2207 2209 2222 2223 2224 2227 2229 2234 2237 2239 2241 2242 2246 2248 2251 2253 2258 2261 2264 2260 2265 2261 2263 2271 2271 2274 2273 2275 2276 2276 2281 2283 2284 2284 2286 2288 2286 2286 2289 2288 2291
spend time: 2293
配置文件（默认格式）
<!-- 更改日志格式， 其他同上不变-->
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36}:%L- %msg%n</pattern>
测试结果（默认格式）
8062 8097 8104 8112 8139 8157 8162 8170 8170 8166 8175 8175 8175 8178 8180 8189 8192 8187 8189 8199 8199 8200 8205 8201 8201 8204 8203 8204 8203 8204 8197 8204 8204 8205 8208 8207 8211 8210 8206 8206 8209 8208 8209 8208 8208 8209 8212 8211 8212 8212
spend time: 8218
简单格式的花费时间是四种里最长的，看来线程的创建开销不容忽视。但是令我惊讶的是在默认格式的测试中，多线程异步并没有提升很多，而且相比多线程同步的3s时间还要慢不少，这点我也不是很明白。
2万+
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
