Logback 日志打印导致程序崩溃的实战分析

news2024/9/9 1:04:21

在软件开发和运维中，日志记录是必不可少的一环，帮我们追踪程序的行为，定位问题所在。然而，有时日志本身却可能成为问题的根源。本文将通过一个真实的案例来探讨 Logback 日志系统中的一个常见问题，当并发量大，日志打印突增时，导致程序崩溃。

一、Logback集成

下面来看下在 SpringBoot 中是如何集成 Logback 的，这虽然是个 demo，但在真实使用中也是这样的，无非是扩展一些功能而已，后面讲到 Logback 是程序崩溃也是基于这样的实现。

首先是添加依赖，关于 SpringBoot 相关的依赖就省略了，这里重点关注 Logback 的依赖，注意使用的版本，不同的版本有不同的表现。

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>6.3</version>
</dependency>

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-core</artifactId>
    <version>1.1.8</version>
</dependency>

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.1.8</version>
</dependency>

Logback 配置文件添加，添加 logback-spring.xml 文件。

<?xml version="1.0" encoding="UTF-8" ?>
<configuration debug="true">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <!-- 日志输出内容，根据实际情况进行调整 -->
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 日志文件名及路径，根据实际情况修改 -->
        <file>./logs/app.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>./logs/app.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="FILE" />
    </root>
</configuration>

然后项目中在需要打印日志的地方，直接使用 log.info 或 log.error 等方式打印日志就好了，是不是很简单。

二、程序崩溃案例

程序在运行过程中，会收到很多服务请求超时的预警，然后过一会就会收到服务重启的预警。而且服务重启是无规律可循的，不是固定在某一个服务的某些 pod 上，而是所有的服务都有重启的现象，然后马上查看了相关监控，发现了一下问题，以下是相关监控内容

open files数量突增

直接内存的使用会突增

CPU 使用率突增

线程数量也会突增

三、原因分析

通过监控发现，在程序重启过程中，CPU、HTTP线程、直接内存使用、Open Files 这些指标都会突增。

首先看 HTTP 线程突增，感觉像是程序哪里阻塞住了，然后导致 HTTP 的堆积，最终导致健康检查的请求进不来，最终导致了服务的重启，而服务重启后一切又都回归了正常，下次在出现这种情况，可能又出现在了别的 Pod 上。到底是哪里出了问题呢？

因为是 HTTP 线程突增，所以第一想到的是程序内部有阻塞点，然后再请求三方接口、数据库查询等依赖的地方都加上了耗时统计，然后再出现重启时在看一下到底是哪里阻塞住了，奇怪的是这些地方都很正常，响应时间也没什么变化。

没有办法只能生成重启时的线程堆栈情况了，联系运维，编写了相应的脚本，当服务发生重启时生成相应的线程堆栈，具体是使用 jstack 命令。通过线程堆栈信息最终才发现了问题所在。以下是详细的线程堆栈分析。

阻塞的线程统计情况如下：

尽然有857个 HTTP 线程被阻塞住了，具体在看下阻塞在哪里了呢。

通过线程堆栈信息可以清楚的看到，是在打印日志时发生了阻塞，大量的 HTTP 线程被阻塞住，无法接受新的请求，最终导致健康检查失败而发生了重启，重启后这些又回归了正常。

为什么会发生阻塞呢？

我们使用的 Logback 版本是1.1.8，根据堆栈信息定位到具体的阻塞点，源码如下：

写日志时采用的是同步写，同步写这里是有加锁操作的，目的是为了防止一个线程将写日志的流关闭导致其他线程无法写入日志，而且采用得还是公平锁。这就是问题的根源所在，在高并发场景下，大量的日志写入都要到这里获取锁才能进行日志写入，这就造成了阻塞，将 HTTP 线程耗尽。

公平锁就是多个线程按照申请锁的顺序去获得锁，线程会直接进入队列去排队，永远都是队列的第一位才能获取到锁。这样虽然可以方式线程饥饿，但是吞吐量会下降很多，队列里除了第一个线程，其他的线程都会被阻塞。

四、解决方案

为了解决上述问题，可以采用如下策略进行修改。

首先，优化日志输出策略，平时在我们的系统重只输出必要的 info 日志和 error 日志，其他的 debug 级别日志和 warn 级别的日志就不用输出了。接口只打印入参，不要打印出参，一般情况下出参都会比较大，还有一些 SQL 语句的日志，这些都会加大日志的输出量。要想解决上述问题，第一条就是减少日志的输出，这也是这次问题解决的第一条方案：对项目中的日志进行梳理并且规范化，debug 级别和 warn 级别的日志统统下掉，简化系统日志输出量，将接口返回值和 SQL 语句的日志省略掉。当然了如果生产环境为了排查问题方便，可以开发一个开关功能，可以在排查问题时打印相应的日志。

其次，升级 Logback 日志版本，目前使用的版本是 1.1.8，将版本升级为 1.2.3，升级以后将公平锁修改为了非公平锁。