Logback性能提升技巧：AsyncAppender与FileAppender的优化实战

导读

cache vs buffer

在系统设计中通常会有cache 及 buffer的设计：

• cache ：设备之间有速度差，高速设备访问低速设备会造成高速设备等待，导致使用率降低，为了减少低速设备对高速设备的影响，在两者之间加入cache，通过加快访问速度，以提升高速设备的使用效率。
• buffer ：通俗来说就是化零为整，把少量多次变成多量少次；具体来说就是进行流量整形，把突发的大数量较小规模的 I/O 整理成平稳的小数量较大规模的 I/O，以减少响应次数

FileAppender AsyncAppender 概述

FileAppender 属于buffer级的方案
AsyncAppender 属于cache级的方案

• FileAppender 内部有缓存buffer，buffer读写都加锁，从buffer写盘 与 log写buffer 会串行，产生RT变长的性能问题。

  
  
  

  image.png

原理简析：
FileAppender内部使用BufferedOutputStream ， BufferedOutputStream的 OutputStream 是 FileOutputStream；
通过BufferedOutputStream写文件的逻辑：

1. 调用write方法，因为缓存大小有限，所以能写缓存就写缓存，如果缓存容不下，就直接写入其内部的OutputStream中。
2. 如果希望缓存不满的情况下也能够立即写入到OutputStream 中，那么久调用flush方法。

简单的总结这两种情况：

1. 自动写：缓存满了（空间不足）直接写入OutputStream
2. 手动写：调用flush方法，强制将缓存数据写入OutputStream中；
   如果是定时手动写，要留意进程退出前 是否有日志尚在buffer中未落盘。

• AsyncAppender
  
  

  image.png
  
  AsyncAppender关注的重点在于高并发下，把日志写盘 变成 日志写内存，减少写日志的RT。
  原理简析：
  appender 之间构成链，AsyncAppender 接收日志，放入其内部的一个阻塞队列，专开一个线程从阻塞队列中取数据（每次一个）丢给链路下游的appender（如 FileAppender);

继承关系

AsyncAppender

FileAppender

同步的 RollingFileAppender

RollingFileAppender 继承关系：RollingFileAppender -> FileAppender -> OutputStreamAppender -> UnsynchronizedAppenderBase，OutputStreamAppender 中的 append 方法调用了 subAppend 方法，subAppend 又调用了 writeOut 方法，writeOut 又调用了 LayoutWrappingEncoder 的 doEncode 方法，在 doEncode 方法中调用了 outputStream 的 write 方法，并且判断 immediateFlush 为 true 的话，则立即 flush

public class RollingFileAppender<E> extends FileAppender<E> { }
public class FileAppender<E> extends OutputStreamAppender<E> { }
public class OutputStreamAppender<E> extends UnsynchronizedAppenderBase<E> {
  @Override
  protected void append(E eventObject) {
    if (!isStarted()) {
      return;
    }

    subAppend(eventObject);
  }
  protected void subAppend(E event) {
    // 省略其他不重要的代码
      lock.lock();
      try {
        writeOut(event);
      } finally {
        lock.unlock();
      }
  }  
  protected void writeOut(E event) throws IOException {
    // setLayout 方法中设置了 encoder = new LayoutWrappingEncoder<E>();
    this.encoder.doEncode(event);
  }  
}  
public class LayoutWrappingEncoder<E> extends EncoderBase<E> {
  public void doEncode(E event) throws IOException {
    String txt = layout.doLayout(event);
    outputStream.write(convertToBytes(txt));
    if (immediateFlush)
      outputStream.flush();
  }  
}  

再看代码追查一下 outputStream 的真实类型，FileAppender 是直接将日志输出到文件中，初始化了一个 ResilientFileOutputStream，其内部使用的是带缓冲的 BufferedOutputStream，然后调用超类的 setOutputStream 方法设置输出流，最终调用 encoder.init 方法将输出流对象赋值给了 outputStream。

public class FileAppender<E> extends OutputStreamAppender<E> {
    public void openFile(String file_name) throws IOException {
        LogbackLock var2 = this.lock;
        synchronized(this.lock) {
            File file = new File(file_name);
            // 如果日志文件所在的文件夹还不存在，就创建之
            if(FileUtil.isParentDirectoryCreationRequired(file)) {
                boolean resilientFos = FileUtil.createMissingParentDirectories(file);
                if(!resilientFos) {
                    this.addError("Failed to create parent directories for [" + file.getAbsolutePath() + "]");
                }
            }

            ResilientFileOutputStream resilientFos1 = new ResilientFileOutputStream(file, this.append);
            resilientFos1.setContext(this.context);
            // 调用父类的 setOutputStream 方法
            this.setOutputStream(resilientFos1);
        }
    }
}

public class ResilientFileOutputStream extends ResilientOutputStreamBase {
    private File file;
    private FileOutputStream fos;

