发布于 由admin

Spring Boot日志写入过重导致业务线程阻塞的性能调优方法

Spring Boot 日志写入过重导致业务线程阻塞的性能调优

大家好，今天我们来探讨一个在实际开发中经常遇到的问题：Spring Boot 应用中，日志写入过重导致业务线程阻塞，进而影响系统性能。我们将从问题分析、定位、到各种优化策略，以及这些策略的实际应用，进行深入的讲解。

一、问题分析与定位

首先，我们需要理解为什么日志写入会阻塞业务线程。在默认情况下，Spring Boot 使用的日志框架（通常是 Logback 或 Log4j2）的 Appender 默认是同步写入日志的。这意味着，当你的代码执行 logger.info("Some log message") 时，当前线程会被阻塞，直到日志写入完成。如果日志量很大，或者写入速度很慢（例如，写入到网络磁盘），那么阻塞时间就会增加，最终导致业务线程的响应时间变长，甚至出现线程池耗尽的情况。

为了定位问题，我们需要收集一些关键信息：

  1. 线程 Dump: 使用 jstack 命令可以获取 JVM 的线程 Dump。分析 Dump 文件，可以查看哪些线程正在等待 I/O 操作，比如等待日志写入。

    jstack <pid> > thread_dump.txt

    分析 thread_dump.txt，寻找处于 BLOCKED 或 WAITING 状态，并且调用栈包含日志相关类的线程。例如，你可能会看到这样的信息：

    "http-nio-8080-exec-2" #23 daemon prio=5 os_prio=0 tid=0x00007f9a081e3000 nid=0x2e waiting for monitor entry [0x00007f99f72e5000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:349)
    - waiting to lock <0x00000007c1234567> (a ch.qos.logback.core.FileAppender)
    at ch.qos.logback.core.AppenderBase.append(AppenderBase.java:173)
    at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
    at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
    at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
    at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
    at ch.qos.logback.classic.Logger.filterAndLog(Logger.java:404)
    at ch.qos.logback.classic.Logger.info(Logger.java:609)
    at com.example.demo.MyService.doSomething(MyService.java:20)

    这个例子表明，http-nio-8080-exec-2 线程正在等待 FileAppender 的锁，这意味着日志写入成为瓶颈。

  2. 日志量分析: 统计单位时间内产生的日志量，可以使用 grep 和 wc 命令，或者使用日志分析工具。例如：

    grep "Some log message" my_application.log | wc -l

    如果发现单位时间内产生的日志量很大，特别是大量的 DEBUG 或 TRACE 级别的日志，就需要考虑调整日志级别。

  3. I/O 性能监控: 使用 iostat 命令可以监控磁盘 I/O 性能。如果发现磁盘 I/O 很高，说明日志写入可能受到磁盘性能的限制。

    iostat -x 1

    关注 %util 列，如果接近 100%，说明磁盘 I/O 已经达到瓶颈。

二、优化策略

