logback异步输出日志详解

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: logback异步输出日志详解

前言


logback应该是目前最流行的日志打印框架了,毕竟Spring Boot中默认的集成的日志框架也是logback。在实际项目开发过程中,常常会遇到由于打印大量日志而导致程序并发降低,QPS降低的问题,而通过logback异步日志输出则能很大程度上解决这个问题。


一、什么是Appender?


logback官方文档:https://logback.qos.ch/manual/appenders.html


logback中文文档


官方介绍:

101.png


Logback 将编写日志事件的任务委托给名为 Appenders 的组件,Appenders 必须实现ch.qos.logback.core.Appender的接口。

简单来说,Appender就是用来处理logback框架下日志输出事件的组件。


Appender接口的核心方法如下:

package ch.qos.logback.core;
import ch.qos.logback.core.spi.ContextAware;
import ch.qos.logback.core.spi.FilterAttachable;
import ch.qos.logback.core.spi.LifeCycle;
public interface Appender<E> extends LifeCycle, ContextAware, FilterAttachable {
  public String getName();
  public void setName(String name);
 //核心方法:处理日志事件
  void doAppend(E event);
}

其中doAppend()方法是 logback 框架中最重要的方法。它负责将日志事件以适当的格式输出到适当的输出设备。


二、Appender类图


100.png

说明:

OutputStreamAppender 是另外三个附加程序的超类,即 ConsoleAppender 和 FileAppender,后者又是 RollingFileAppender 的超类。下一个图说明了 OutputStreamAppender 及其子类的类图。


1、控制台日志输出 ConsoleAppender

配置示例:

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n</pattern>
    </encoder>
  </appender>
  <root level="DEBUG">
       <appender-ref ref="STDOUT" />
  </root>
  </configuration>


说明:

控制台日志输出主要是在开发环境采用,比如在IDEA中开发时,可以清楚直观得在控制台看到运行日志,更方便程序调试。当应用发布到测试环境、生产环境时,建议关闭控制台日志输出,以提高日志输出的吞吐量,减少不必要的性能开销。


2、单日志文件输出 FileAppender

配置示例:

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <!-- 日志文件名称 -->
    <file>testFile.log</file>
    <!-- 是否追加输出 -->
    <append>true</append>
    <!-- 立即刷新,设置成false可以提高日志吞吐量 -->
    <immediateFlush>true</immediateFlush>
    <encoder>
     <!-- 日志输出格式 -->
      <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
    </encoder>
  </appender>
  <root level="DEBUG">
    <appender-ref ref="FILE" />
  </root>
</configuration>


弊端:

采用单日志文件输出日志,很容易导致日志文件的体积一直膨胀,不利于日志文件的管理和查看。一般很少采用。


3、滚动日志文件输出 RollingFileAppender

配置示例:

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <!-- 日志文件名称 -->
    <file>logFile.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- 按天滚动生成历史日志文件 -->
      <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
      <!-- 历史日志文件保存的天数和容量大小-->
      <maxHistory>30</maxHistory>
      <totalSizeCap>3GB</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
    </encoder>
  </appender> 
  <root level="DEBUG">
    <appender-ref ref="FILE" />
  </root>
</configuration>


说明:

通过rollingPolicy 配置日志文件的滚动生成策略,以及历史日志文件保存的天数和总容量大小,

是测试环境和生产环境最推荐的日志输出方式。


三、同步输出和异步输出比较


同步输出

传统的日志打印采用的是同步输出的方式,所谓同步日志,即当输出日志时,必须等待日志输出语句执行完毕后,才能执行后面的业务逻辑语句。

使用logback的同步日志进行日志输出,日志输出语句与程序的业务逻辑语句将在同一个线程运行。在高并发场景下,日志数量不但激增,作为磁盘IO来说,容易产生瓶颈,导致线程卡顿在生成日志过程中,会影响程序后续的主业务,降低程序的性能。

99.png


异步输出

使用异步日志进行输出时,日志输出语句与业务逻辑语句并不是在同一个线程中运行,而是有专门的线程用于进行日志输出操作,处理业务逻辑的主线程不用等待即可执行后续业务逻辑。这样即使日志没有完成输出,也不会影响程序的主业务,从而提高了程序的性能。

98.png



四、异步日志实现原理AsyncAppender


logback异步输出日志是通过AsyncAppender实现的。AsyncAppender可以异步的记录 ILoggingEvents日志事件。

但是这里需要注意,AsyncAppender只充当事件分配器,它必须引用另一个Appender才能完成最终的日志输出。


