记一次排查 SpringBoot 服务“假死”的惨痛教训：被 System.out 支配的恐惧

在日常开发中，我们常常会遇到服务突然无法响应（Pending）的情况。通常的排查方向要么是 CPU 飙高（死循环），要么是内存溢出（OOM），又或者是数据库连接池耗尽。

但最近我们在线上 Docker 环境遇到了一个极其诡异的问题：服务完全不可用，请求全部 Pending，但容器 CPU 使用率不到 1%，内存也处于极低水位。

经过一步步抽丝剥茧，我们最终发现，引发这场“血案”的凶手，竟然是一个随处可见的“教学级”配置——MyBatis 的 StdOutImpl。

🕵️‍♂️ 第一阶段：案发现场与线索收集

症状描述：

生产环境的小程序接口频繁出现超时圈圈（Pending），服务没有宕机，但就是不干活。重启容器后能短暂恢复，但过几个小时又会重蹈覆辙。

首先，我们登录宿主机查看容器资源占用：

Bash

docker stats ***-charge-application --no-stream

结果非常反常：

  • CPU：0.42%（几乎没在计算）

  • MEM：6.27%（内存极其健康）

  • PIDS：203（刚好是 Tomcat 默认的最大线程池大小 200 + 几个后台线程）

初步推断：既然 CPU 不高且 PIDS 跑满，说明 200 个处理请求的 Tomcat 线程都在“等”。不是等数据库连接，就是等某个锁。

🔬 第二阶段：开箱验尸，抓取堆栈

为了找出这 200 个线程到底卡在哪，我们直接进入 Docker 容器，使用 jstack 抓取线程快照：

Bash

docker exec -it ***-charge-application /bin/bash
jstack 1 > /tmp/jstack.txt

# 统计线程状态分布
grep "java.lang.Thread.State" /tmp/jstack.txt | sort | uniq -c

统计结果令人心肺骤停：

Plaintext

     20    java.lang.Thread.State: BLOCKED (on object monitor)
     65    java.lang.Thread.State: WAITING (parking)
     ...

有 20 个业务线程处于 BLOCKED 状态！在 Java 中，这意味着它们正在激烈抢夺一个 synchronized 锁。我们立刻去查看 BLOCKED 的具体堆栈：

Plaintext

"http-nio-9000-exec-1" daemon prio=5 tid=0x... waiting for monitor entry 
   java.lang.Thread.State: BLOCKED (on object monitor)
        at java.io.PrintStream.println(PrintStream.java:881)
        - waiting to lock <0x0000000615800800> (a java.io.PrintStream)
        at org.apache.ibatis.logging.stdout.StdOutImpl.debug(StdOutImpl.java:52)
        at org.mybatis.logging.Logger.debug(Logger.java:49)
        ...
        at cn.net.ydlx.charge.service... (我们的业务代码)

真相大白：所有的业务线程，全部卡死在 MyBatis 打印 SQL 的 StdOutImpl.debug 这一行，等待获取 java.io.PrintStream 的全局锁！

📖 第三阶段：源码追踪，为什么会死锁？

为什么打印个 SQL 就能把 200 个线程的 Tomcat 拖垮？我们深入扒了一下底层的源码。

1. MyBatis 的 StdOutImpl 陷阱

如果你的 application.yml （或 Nacos 远程配置）里有这样一行：

YAML

mybatis-plus:
  configuration:
    log-impl: org.apache.ibatis.logging.stdout.StdOutImpl # 罪魁祸首

MyBatis 就会绕过所有的日志框架（如 Logback），直接粗暴地调用 System.out.println() 来打印每一条 SQL。

2. System.out.println 的夺命源码

点开 JDK 中 PrintStream 的源码：

Java

public void println(String x) {
    synchronized (this) { // 👈 全局唯一重锁
        print(x);
        newLine();
    }
}

这就是灾难的根源。 System.out 在整个 JVM 中是单例的。

当后台定时任务每 5 秒触发一次大数据量的 SQL 查询时，会疯狂向控制台输出日志。在 Docker 环境下，控制台输出还要经过 IO 重定向到 json-file，写入极慢。

此时，业务线程要想执行任何带 SQL 的操作，就必须去排队抢这把锁。一瞬间，线程池被耗尽，服务彻底 Pending。

3. Logback 是如何解决这个问题的？

对比我们配置的 Logback，如果我们使用了 Slf4jImpl，日志最终会走到 Logback 的核心分发代码：

Java

// ch.qos.logback.classic.Logger
public void callAppenders(ILoggingEvent event) {
    int writes = 0;
    for (Logger l = this; l != null; l = l.parent) {
        writes += l.appendLoopOnAppenders(event); // 👈 扔给 Appender 处理
        // ...
    }
}

如果配合了 AsyncAppender（异步日志），appendLoopOnAppenders 仅仅是把日志事件丢进内存队列（BlockingQueue）就立刻返回，完全不阻塞业务线程。

而 StdOutImpl 则是“一条路走到黑”，硬生生把高速公路变成了单行道。

🛠️ 第四阶段：终极解决方案

要彻底根治这个问题，必须将日志的控制权交还给 SLF4J 和 Logback。

1. 修改 MyBatis 日志实现

在配置文件（或 Nacos 配置中心）中，彻底封杀 StdOutImpl，强制指定为 Slf4jImpl：

YAML

mybatis-plus:
  configuration:
    # 严禁在生产环境使用 StdOutImpl！
    # log-impl: org.apache.ibatis.logging.stdout.StdOutImpl 

    # 正确姿势：交给 SLF4J，让 Logback 去管
    log-impl: org.apache.ibatis.logging.slf4j.Slf4jImpl

2. 升级 Logback 异步队列

确保 logback-spring.xml 中，文件写入被包装在异步 Appender 中，并开启防丢救命稻草 neverBlock：

XML

<!-- 异步包装 -->
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
    <!-- 队列满时，丢弃 TRACE/DEBUG/INFO，保留 WARN/ERROR，绝不阻塞业务 -->
    <discardingThreshold>20</discardingThreshold>
    <!-- 核心配置：即使队列全满，也不要阻塞主线程！ -->
    <neverBlock>true</neverBlock>
    <appender-ref ref="FILE" />
</appender>

💡 总结与反思

  1. 敬畏生产环境：System.out.println 和 StdOutImpl 仅限本地 Demo 调试使用。在生产环境的高并发下，任何一处 synchronized (this) 的同步写磁盘操作，都是埋在系统里的定时炸弹。

  2. 看懂 CPU 和 Thread 的关系：服务假死不一定是 CPU 满载。低 CPU + 高 PIDS + 请求挂起，往往是典型的“锁竞争”或“连接池耗尽”特征。

  3. 不要轻信本地配置：有时候本地 YAML 里没有配置 StdOutImpl，但如果 Nacos 远程配置有、代码硬编码有、或者启动脚本里带了参数，都会导致“幽灵配置”生效。遇事不决，直接用 jstack 看最真实的运行时状态。

排查问题就像破案，大胆假设，小心求证，jstack 永远是你最忠诚的显微镜！

posted on 2026-04-08 16:33  滚动的蛋  阅读(5)  评论(0)    收藏  举报

导航