logback异步打印日志

转载

mb600beb5e8f23b 2021-01-28 21:14:22

文章标签 logback 文章分类 后端开发

背景

生产环境，运营系统发现很慢，打开一个页面要好几秒，

怎么知道耗时好几秒？浏览器的调试模式可以看到，而且可以看到是哪个请求耗时好几秒。

具体原因是打印日志太多，导致耗时太久。是什么日志呢？查组织机构的数据，总共100万字。

本质原因是因为没有异步打印，是同步打印，然后日志太多，导致好久太久。之前也配置了异步打印，但是配置的有点问题。

那怎么实现异步打印日志？

首先第一步，怎么使用？按下面的方式，通过日志名字获取到对应的日志记录器。

private static final Logger logger = LoggerFactory.getLogger("dubbo.accesslog"); //同步打印日志
private static final Logger logger_async = LoggerFactory.getLogger("dubbo.accesslog.asnyc"); //异步打印日志复制代码

日志名字对应的日志记录器在哪里？在配置文件logback.xml里配置。

<appender name="INFO_FILE"
 class="xxx.log.logback.appender.ExtRollingFileAppender">
 <file>${logback.logpath}/info.log</file>
 <!-- see https://logback.qos.ch/manual/filters.html -->
 <filter class="ch.qos.logback.classic.filter.LevelFilter">
  <level>INFO</level>
  <onMatch>ACCEPT</onMatch>
  <onMismatch>DENY</onMismatch>
 </filter>
 <!-- see https://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedFNATP -->
 <rollingPolicy
  class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
  <fileNamePattern>${logback.logpath}/info.%d{yyyyMMdd}.%i.log
  </fileNamePattern>
  <maxFileSize>${logback.maxFileSize}</maxFileSize>
 </rollingPolicy>
 <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
  <!-- see https://logback.qos.ch/manual/layouts.html -->
  <layout class="xxx.log.logback.layout.ExtLayout">
   <pattern>${logback.pattern}</pattern>
   <charset>${logback.encoding}</charset>
  </layout>
 </encoder>
</appender>

<appender name="ERROR_FILE"
 class="xxx.log.logback.appender.ExtRollingFileAppender">
 <file>${logback.logpath}/error.log</file>
 <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
  <level>WARN</level>
 </filter>
 <rollingPolicy
  class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
  <fileNamePattern>${logback.logpath}/error.%d{yyyyMMdd}.%i.log
  </fileNamePattern>
  <maxFileSize>${logback.maxFileSize}</maxFileSize>
 </rollingPolicy>
 <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
  <layout class="xxx.log.logback.layout.ExtLayout">
   <pattern>${logback.pattern.error}</pattern>
   <charset>${logback.encoding}</charset>
  </layout>
 </encoder>
</appender>

<!-- 设置控制台日志 -->
<appender name="stdout" class="xxx.log.logback.appender.ExtConsoleAppender">
 <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
  <layout class="xxx.log.logback.layout.ExtLayout">
   <pattern>${logback.pattern}</pattern>
   <charset>${logback.encoding}</charset>
  </layout>
 </encoder>
</appender>

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender"> //异步打印日志
 <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
 <discardingThreshold>0</discardingThreshold>
 <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
 <queueSize>512</queueSize>
 <!-- 添加附加的appender,最多只能添加一个 -->
 <appender-ref ref="INFO_FILE"/>
</appender>



<logger name="dubbo.accesslog" additivity="false"> //同步打印日志
 <level value="info"/>
 <appender-ref ref="INFO_FILE"/>
</logger>

<!-- 异步日志 -->
<logger name="dubbo.accesslog.asnyc" additivity="false"> //异步打印日志
 <level value="info"/>
 <appender-ref ref="ASYNC"/>
</logger>

<root level="${logback.rootLoggerLevel}">
  <appender-ref ref="DEBUG_FILE" />
  <appender-ref ref="INFO_FILE" />
  <appender-ref ref="ERROR_FILE" />
  <!-- 控制台日志放在最后解析 -->
  <appender-ref ref="stdout" />
 </root>