在确认了问题之后，我们就可以开始实施优化策略。主要有以下几个方向：

  1. 异步日志: 这是最常见的解决方案。将同步日志写入改为异步写入，可以显著降低对业务线程的影响。

    • Logback 异步 Appender: Logback 提供了 AsyncAppender，可以将日志事件放入一个队列，由一个单独的线程来写入日志。

      <configuration>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>my_application.log</file>
        <encoder>
            <pattern>%d{yyyy-MM-dd 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" />
        <queueSize>512</queueSize>
        <discardingThreshold>0</discardingThreshold> <!-- 丢弃日志的阈值，0 表示不丢弃 -->
    </appender>

    <root level="INFO">
        <appender-ref ref="ASYNC" />
    </root>
</configuration>

      queueSize 设置队列的大小，discardingThreshold 设置丢弃日志的阈值。需要根据实际情况调整这些参数。

    • Log4j2 异步 Appender: Log4j2 提供了多种异步 Appender，包括基于 Disruptor 的高性能异步 Appender。

      <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <File name="FILE" fileName="my_application.log">
            <PatternLayout>
                <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n</Pattern>
            </PatternLayout>
        </File>

        <Async name="ASYNC">
            <AppenderRef ref="FILE"/>
        </Async>
    </Appenders>
    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="ASYNC"/>
        </Root>
    </Loggers>
</Configuration>

      Log4j2 的异步 Appender 默认使用 LinkedTransferQueue，也可以配置使用 Disruptor 来获得更高的性能。

  2. 调整日志级别: 降低日志级别，减少日志量。在生产环境中，通常只需要 INFO 或 WARN 级别的日志。

    <root level="INFO">
    <appender-ref ref="ASYNC" />
</root>

    可以通过配置不同的 Logger 来控制不同包或类的日志级别，例如：

    <logger name="com.example.demo.MyService" level="DEBUG" additivity="false">
    <appender-ref ref="ASYNC" />
</logger>

    这意味着，只有 com.example.demo.MyService 类的日志级别是 DEBUG，其他类的日志级别仍然是 INFO。additivity="false" 表示不将日志传递给 root logger。

  3. 优化日志格式: 减少日志格式中的冗余信息，例如，可以去掉线程名、类名等。

    <encoder>
    <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %msg%n</pattern>
</encoder>

    虽然这一点优化效果可能不明显，但是在高并发场景下，仍然可以节省一些 CPU 资源。

  4. 批量写入: 将多个日志事件批量写入到文件，可以减少 I/O 操作的次数。Logback 和 Log4j2 都支持批量写入。

    • Logback: 可以通过自定义 Appender 来实现批量写入。

    • Log4j2: 可以使用 RollingFileAppender 的 bufferedIO 和 bufferSize 属性来实现批量写入。

      <RollingFile name="FILE" fileName="my_application.log"
             filePattern="my_application-%d{yyyy-MM-dd}.log">
    <PatternLayout>
        <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n</Pattern>
    </PatternLayout>
    <Policies>
        <TimeBasedTriggeringPolicy interval="1"/>
    </Policies>
    <DefaultRolloverStrategy max="7"/>
    <BufferedIO>true</BufferedIO>
    <BufferSize>8192</BufferSize>
</RollingFile>

      BufferedIO 设置为 true 启用缓冲 I/O，BufferSize 设置缓冲区的大小。

  5. 使用更快的存储介质: 如果日志写入到磁盘，可以考虑使用 SSD 磁盘，或者将日志写入到内存文件系统（例如 tmpfs）。

  6. 减少日志输出: 避免在循环中频繁输出日志。 如果必须在循环中输出日志，可以设置一个阈值，例如每 1000 次循环输出一次。

    for (int i = 0; i < 10000; i++) {
    // Some logic
    if (i % 1000 == 0) {
        logger.info("Processing item: {}", i);
    }
}

  7. 使用专门的日志收集系统: 将日志发送到专门的日志收集系统（例如 ELK Stack, Splunk），可以减轻应用程序的 I/O 负担。

    • Logstash: 可以配置 Logstash 从文件读取日志，并将其发送到 Elasticsearch。

    • Fluentd: Fluentd 是另一个流行的日志收集器，可以配置 Fluentd 将日志发送到各种后端存储。

  8. 限制异步队列大小和配置丢弃策略: 虽然异步日志可以解耦日志写入和业务线程，但是异步队列如果无限增长，最终也会导致内存溢出。 因此，应该合理配置异步队列的大小，并且配置合适的丢弃策略。 当队列已满时，可以选择丢弃最早的日志，或者丢弃优先级较低的日志。

    <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE" />
    <queueSize>512</queueSize>
    <discardingThreshold>0</discardingThreshold> <!-- 0 表示不丢弃，可以设置为队列大小的一半 -->
    <includeCallerData>false</includeCallerData> <!-- 避免收集调用者数据，提升性能 -->
</appender>

    includeCallerData 设置为 false 可以避免收集调用者数据，从而提升性能。

  9. 使用非阻塞 I/O: 某些日志框架支持非阻塞 I/O，可以进一步提升日志写入的性能。 例如，Log4j2 支持使用 RandomAccessFile 和 MappedByteBuffer 进行非阻塞 I/O。

三、不同策略的对比

下面是一个表格，对比了不同优化策略的优缺点：

优化策略 优点 缺点 适用场景
异步日志 显著降低对业务线程的影响 需要配置和维护异步队列，可能会丢失日志 大部分场景，特别是对响应时间要求高的场景
调整日志级别 简单有效，直接减少日志量 可能会丢失一些有用的信息 所有场景，特别是生产环境
优化日志格式 减少日志格式中的冗余信息，节省 CPU 资源 效果可能不明显 高并发场景
批量写入 减少 I/O 操作的次数 需要配置，可能会增加延迟 日志量很大的场景
更快的存储介质 提升 I/O 性能 成本较高 对 I/O 性能要求非常高的场景
减少日志输出 避免在循环中频繁输出日志，减少 I/O 操作 需要修改代码 循环中输出日志的场景
日志收集系统 减轻应用程序的 I/O 负担 需要配置和维护日志收集系统 需要集中管理和分析日志的场景
限制队列和丢弃策略 避免内存溢出，保证系统稳定性 可能会丢失日志 所有使用异步日志的场景
非阻塞 I/O 提升日志写入性能 配置复杂，兼容性可能存在问题 对日志写入性能有极致要求的场景

四、代码示例：使用 Logback 异步 Appender

以下是一个完整的 Spring Boot 示例，演示如何使用 Logback 异步 Appender：

  1. 添加 Logback 依赖:

    <dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter</artifactId>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
</dependency>

  2. 创建 logback-spring.xml:

    <?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>my_application.log</file>
        <encoder>
            <pattern>%d{yyyy-MM-dd 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" />
        <queueSize>512</queueSize>
        <discardingThreshold>0</discardingThreshold>
    </appender>

    <root level="INFO">
        <appender-ref ref="ASYNC" />
    </root>
</configuration>

  3. 创建 Spring Boot 应用:

    import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
@RestController
public class DemoApplication {

    private static final Logger logger = LoggerFactory.getLogger(DemoApplication.class);

    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }

    @GetMapping("/log")
    public String log() {
        for (int i = 0; i < 1000; i++) {
            logger.info("Log message: {}", i);
        }
        return "Logged 1000 messages";
    }
}

  4. 运行应用，访问 /log 接口，查看 my_application.log 文件。

五、总结和建议

Spring Boot 日志写入过重导致业务线程阻塞是一个常见的问题，但是通过合理的分析和优化，可以有效地解决这个问题。 本次讨论涵盖了多种优化策略，包括异步日志、调整日志级别、优化日志格式、批量写入、使用更快的存储介质、使用专门的日志收集系统等。 选择哪种策略取决于具体的应用场景和性能需求。 建议在生产环境中始终开启异步日志，并根据实际情况调整异步队列的大小和丢弃策略。 此外，定期审查日志级别和日志格式，避免输出不必要的日志。

发表回复

您的邮箱地址不会被公开。 必填项已用 * 标注