示意图:

97.png

Logback的异步输出采用生产者消费者的模式,将生成的日志放入消息队列中,并将创建一个线程用于输出日志事件,有效的解决了这个问题,提高了程序的性能。

logback中的异步输出日志使用了AsyncAppender这个appender,通过看AsyncAppender源码,跟到它的父类AsyncAppenderBase,可以看到它有几个重要的成员变量:

AppenderAttachableImpl<E> aai = new AppenderAttachableImpl<E>();
BlockingQueue<E> blockingQueue;
AsyncAppenderBase<E>.Worker worker = new AsyncAppenderBase.Worker();


lockingQueue是一个队列,Worker是一个消费线程,基本可以判定是个生产者消费者模式。

再看消费者(work)的主要代码:

while (parent.isStarted()) {
    try {
        E e = parent.blockingQueue.take();    //单条循环
        aai.appendLoopOnAppenders(e);
    } catch (InterruptedException ie) {
        break;
    }
}


使用的是while单条循环 ,即logback异步输出是由一个消费者循环单条写入日志文件,工作流程如下图:

96.png


五、异步日志配置


配置示例:

配置异步输出日志的方式很简单,添加一个基于异步写日志的 appender,并指向原先配置的 appender即可。

<configuration>
   <appender name="FILE" class="ch.qos.logback.core.FileAppender">
     <file>myapp.log</file>
     <encoder>
       <pattern>%logger{35} - %msg%n</pattern>
     </encoder>
   </appender>
   <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
      <appender-ref ref="FILE" />
         <!-- 设置异步阻塞队列的大小,为了不丢失日志建议设置的大一些,单机压测时100000是没问题的,应该不用担心OOM -->
        <queueSize>10000</queueSize>
        <!-- 设置丢弃DEBUG、TRACE、INFO日志的阀值,不丢失 -->
        <discardingThreshold>0</discardingThreshold>
        <!-- 设置队列入队时非阻塞,当队列满时会直接丢弃日志,但是对性能提升极大 -->
        <neverBlock>true</neverBlock>
   </appender>
   <root level="DEBUG">
     <appender-ref ref="ASYNC" />
   </root>
 </configuration>


核心配置参数说明:

属性名

类型

描述

queueSize

int

BlockingQueue的最大容量,默认情况下,大小为256。

discardingThreshold

int

设置日志丢弃阈值, 默认情况下,当队列还有20%容量,他将丢弃trace、debug和info级别的日志,只保留warn和error级别的日志。

includeCallerData

boolean

提取调用方数据可能相当昂贵。若要提高性能,默认情况下,当事件添加到事件队列时,不会提取与事件关联的调用方数据。默认情况下,只复制线程名和 MDC 等“廉价”数据。通过将 includeecallerdata 属性设置为 true,可以指示此附加程序包含调用方数据。

maxFlushTime

int

根据被引用的 appender 的队列深度和延迟,AsyncAppender 可能需要不可接受的时间来完全刷新队列。当 LoggerContext 停止时,AsyncAppender stop 方法将等待工作线程完成直到超时。使用 maxFlushTime 指定最大队列刷新超时(以毫秒为单位)。无法在此窗口内处理的事件将被丢弃。此值的语义与 Thread.join (long)的语义相同。

neverBlock

boolean

默认是false,代表在队列放满的情况下是否卡住线程。也就是说,如果配置neverBlock=true,当队列满了之后,后面阻塞的线程想要输出的消息就直接被丢弃,从而线程不会阻塞。


默认情况下,event queue配置最大容量为256个events。如果队列已经满了,那么应用程序线程将被阻塞,无法记录新事件,直到工作线程有机会分派一个或多个事件。当队列不再达到最大容量时,应用程序线程可以再次开始记录事件。因此,当应用程序在其事件缓冲区的容量或附近运行时,异步日志记录就变成了伪同步。这未必是件坏事,AsyncAppender异步追加器设计目的是允许应用程序继续运行,尽管需要稍微多一点的时间来记录事件,直到附加缓冲区的压力减轻。


优化 appenders 事件队列的大小以获得最大的应用程序吞吐量取决于几个因素。


下列任何或全部因素都可能导致出现伪同步行为:


大量的应用程序线程


每个应用程序调用都有大量的日志事件


每个日志事件都有大量数据


子级appenders的高延迟


为了保持事情的进展,增加队列的大小通常会有所帮助,代价是减少应用程序可用的堆。