</configuration>  

复制代码

源码分析

结论

首先说结论
1.默认是同步打印日志，就不会走异步打印
2.配置了异步打印日志，才会走异步打印

类继承图

然后再看一下类继承图 logback异步打印日志_logback

1.默认是同步，就用同步日志记录器打印日志
2.如果配置了异步，并且使用的时候也是用的异步，那么就用异步日志记录器打印日志

源码

UnsynchronizedAppenderBase

/**
 * Similar to AppenderBase except that derived appenders need to handle 
 * thread synchronization on their own.
 * 
 * @author Ceki G&uuml;lc&uuml;
 * @author Ralph Goers
 */
abstract public class UnsynchronizedAppenderBase<E> extends ContextAwareBase implements Appender<E> {

public void doAppend(E eventObject) {
    // WARNING: The guard check MUST be the first statement in the
    // doAppend() method.

    // prevent re-entry.
    if (Boolean.TRUE.equals(guard.get())) {
        return;
    }

    try {
        guard.set(Boolean.TRUE);

        if (!this.started) {
            if (statusRepeatCount++ < ALLOWED_REPEATS) {
                addStatus(new WarnStatus("Attempted to append to non started appender [" + name + "].", this));
            }
            return;
        }

        if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
            return;
        }

        // ok, we now invoke derived class' implementation of append
        this.append(eventObject); //异步打印日志

    } catch (Exception e) {
        if (exceptionCount++ < ALLOWED_REPEATS) {
            addError("Appender [" + name + "] failed to append.", e);
        }
    } finally {
        guard.set(Boolean.FALSE);
    }
}复制代码

AsyncAppenderBase

1.日志生产者
先把日志暂存起来，放到集合里。

/**
 * This appender and derived classes, log events asynchronously.  In order to avoid loss of logging events, this
 * appender should be closed. It is the user's  responsibility to close appenders, typically at the end of the
 * application lifecycle.
 * <p/>
 * This appender buffers events in a {@link BlockingQueue}. {@link Worker} thread created by this appender takes
 * events from the head of the queue, and dispatches them to the single appender attached to this appender.
 * <p/>
 * <p>Please refer to the <a href="http://logback.qos.ch/manual/appenders.html#AsyncAppender">logback manual</a> for
 * further information about this appender.</p>
 *
 * @param <E>
 * @author Ceki G&uuml;lc&uuml;
 * @author Torsten Juergeleit
 * @since 1.0.4
 */
public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {

@Override
protected void append(E eventObject) {
    if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
        return;
    }
    preprocess(eventObject);
    put(eventObject); //把日志先暂存起来，放到集合里去
}

private void put(E eventObject) {
    if (neverBlock) {
        blockingQueue.offer(eventObject); //把日志先暂存起来，放到集合里去
    } else {
        putUninterruptibly(eventObject);
    }
}复制代码

2.日志消费者
然后再慢慢消费，异步消费，消费线程是独立的线程。

class Worker extends Thread {

    public void run() {
        AsyncAppenderBase<E> parent = AsyncAppenderBase.this;
        AppenderAttachableImpl<E> aai = parent.aai;

        // loop while the parent is started
        while (parent.isStarted()) {
            try {
                E e = parent.blockingQueue.take(); //把日志取出来消费掉
                aai.appendLoopOnAppenders(e);
            } catch (InterruptedException ie) {
                break;
            }
        }

        addInfo("Worker thread will flush remaining events before exiting. ");

        for (E e : parent.blockingQueue) {
            aai.appendLoopOnAppenders(e);
            parent.blockingQueue.remove(e);
        }

        aai.detachAndStopAllAppenders();
    }
}复制代码

调用栈

核心流程
1.应用程序调用日志记录器打印日志
用哪个日志级别打印日志？

2.找到用哪个日志记录器
是同步还是异步？

3.用同步appender还是异步appender？
如果是异步，就用异步appender打印；
如果是同步，就用同步appender打印。

异步打印日志的完整方法调用栈

