java - 当 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>

示例MultiThreadsExecutor测试程序，它应该生成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 ended - 46
ASYNC_FILE_LOG ended - 16
END

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 之前 hibernate 1 秒，以防 AsyncAppender 需要时间清除队列...

FILE_LOG ended - 47
ASYNC_FILE_LOG ended - 16
END

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 程序立即退出。