为了减少阻塞,在缺省情况下,当队列容量保留不到20% 时,AsyncAppender 将丢失 TRACE、 DEBUG 和 INFO 级别的事件,只保留 WARN 和 ERROR 级别的事件。这种策略确保了对日志事件的非阻塞处理(因此具有优异的性能) ,同时在队列容量小于20% 时减少 TRACE、 DEBUG 和 INFO 级别的事件。事件丢失可以通过将丢弃阈值属性设置为0(零)来防止。


六、性能测试


这部分自己还没时间做测试,引用网上的一些测试数据。


既然能提高性能的话,必须进行一次测试比对,同步和异步输出日志性能到底能提升多少倍?


服务器硬件


CPU 六核

内存 8G

测试工具


Apache Jmeter

1、同步输出日志


线程数:100

Ramp-Up Loop(可以理解为启动线程所用时间) :0 可以理解为100个线程同时启用

测试结果:

95.png

重点关注指标 Throughput【TPS】 吞吐量:系统在单位时间内处理请求的数量,在同步输出日志中 TPS 为 44.2/sec

2、异步输出日志

线程数 100

Ramp-Up Loop:0

测试结果:

94.png


TPS 为 497.5/sec , 性能提升了10多倍!!!


参考文章:


logback那些事儿

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
1月前
|
XML 安全 Java
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
本文介绍了Java日志框架的基本概念和使用方法,重点讨论了SLF4J、Log4j、Logback和Log4j2之间的关系及其性能对比。SLF4J作为一个日志抽象层,允许开发者使用统一的日志接口,而Log4j、Logback和Log4j2则是具体的日志实现框架。Log4j2在性能上优于Logback,推荐在新项目中使用。文章还详细说明了如何在Spring Boot项目中配置Log4j2和Logback,以及如何使用Lombok简化日志记录。最后,提供了一些日志配置的最佳实践,包括滚动日志、统一日志格式和提高日志性能的方法。
212 30
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
|
28天前
|
Java 中间件
SpringBoot入门(6)- 添加Logback日志
SpringBoot入门(6)- 添加Logback日志
70 5
|
2月前
|
XML JSON Java
Logback 与 log4j2 性能对比:谁才是日志框架的性能王者?
【10月更文挑战第5天】在Java开发中,日志框架是不可或缺的工具,它们帮助我们记录系统运行时的信息、警告和错误,对于开发人员来说至关重要。在众多日志框架中,Logback和log4j2以其卓越的性能和丰富的功能脱颖而出,成为开发者们的首选。本文将深入探讨Logback与log4j2在性能方面的对比,通过详细的分析和实例,帮助大家理解两者之间的性能差异,以便在实际项目中做出更明智的选择。
271 3
|
2月前
|
存储 Java Android开发
Android|记一个导致 logback 无法输出日志的问题
在给一个 Android 项目添加 logback 日志框架时,遇到一个导致无法正常输出日志的问题,这里记录一下。
38 2
|
2月前
|
Java 程序员 API
Android|集成 slf4j + logback 作为日志框架
做个简单改造,统一 Android APP 和 Java 后端项目打印日志的体验。
113 1
|
4月前
|
XML 监控 Java
异步日志:性能优化的金钥匙
本文主要介绍了Log4j2框架的核心原理、实践应用以及一些实用的小Tips,力图揭示Log4j2这一强大日志记录工具在现代分布式服务架构运维中的关键作用。
|
4月前
|
Java 应用服务中间件 HSF
Java应用结构规范问题之配置Logback以仅记录错误级别的日志到一个滚动文件中的问题如何解决
Java应用结构规范问题之配置Logback以仅记录错误级别的日志到一个滚动文件中的问题如何解决
|
4月前
|
Java 应用服务中间件 HSF
Java应用结构规范问题之配置Logback以在控制台输出日志的问题如何解决
Java应用结构规范问题之配置Logback以在控制台输出日志的问题如何解决
|
4月前
|
XML Java API
Java日志通关(四) - Logback 介绍
作者日常在与其他同学合作时,经常发现不合理的日志配置以及五花八门的日志记录方式,后续作者打算在团队内做一次Java日志的分享,本文是整理出的系列文章第四篇。
|
4月前
|
SQL JavaScript 前端开发
【Azure 应用服务】Azure JS Function 异步方法中执行SQL查询后,Callback函数中日志无法输出问题
【Azure 应用服务】Azure JS Function 异步方法中执行SQL查询后,Callback函数中日志无法输出问题