append:157, AsyncAppenderBase (ch.qos.logback.core) //异步打印日志
doAppend:84, UnsynchronizedAppenderBase (ch.qos.logback.core) //用异步appender还是同步appender来打印日志？这里是用异步appender来打印日志。

appendLoopOnAppenders:51, AppenderAttachableImpl (ch.qos.logback.core.spi) //1.如果是4个同步appender，都不走异步 2.如果是异步，才走异步 。
appendLoopOnAppenders:270, Logger (ch.qos.logback.classic)
callAppenders:257, Logger (ch.qos.logback.classic)
buildLoggingEventAndAppend:421, Logger (ch.qos.logback.classic)
filterAndLog_0_Or3Plus:383, Logger (ch.qos.logback.classic)
info:579, Logger (ch.qos.logback.classic) //用哪个日志级别？这里是info日志级别。

invoke:197, AccessLogExtFilter (xxx.xxx.common.filter.dubbo) //应用程序层

invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:82, CatTransaction (com.xxx.log.rpc.dubbo)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:49, ConsumerContextFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:56, InvokerWrapper (com.alibaba.dubbo.rpc.protocol)
doInvoke:78, FailoverClusterInvoker (com.alibaba.dubbo.rpc.cluster.support)
invoke:244, AbstractClusterInvoker (com.alibaba.dubbo.rpc.cluster.support)
invoke:75, MockClusterInvoker (com.alibaba.dubbo.rpc.cluster.support.wrapper)
invoke:52, InvokerInvocationHandler (com.alibaba.dubbo.rpc.proxy)
decryptByType:-1, proxy18 (com.alibaba.dubbo.common.bytecode)
decryptByType:193, CipherServiceImpl (xxx.xxx.register.component.cipher)
decryptAddress:252, CipherServiceImpl (xxx.xxx.register.component.cipher)
decryptMerc:134, xxxMerQueryServer (xxx.xxx.register.remoteserver.impl)
getUrmtminf:97, xxxMerQueryServer (xxx.xxx.register.remoteserver.impl)
queryMerchantInfo:74, xxxMerQueryServer (xxx.xxx.register.remoteserver.impl)
invokeMethod:-1, Wrapper28 (com.alibaba.dubbo.common.bytecode)
doInvoke:47, JavassistProxyFactory$1 (com.alibaba.dubbo.rpc.proxy.javassist)
invoke:76, AbstractProxyInvoker (com.alibaba.dubbo.rpc.proxy)
invoke:52, DelegateProviderMetaDataInvoker (com.alibaba.dubbo.config.invoker)
invoke:56, InvokerWrapper (com.alibaba.dubbo.rpc.protocol)
invoke:11, AppNameAppendFilter (com.xxx.log.rpc.dubbo)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:62, ExceptionFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:42, TimeoutFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:60, ExecuteLimitFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:75, MonitorFilter (com.alibaba.dubbo.monitor.support)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:78, TraceFilter (com.alibaba.dubbo.rpc.protocol.dubbo.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:85, AccessLogExtFilter (xxx.xxx.common.filter.dubbo)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:82, CatTransaction (com.xxx.log.rpc.dubbo)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:73, ContextFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:138, GenericFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:38, ClassLoaderFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:38, EchoFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
reply:104, DubboProtocol$1 (com.alibaba.dubbo.rpc.protocol.dubbo)
handleRequest:96, HeaderExchangeHandler (com.alibaba.dubbo.remoting.exchange.support.header)
received:173, HeaderExchangeHandler (com.alibaba.dubbo.remoting.exchange.support.header)
received:51, DecodeHandler (com.alibaba.dubbo.remoting.transport)
run:57, ChannelEventRunnable (com.alibaba.dubbo.remoting.transport.dispatcher)
runWorker:1145, ThreadPoolExecutor (java.util.concurrent)
run:615, ThreadPoolExecutor$Worker (java.util.concurrent)
run:745, Thread (java.lang)复制代码

在idea里看方法调用栈 logback异步打印日志_logback_02