    public ResilientFileOutputStream(File file, boolean append) throws FileNotFoundException {
        this.file = file;
        this.fos = new FileOutputStream(file, append);
        // OutputStream os 在超类 ResilientOutputStreamBase 里
        this.os = new BufferedOutputStream(this.fos);
        this.presumedClean = true;
    }
}    

public class OutputStreamAppender<E> extends UnsynchronizedAppenderBase<E> {
  private OutputStream outputStream;    
  protected Encoder<E> encoder;
  public void setOutputStream(OutputStream outputStream) {
    lock.lock();
    try {
      // close any previously opened output stream
      closeOutputStream();
      encoderInit();
    } finally {
      lock.unlock();
    }
  } 
  // 将 outputStream 送入 encoder
  void encoderInit() {
    encoder.init(outputStream);
  }  
}   

异步的 AsyncAppender

AsyncAppender 的继承关系是：AsyncAppender -> AsyncAppenderBase -> UnsynchronizedAppenderBase，AsyncAppenderBase 中 append 方法实现如下：

public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {
  BlockingQueue<E> blockingQueue = new ArrayBlockingQueue<E>(queueSize);
  @Override
  protected void append(E eventObject) {
    // 如果队列满，并且允许丢弃，则直接 return
    if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {
      return;
    }
    preprocess(eventObject);
    put(eventObject);
  }
  private void put(E eventObject) {
    try {
      blockingQueue.put(eventObject);
    } catch (InterruptedException e) {
    }
  }  
}  

append 方法是把日志对象放到了阻塞队列 ArrayBlockingQueue 中。

discardingThreshold是一个阈值，通过下面代码看他的作用：

当队列的剩余容量小于这个阈值并且当前日志level TRACE, DEBUG or INFO ，则丢弃这些日志。

在压测时候代码配置如上，也就是配置了异步日志，但是还是出现了线程阻塞在打日志的地方了，经查看是阻塞到了日志队列ArrayBlockingQueue的put方法：

可知put方法在队列满时候会挂起当前线程。那么如何解那？
上面介绍了discardingThreshold，可知本文设置为0说明永远不会丢弃日志level TRACE, DEBUG or INFO的日志，只要discardingThreshold>0则当队列快满时候level TRACE, DEBUG or INFO的日志就会丢弃掉，这个貌似可以解决问题。但是如果打印的是warn级别的日志那？还是会在put的时候阻塞。

通过看代码发现最终写日志时候有个判断：

如果设置了neverBlock=true则写日志队列时候会调用ArrayBlockingQueue对的offer方法而不是put,而offer是非阻塞的：

可知如果队列满则直接返回，而不是被挂起当前线程（当队列满了，put阻塞，等有了再加，add直接报错，offer返回状态）
所以配置异步appender时候如下：

<appender name ="asyncFileAppender" class= "ch.qos.logback.classic.AsyncAppender">
        <!-- 如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
        <discardingThreshold >20</discardingThreshold>
        <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
        <queueSize>512</queueSize>
        <!-- 队列满了不阻塞调用者-->
        <neverBlock>true</neverBlock>
        <!-- 添加附加的appender,最多只能添加一个 -->
        <appender-ref ref ="file"/>
    </appender>


    <springProfile name="default,dev">
        <root level="info">
            <appender-ref ref="consoleWithSwitch"/>
            <appender-ref ref="asyncFileAppender"/>
        </root>
    </springProfile>
    <springProfile name="pro,prd,stg,test,uat,fit,fat,sit">
        <root level="info">
            <!--<appender-ref ref="consoleWithSwitch"/>-->
            <appender-ref ref="catAppender"/>
            <appender-ref ref="asyncFileAppender"/>
        </root>
    </springProfile>

那么何时把队列中的数据存入日志文件呢？AsyncAppenderBase 中有一个 Worker 对象，负责从队列中取数据并调用 AppenderAttachableImpl 来处理：（这里一次只取一个进行追加的方式，效率有点低啊）

    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);
      }

      aai.detachAndStopAllAppenders();
    }
  }

这里的 AppenderAttachableImpl 也就是 logback.xml 里配置的 appender-ref 对象：

测试demo

package com.zto.titans.test.logging.commandLineRunner;

import org.elasticsearch.common.StopWatch;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.CommandLineRunner;
import org.springframework.stereotype.Component;

import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

/**
 * @Author: zs
 * @Description: 测试日志写入级别以及验证动态日志,在console,logFile,cat中的显示以及存储情况,用例查看测试logging测试用例文档
 * 1.环境 default,dev,fat  vm参数:-Denv=*** -Dspring.profiles.active=***
 * 2.日志级别 default/dev root=info ; fat/pro : root= error ,vm参数控制日志级别 -Dlogging.level.root = debug
 * 3.动态日志级别 apollo中动态配置logging.levle.root
 * @Date: Created in 10:26) 2019-04-29
 * @Modified By
 */
@Component
public class LogPerformanceRunner implements CommandLineRunner {

    private Logger logger = LoggerFactory.getLogger(LogPerformanceRunner.class);
    private String getDtStr(){
        return LocalDateTime.now().format(DateTimeFormatter.ISO_LOCAL_DATE_TIME);
    }

