当 Logback 的 AsyncAppender 崩溃时，排队的消息会发生什么情况？

Question

使用Logback的AsyncAppender时，消息会在它们之前排队写入其最终目的地(取决于哪个Appender你用AsyncAppender包裹)。到目前为止还不错。

当我的程序或logback本身崩溃时，这些排队的消息可能会丢失吗？

Answer 1

是的，我认为当JVM崩溃甚至正常程序关闭时，排队的消息会丢失。

我在调查使用AsyncAppender时能缩短多少时间。

示例logback.xml：
我有一个普通的FILE_LOG和ASYNC_FILE_LOG。

<appender name="FILE0" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>./file.log</file>
... (not relevant)
</appender>
<appender name="FILE1" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>./async_file.log</file>
... (not relevant)
</appender>
<appender name="ASYNC_FILE1" class="ch.qos.logback.classic.AsyncAppender">
<appender-ref ref="FILE1" />
<discardingThreshold>0</discardingThreshold>
</appender>
<logger name="FILE_LOG" additivity="false">
<appender-ref ref="FILE0" />
</logger>
<logger name="ASYNC_FILE_LOG" additivity="false">
<appender-ref ref="ASYNC_FILE1" />
</logger>

示例MultiThreadsExecution测试程序，它应该生成1010行日志消息：

import java.util.concurrent.CountDownLatch;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class MultiThreadsExecutor {
private static final Logger asyncLOGGER = LoggerFactory.getLogger("ASYNC_FILE_LOG");
private static final Logger normaLOGGER = LoggerFactory.getLogger("FILE_LOG");
static CountDownLatch latch = null; // Java7 feature to ensure all threads ended execution.
public MultiThreadsExecutor() {
}
public void someMethod(String who, String loggerName) {
Thread backgroundThread = new Thread(new Runnable() {
public void run() {
getLogger(loggerName).warn(Thread.currentThread().getName() +": is Running in the background");
for (int i=0; i<100; i++) {
getLogger(loggerName).info(Thread.currentThread().getName() +" counting: " + i);
}
latch.countDown();
}
},"Background " + who + " Thread");
backgroundThread.start();
}
private Logger getLogger(String name) {
if (name.equals("ASYNC_FILE_LOG")) {
return asyncLOGGER;
} else if (name.equals("FILE_LOG")) {
return normaLOGGER;
} else {
System.out.println("Logger Undefined");
return null;
}
}
public static void main(String[] args) {
long start;
MultiThreadsExecutor mte = new MultiThreadsExecutor();
latch = new CountDownLatch(10);
start = System.currentTimeMillis();
for (int i=0; i<10; i++) {
mte.someMethod(Integer.toString(i)," FILE_LOG");
}
try {
latch.await();
System.out.println("FILE_LOG ended - " + (System.currentTimeMillis() - start));
} catch (InterruptedException e) {
e.printStackTrace();
}
latch = new CountDownLatch(10);
start = System.currentTimeMillis();
for (int i=0; i<10; i++) {
mte.someMethod(Integer.toString(i)," ASYNC_FILE_LOG");
}
try {
latch.await();
System.out.println("ASYNC_FILE_LOG ended - " + (System.currentTimeMillis() - start));
} catch (InterruptedException e) {
e.printStackTrace();
}
// Remove below to enable Testcase(2)
// try { Thread.sleep(1000); } catch (InterruptedException e) { e.printStackTrace(); }
System.out.println("END");
}
}

测试用例(1)正常执行

FILE_LOG已结束-46
ASYNC_FILE_LOG结束-16
结束

ASYNC_FILE_LOG确实快得多。然而

File.log正确记录了1010行消息：

line1 Background 1 Thread: is Running in the background
line2 Background 3 Thread: is Running in the background
line3 Background 6 Thread: is Running in the background
line4 Background 8 Thread: is Running in the background
...
line1009 Background 0 Thread counting: 99
line1010 Background 8 Thread counting: 99

Async_File.log最多只记录800多条消息！

line1 Background 0 Thread: is Running in the background
line2 Background 1 Thread: is Running in the background
line3 Background 1 Thread counting: 0
line4 Background 1 Thread counting: 1
line5 Background 1 Thread counting: 2
....
line811 Background 2 Thread counting: 95
line812 Background 4 Thread counting: 66
line813 Background 8 Thread counting: 46

测试用例(2)，测试人员在END前1秒睡眠，以防AsyncAppender需要时间清除队列

FILE_LOG结束-47
ASYNC_FILE_LOG已结束-16
结束

ASYNC_FILE_LOG仍然更快。这一次，ASYNC_FILE_LOG正确记录了1010行。

line1 Background 0 Thread: is Running in the background
line2 Background 2 Thread: is Running in the background
line3 Background 2 Thread counting: 0
line4 Background 2 Thread counting: 1
line5 Background 2 Thread counting: 2
....
line1008 Background 5 Thread counting: 97
line1009 Background 5 Thread counting: 98
line1010 Background 5 Thread counting: 99

结论

上述测试证明，当Java程序关闭时，AsyncAppender没有足够的时间清除日志队列。更不用说JVM崩溃了，Java程序的退出是即时的。