Logback 日志打印对性能影响的探讨

关注

原创 2025-02-20 13:48:26 1.2k 阅读 AI 写同款· GEO 优化 ›

Logback 日志打印导致程序崩溃的实战分析日志记录是必不可少的一环，帮我们追踪程序的行为，定位问题所在。然而，有时日志本身却可能成为问题的根源。所以要根据实际情况选择合适的日志输出方式，避免造成程序阻塞而导致业务收到影响。从理论到实践：零拷贝技术的全面解读_零拷贝详解-CSDN博客Sentinel与Nacos强强联合，构建微服务稳定性基石的重要实践_nacos sentinel-CSDN博客从0开始理解云原生架构-CSDN博客TiDB高手进阶：揭秘自增ID热点现象与高级调优技巧_tidb 分布式自增id-CSDN博客。阅读详情

一、引言

在日常系统业务开发中，日志记录是不可或缺的一部分，不仅帮助我们调试和排查问题，还能提供系统的运行状态和健康状况。然而，配置使用不当可能会对性能产生负面影响。在我们的项目中，服务耗时优化是提升系统性能的关键任务。在压测过程中，我们发现单机 QPS 存在明显的性能瓶颈，进一步分析表明，平常看似不起眼的日志打印实际上对性能产生了不小的影响。本文将探讨 Logback 日志打印对性能的影响，并提供一些优化建议。

二、日志记录的基本原理

日志消息打印的过程包括以下几个步骤：

2.1 获取 Logger

调用 org.slf4j.LoggerFactory 类的 getLogger 方法，即可获取 Logger 对象

Logger log = LoggerFactory.getLogger("HelloWord");

2.2 调用 logger.info 打印方法

log.info("NewIt");

2.2.1 取得过滤链的判定结果

调用log.info()方法，实际调用的是filterAndLog_1方法，第一步会进行TurboFilter过滤，可以在早期阶段决定是否丢弃日志事件，从而提高性能和减少不必要的日志处理开销。它支持根据日志级别、MDC 数据、标记等多种条件进行灵活的过滤。

2.2.2 检查日志级别

对 Logger 的有效级别与日志请求级别进行比较。如果请求级别数值小于有效级别，本次请求将被禁用，Logback 会直接跳过本次请求

private void filterAndLog_1(final String localFQCN, final Marker marker, final Level level, final String msg, final Object param, final Throwable t) {
        /**
         * 这里先经过一串过滤器处理，根据传入的marker满足的条件不同返回不同的结果，
         */
        final FilterReply decision = loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t);
        /**
         * 过滤后返回NEUTRAL则进一步判断当前想要打印的日志等级
         * 如果小于有效日志级别，则表示该日志无效，直接返回，不做具体输出动作。
         */
        if (decision == FilterReply.NEUTRAL) {
            if (effectiveLevelInt > level.levelInt) {
                return;
            }
        } else if (decision == FilterReply.DENY) {
            return;
        }
        buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param }, t);
}

2.2.3 创建 LoggingEvent 对象

如果日志级别允许，Logback 会构建一个 LoggingEvent 对象，该对象包含所有与请求相关的参数，如请求用的 logger、请求级别、日志消息、请求携带的异常、当前时间、当前线程、MDC信息等等。

private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
                    final Throwable t) {
        LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
        le.setMarker(marker);
        callAppenders(le);
    }

2.2.4 调用 appenders 的 doAppend() 方法

在创建 LoggingEvent 对象以后，logback 将调用所有可用 appender 的 doAppend()方法，进行日志输出。

常见的 Appender 包括：

ConsoleAppender：将日志输出到控制台

FileAppender：将日志输出到文件

RollingFileAppender：将日志输出到文件，并支持日志滚动

SMTPAppender：将日志发送到电子邮件

DBAppender：将日志写入数据库

public void callAppenders(ILoggingEvent event) {
        int writes = 0;
        for (Logger l = this; l != null; l = l.parent) {
            writes += l.appendLoopOnAppenders(event);
            if (!l.additive) {
                break;
            }
        }
        if (writes == 0) {
            loggerContext.noAppenderDefinedWarning(this);
        }
    }

2.2.5 格式化日志信息

Appender 在输出日志信息前，需要对日志事件(LoggingEvent)进行格式化。它使用 Encoder 将日志事件转换为字节数组并把字节数组写出到相应的输出流，在转换为字节数组前，Encoder 通过调用 Layout 的 doLayout() 方法将日志事件格式化为字符串。

常见的 Layout 包括：

PatternLayout：使用模式字符串来格式化日志消息

HTMLLayout：生成 HTML 格式的日志

XMLLayout：生成 XML 格式的日志

2.2.6 输出日志信息

Appender 会根据配置的 Layout 将 LoggingEvent 转换为最终的日志消息，并将其输出到指定的目标

