守护线程在logback中的使用 - 论基础知识的重要性

守护线程在logback中的使用

先说问题,在java应用中,logback的异步Appender是怎么在主线程结束后,停下来的?

复盘

我在一个logback的测试用例中,写了这样的代码和logback的配置:

// 一个测试类,main函数中简单的打印了几行日志
public class Test {

    private static final Logger LOGGER = LoggerFactory.getLogger(Test.class);

    public static void main(String[] args) {
        LOGGER.info("test log 1");
        LOGGER.info("test log 2");
    }

}

这是我使用的logback的配置,为root-logger配置了两个appender,一个是ConsoleAppender,会将日志内容输出到控制台中,另一个是套在AsyncAppender中的FileAppender,它采用异步的方式将日志内容输出到文件中

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>/usr/local/test.log</file>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="FILE" />
    </appender>
    <root level="debug">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="ASYNC"/>
    </root>
</configuration>

当我正常执行Test.main(),观察控制台和文件中都正常输出了日志。然后,为了观察AsyncAppender的原理,我在AsyncAppender的父类AsyncAppenderBase中,看了一下大致的原理:AsyncAppenderBasestart()方法中,调用了worker.start(),其实就是启动了一个线程。截取Worker.run()方法中比较重要的代码,就是在一个while循环中,从阻塞队列获取ILoggerEvent,我在这里打了断点,希望追进具体的Appender中看一下

while (parent.isStarted()) {
    try {
    	E e = parent.blockingQueue.take();
        // 这里打了断点
    	aai.appendLoopOnAppenders(e);
    } catch (InterruptedException ie) {
    	break;
    }
}

当执行到断点处,观察了一会儿变量后,点击步进,突然发现整个java应用结束了。没有任何异常发生。这种情况我重试了很多次,不一定在断点处结束,可能再往下几步,但是debug模式下,java应用一定会在某个点毫无征兆的“正常结束”

我当时去确认了一下,控制台中两行日志都打印了出来,这说明主线程一定执行完了,但是我当时的知识储备是,java主线程结束时,如果子线程没有结束,那么会等待子线程结束后,JVM才会执行最后的结束任务。(这里完全不记得守护线程的概念)

!!!上面这个结论是错误的

然后就想通过jstack来观测一下,当main-Thread结束后,线程到底是什么情况:

这里发现:

DestroyJavaVM线程居然处于RUNNABLE阶段,可是还有子线程在执行啊,为什么它就开始了

带着疑问再看一下AsyncAppender-Worker-ASYNC线程,这就是异步日志打印任务的线程了,也是RUNNABLE状态,但是它好像是一个守护线程(daemon),这才想起来java线程的基础知识,用户线程守护线程,这里直接贴出来ThreadsetDaemon方法,代码注释中说:标记该线程为user thread或daemon thread,JVM只会在当前运行的线程,全部都是daemon thread时,才会结束。

再看看AsyncAppenderBase中的start()方法:

可以看到,它将worker指定为了daemon线程,问题到这里其实也就解决了。

结论

这次碰到的问题,其实并不复杂,主要还是知识储备的问题

java多线程中,用户线程和守护线程在能力上并没有什么区别,最重要的区别是当JVM退出时,如果还有存活的用户线程,则不会退出;如果只剩下守护线程了,那么JVM则会杀掉所有的守护线程,并退出。

PS:
没人知道我DEBUG了多久。。。简直超出认知范围了!!!差点以为是玄学

posted @ 2019-11-25 15:48  大地的谎言  阅读(...)  评论(...编辑  收藏