    /**
     *
     */
    @Override
    public void run(String... args) throws Exception {

        String logStr = "#####OutputStream\n" +
                "OutputStream类是抽象类，其方法几乎什么也没做，write和flush都没有实际的动作。\n" +
                "\n" +
                "#####FileOutputStream\n" +
                "直接使用其写文件，没有必要调用flush()，其flush方法是继承父类`OutputStream#flush`，也是空；其write方法是native方法，直接写盘。\n" +
                "\n" +
                "#####BufferedOutputStream\n" +
                "* 所谓的buffer其实就是一个byte[]。\n" +
                "* 所谓的 OutputStream 是在其构造函数中传入的。\n" +
                "简单理解是 数据先写入 buffer中，再从buffer中写到OutputStream中，举个场景 添加buffer缓存，避免每次写入操作都要写盘：\n" +
                "```\n" +
                "FileOutputStream fos = new FileOutputStream(\"c:\\a.txt\");\n" +
                "BufferedOutputStream bos = new BufferedOutputStream(fos);\n" +
                "```\n" +
                "BufferedOutputStream 的 OutputStream 是  FileOutputStream；\n" +
                "通过BufferedOutputStream写文件的逻辑：\n" +
                "1.  调用write方法，因为缓存大小有限，所以能写缓存就写缓存，如果缓存容不下，就直接写入其内部的OutputStream中。\n" +
                "2.  如果希望缓存不满的情况下也能够立即写入到OutputStream 中，那么久调用flush方法。\n" +
                "\n" +
                "简单的总结这两种情况：\n" +
                "1.  自动写：缓存满了（空间不足）直接写入OutputStream\n" +
                "2.  手动写：调用flush方法，强制将缓存数据写入OutputStream中。\n" +
                "\n" +
                "自动写的源码：\n" +
                "```\n" +
                "   public synchronized void write(byte b[], int off, int len) throws IOException {\n" +
                "        //buffer小，直接写outputStream\n" +
                "        if (len >= buf.length) {\n" +
                "            //先把缓存里的写入outputStream\n" +
                "            flushBuffer();\n" +
                "            //把新数据直接写入outputStream\n" +
                "            out.write(b, off, len);\n" +
                "            return;\n" +
                "        }\n" +
                "        //buffer小，直接写outputStream\n" +
                "        if (len > buf.length - count) {\n" +
                "            flushBuffer();\n" +
                "        }\n" +
                "        //先写入缓存中\n" +
                "        System.arraycopy(b, off, buf, count, len);\n" +
                "        count += len;\n" +
                "    }\n" +
                "```\n" +
                "\n" +
                "flush的源码：\n" +
                "```\n" +
                "    public synchronized void flush() throws IOException {\n" +
                "        flushBuffer();\n" +
                "        out.flush();\n" +
                "    }\n" +
                "\n" +
                "    /** Flush the internal buffer */\n" +
                "    private void flushBuffer() throws IOException {\n" +
                "        if (count > 0) {\n" +
                "            out.write(buf, 0, count);\n" +
                "            count = 0;\n" +
                "        }\n" +
                "    }\n" +
                "```\n" +
                "\n" +
                "\n" +
                "\n";

        ExecutorService executorService = Executors.newFixedThreadPool(100);
        int ncount  = 100 * 10000;
        CountDownLatch countDownLatch = new CountDownLatch(ncount);
        StopWatch stopWatch = new StopWatch();
        stopWatch.start();

        for(int i =0;i<ncount;i++)
            executorService.submit(()-> {
                StopWatch stopWatch1 = new StopWatch();
                stopWatch1.start();
                    String dtStr = getDtStr();
                    logger.debug("debug:at->{}", logStr);
                    logger.info("info:at->{}", logStr);
                    logger.warn("warn:at->{}", logStr);
                    logger.error("error:at->{}", logStr);
                    logger.error("throwableError:at->" + dtStr, new Exception("testLogging"));
                countDownLatch.countDown();
                stopWatch1.stop();
                if(stopWatch1.totalTime().millis() > 1000)
                    System.out.println(stopWatch1.totalTime().millis());
            });

        countDownLatch.await();
        //executorService.awaitTermination();
        stopWatch.stop();
        long seconds = stopWatch.totalTime().seconds();
        System.out.println(seconds);
        executorService.shutdown();

    }
}

---

logback.xml immediate=false 到底缓存空间是多大
异步记录日志
logback性能调优测试
Java 日志框架解析：设计模式、性能
Log4j的AsyncAppender能否提升性能？什么场景用比较好？
http://www.logback.cn/04章Appenders 介绍了各种Appenders
SpringBoot2.0学习笔记：(四) Spring Boot的日志详解
AsyncAppender异步打印日志
异步打印日志的一点事
log4j2异步日志解读（一）AsyncAppender
logback 常用配置（详解）
https://www.cnblogs.com/vandusty/p/11397619.html