protected void subAppend(E event) {
        ......
        try {
            if (event instanceof DeferredProcessingAware) {
                ((DeferredProcessingAware) event).prepareForDeferredProcessing();
            }
            // 格式化日志文件        
            byte[] byteArray = this.encoder.encode(event);
            // 写入日志到特定的输出流中
            writeBytes(byteArray);
        } catch (IOException ioe) {
          ......
        }
    }

2.2.7 清理资源

在日志输出完成后，Appender 会清理相关的资源，如关闭文件句柄等。

public void stop() {
    synchronized (lock) {
      closeOutputStream();
      super.stop();
    }
  }

性能影响因素

通过 Logback 的原理，我们可以了解到日志记录在提高应用程序的可维护性和可调试性的同时，因为日志生成和格式化会消耗 CPU 资源、日志写入和网络传输引入 I/O 延迟，以及日志事件对象占用内存等方面，也会对系统的性能产生一定的影响。

1. CPU 使用率增加

日志生成和格式化：每次生成日志时，需要执行字符串拼接、日期格式化等操作，这些操作会消耗 CPU 资源。

日志级别检查：每次调用日志方法时，Logback 都会检查当前日志级别是否允许记录该级别的日志。虽然这是一个简单的比较操作，但在高并发场景下也会累积成显著的开销。

2. 内存使用增加

日志事件对象：每个日志事件都会创建一个 LoggingEvent 对象，这些对象需要占用内存。在高并发场景下，大量的 LoggingEvent 对象可能会导致内存压力。

缓冲区：某些 Appender（如 AsyncAppender）会使用缓冲区来异步处理日志，这也会占用一定的内存。

3. I/O 操作延迟

文件写入：将日志写入文件系统是一个 I/O 操作，可能会导致磁盘 I/O 延迟。特别是在高并发场景下，频繁的文件写入操作可能会成为性能瓶颈。

网络传输：如果日志被发送到远程服务器（如通过 SMTPAppender 发送邮件或通过 SocketAppender 发送网络日志），网络传输也会引入延迟。

4. 线程阻塞

同步 I/O 操作：默认情况下，大多数 Appender 是同步的，这意味着日志写入操作会阻塞当前线程，直到写入操作完成。在高并发场景下，可能会导致线程阻塞，影响程序的响应速度。

日志滚动：某些 Appender（如 RollingFileAppender）在日志文件达到一定大小时会进行日志滚动操作，可能会导致短暂的阻塞。

5. 系统调用开销

文件描述符：每次打开和关闭文件描述符都会涉及系统调用，这会带来额外的开销。虽然 FileAppender 通常会保持文件描述符打开状态，但在某些情况下（如日志滚动）仍然会涉及文件描述符的管理。

线程切换：在多线程环境下，日志操作可能会导致线程切换，会增加调度开销。

优化建议

为了减少日志记录对性能的影响，可以采取以下措施：

1. 合理设置日志级别：

在生产环境中，将日志级别设置为 INFO 或更高，避免记录过多的 DEBUG 和 TRACE 日志。

使用条件日志记录，例如：

if (logger.isDebugEnabled()) {
    logger.debug("This is a debug message with computation: {}", computation());
}

1. 使用高效的 Appender：

选择适合应用场景的 Appender，在高性能场景下使用 AsyncAppender ，减少主线程的阻塞时间。

<appender name="asyncInfoAppender" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE" />
</appender>

1. 优化日志格式：

减少不必要的日志信息，简化日志格式，减少字符串拼接和格式化的开销。

1. 合理的配置 Appender属性：

如配置 RollingFileAppender 时，合理设置日志滚动策略，避免频繁的文件滚动操作。

1. 限制日志文件大小：

设置合理的日志文件大小限制，避免单个日志文件过大导致的 I/O 延迟

实践案例

我们有个高并发的 Web 应用，需要最大的提升服务的TPS，在发现日志记录有性能影后，于是对日志开始优化。

使用 Logback 进行日志记录。初始配置如下：

<configuration>
    ......
    <appender name="infoAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
	    <file>${log.dir}/logs/${APP_NAME}-ss_micro_app_${APP_NAME}_lt_info.log</file>
	    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
		    <level>INFO</level>
	    </filter>
	    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
		    <fileNamePattern>${log.dir}/logs/${APP_NAME}_${projectname}-%d{yyyy-MM-dd}.log
		    </fileNamePattern>
		    <maxHistory>30</maxHistory>
	    </rollingPolicy>
	    <encoder charset="UTF-8">
		    <pattern>%d [%thread] %-5p [%c] [%F:%L] [trace=%X{trace_id},span=%X{span_id}] - %msg%n</pattern>
	    </encoder>
    </appender>
    
    <!-- 监控耗时 -->
    <appender name="BizRollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log_dir}/logs/${APP_NAME}-ss_micro_app_${projectname}_lt_biz.log</file>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log_dir}/logs/${APP_NAME}-ss_micro_app_${projectname}_lt_biz.log-%d{yyyy-MM-dd}.log
            </fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder charset="UTF-8">
              <pattern>%msg%n</pattern>
        </encoder>
    </appender>
    
    <logger name="com.newit.core.payment.common.interceptors.MonitorLogUtil" additivity="false">
        <level value="INFO"/>
    	<appender-ref ref="BizRollingFile"/>
    </logger>
    
    <root level="debug">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="infoAppender" />
    </root>
    ......
</configuration>

在高并发场景下，发现应用性能明显下降，日志文件迅速增大。经过分析、我们进行了以下优化：

关闭不需要的日志输出

在对外输出项目中，biz日志其实并不需要使用，可以对其停止打印

<logger name="com.newit.core.payment.common.interceptors.MonitorLogUtil" additivity="false">
    <level value="OFF"/>
    <appender-ref ref="BizRollingFile"/>
</logger>

优化日志格式化方式

a.使用 %d{MM-dd HH:mm:ss.SSS} 来格式化日期和时间，在确保时间和日期的可读性的同时，可减少日志字符

b. 使用%C{15} 等占位符来截断长的日志记录器名称和类名

<encoder charset="UTF-8">
	<pattern>%d{MM-dd HH:mm:ss.SSS} [%thread] %-5p [%c{15}] [%F%L] [trace=%X{trace_id},span=%X{span_id}] - %msg%n</pattern>
</encoder>

使用异步日志记录：

<appender name="asyncInfoAppender" class="ch.qos.logback.classic.AsyncAppender">
    <!-- 设置为0不丢弃日志,默认队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
    <discardingThreshold>0</discardingThreshold>
    <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
    <queueSize>1024</queueSize>
    <!-- 队列满了不阻塞调用者-->
    <neverBlock>true</neverBlock>
    <appender-ref ref="infoAppender" />
</appender>
<root level="info">
    <appender-ref ref="STDOUT" />
    <appender-ref ref="asyncInfoAppender" />
</root>

AsyncAppender提升了日志记录的性能和响应速度，但可能导致日志顺序不一致和增加内存消耗。在高并发场景下需要高性能的服务非常有用，但在需要严格日志顺序的应用中需谨慎使用

小插曲：

在用AsyncAppender进行日志输出后，日志中的%L号无法转换，最后查看logback的源码：org.apache.log4j.AsyncAppender发现有一个参数：includeCallerData，根本原因是获取方法名、代码行号的方法的性能不太好，AsyncAppender默认关闭该实现，日志中如果需要显示该属性，将这个参数设置为true即可：

<appender name="asyncInfoAppender" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="infoAppender"/>
    <param name="includeCallerData" value="true"/>
</appender>

配置单个日志文件大小

可以在现有的按天归档日志的配置上，再加上根据文件大小分割配置，在一个自然日多个文件会按照后缀为yyyy-MM-dd-%i.log的格式顺序生成。

限制单个日志文件的大小可以提高文件管理和备份的效率，减少磁盘 I/O 操作，提高日志写入速度，同时也增强日志读取和分析的便捷性。此外它还能简化日志轮转过程，避免大文件带来的性能和管理问题。

<appender name="infoAppender"
              class="ch.qos.logback.core.rolling.RollingFileAppender">
        ......
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log_dir}/logs/${APP_NAME}_${projectname}-%d{yyyy-MM-dd}-%i.log
            </fileNamePattern>
            <maxHistory>30</maxHistory>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>500MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
       ......
    </appender>

优化效果

性能：

为了减少其它中间件对优化效果的影响，我们屏蔽了其它中间件对性能的影响，压测方法中仅有日志的输出，来看看优化前后的区别：

日志优化前TPS：

日志优化后TPS：

根据一些其它基准测试，调整压测方法中日志输出比例，使用优化后的配置通常可以带来以下性能提升：

低频日志记录：如果日志记录频率较低，性能提升可能不太明显，大约在 10% 到 30% 之间

高频日志记录：如果日志记录频率较高，性能提升可以达到 50% 到 100% 甚至更高

存储：

通过优化日志格式，在不影响日志分析的前提下，每行日志输出可以固定减少大约20个字符左右。按照每天1000万条日志计算，每天可以节省大约200MB的存储空间。这对于处理大量日志的应用程序来说，能够有效降低存储成本。

七、总结

Logback 是一个强大且灵活的日志框架，但在使用过程中需要注意日志记录对性能的影响。通过合理设置日志级别、使用异步日志记录、记录必要的信息、简化日志格式、启用日志轮转和过滤敏感信息等措施，可以最大限度地发挥日志的作用，同时尽量避免因日志打印引起的性能问题。然而，优化日志记录还需要结合具体的应用场景，特别是在互联网应用中追求高性能、高并发和高可用的“三高”要求。每个服务在这些维度上的侧重点不同，因此需要根据实际情况进行针对性的优化。以上是一些相关影响点的优化探讨，希望大家在实际项目中更好地使用 Logback，提升应用的性能和稳定性。

收录于