SLF4J 绑定竞态导致内存泄漏

结算服务又开始重启了。监控群里每隔几个小时蹦一条告警，k8s 把结算服务的 Pod 杀掉重来，节奏稳定得像闹钟。我第一反应是把日志拉出来找 OutOfMemoryError，翻了个底朝天，一条都没有。日志干净得反常，服务被杀前一刻还在正常处理请求。

这篇文章记录从这条"没有报错的重启"出发，一路挖到 SLF4J 初始化竞态的完整过程，中间几次怀疑错方向的弯路也留着。

先搞清楚它到底是怎么死的

常见的堆溢出会留下完整的报错栈、GC 日志、临死前的挣扎痕迹，这次全没有。那就去问 k8s 本身，kubectl describe pod 看上一次终止状态：

Last State:  Terminated
  Reason:    OOMKilled
  Exit Code: 137

这个退出码就是第一个关键线索。137 = 128 + 9，进程收到了 SIGKILL。cgroup 发现进程内存超过容器限额，内核直接动手，而 SIGKILL 没法被捕获，JVM 连组织一次异常的机会都没有，所以应用日志里当然什么都不会有。

到这里，问题从"为什么内存溢出"变成了"内存到底去哪了"。

堆没爆，爆的是进程

接着看 JVM 自己的视角。堆上限配置合理，离容器 limit 留了不少余量；jstat 盯了一阵，大概是这样的样子（示意）：

  S0    S1    E      O      M    YGC   FGC
  0.00  95.2  68.4   69.41  98.1 412   2
  0.00  0.00  71.2   73.86  98.1 438   2     <- 十分钟后

年轻代回收很规律，Full GC 十分钟一次都没涨，JVM 觉得自己很健康。真正扎眼的是老年代：没人动它，它自己从 69.41% 爬到了 73.86%。有活对象在匀速堆积，Full GC 救不了活对象。

监控上容器内存是一条笔直的斜线：每个周期从重启点开始线性爬升，碰到 limit，垂直跌回（被杀，重启），下个周期再来一遍，斜率几乎不变。堆没爆，容器爆了，这两个事实放一起其实就通了：容器 limit 管的是整个进程的驻留内存，堆只是其中一块，旁边还有元空间、线程栈、直接内存和 JVM 自身。堆在慢性泄漏，只是还没涨到让 JVM 分配失败，总内存就先撞墙了。

斜率恒定这个细节当时给了我一个预感：泄漏速度跟某个稳定的业务动作频率绑在一起，不是随机抖动。这决定了后面 dump 里该找什么，一个只增不减、匀速变大的东西。

选一台健康节点 dump

抓泄漏物，思路是堆快照。这里有个选择：dump 哪台？

不能等它快被杀的时候去 dump，一是可能 dump 到一半进程就没了，二是那时候节点已经在异常状态。正确做法是挑一台跑了几个小时、还没轮到被重启的健康节点：泄漏物已经积累了足够大的量，在堆里会非常显眼。

# 导出会使服务短暂停顿，避开流量高峰执行
kubectl exec <pod> -- jcmd 1 GC.heap_dump /tmp/dump.hprof

# 或者用 jmap；live 会先触发一次全文回收再导出存活对象，产物更小
kubectl exec <pod> -- jmap -dump:live,format=b,file=/tmp/dump.hprof 1

kubectl cp <pod>:/tmp/dump.hprof ./dump.hprof

拿到手 749 MB。本地怎么啃这种体量：机器上装了 MAT（Eclipse MemoryAnalyzer），图形界面打开要先建索引干等，不如先用它的无头脚本把三个标准报告挂后台跑：

/Applications/MemoryAnalyzer.app/Contents/MacOS/ParseHeapDump.sh \
    ./dump.hprof \
    org.eclipse.mat.api:suspects \
    org.eclipse.mat.api:overview \
    org.eclipse.mat.api:top_components

报告是几个 zip，解压开浏览器看 index.html。

半个堆在一个队列里

总览页先给个底：堆内存活对象 531.2 MB，对象总数 5,977,711，类 25,210 个，JVM 是 1.8.0_191。

然后是 Leak Suspects 的第一嫌疑，这段是报告原文：

Problem Suspect 1

One instance of java.util.concurrent.LinkedBlockingQueue loaded by
<system class loader> occupies 280,555,920 (50.37%) bytes. The top
consumers of its minimum retained heap are

    char[]                                (460,983 instances, 231,686,384 bytes)
    org.slf4j.event.SubstituteLoggingEvent (472,571 instances,  26,463,976 bytes)
    java.util.concurrent.LinkedBlockingQueue$Node (472,572 instances, 11,341,728 bytes)

The instance is referenced by org.slf4j.helpers.SubstituteLogger @ 0x730019468.
Thread com.xxx.errorreporter.impl.ErrorConsumeThread @ 0x73013a060 Thread-4
has a local variable or reference to org.slf4j.helpers.SubstituteLogger @ 0x73013a5a0
which is on the shortest path to java.util.concurrent.LinkedBlockingQueue @ 0x730019490.

信息量大到不用我自己推理：

• 一个链式阻塞队列，保留集 280,555,920 字节，占已用堆的 50.37%，半个堆
• 队列里 472,571 个 SubstituteLoggingEvent，这是 SLF4J 的日志事件包装类；队列节点 472,572 个，恰好比事件数多 1，多的那个是链表哨兵头节点，说明 47 万个事件一个不落全串在这个队列上
• 字符数组 46 万个、2.3 亿字节，装的就是日志正文
• 队列被 org.slf4j.helpers.SubstituteLogger 引用，而引用这个替代日志器的线程，MAT 直接点名：com.xxx.errorreporter.impl.ErrorConsumeThread，错误上报组件的消费线程，Thread-4

第一反应先记下三个名字：错误上报组件、SLF4J 的替代日志器、一个无上限队列。第二嫌疑是 MyBatis 会话工厂占 10.11%，属于正常缓存行为，先排除。

SubstituteLoggingEvent 这个名字我看着眼熟，SLF4J 初始化期间的过渡产物。当时心里咯噔了一下，但先忍住不下结论，继续看队列里装的内容到底是不是业务的东西。

47 万条被吞掉的错误日志

字符数组是 UTF-16 存的，直接在快照文件里按 UTF-16 小端抽字符串：

strings -e l dump.hprof | grep -a -m 3 'SaveSingle'

捞出来的内容长这样（节选脱敏）：

SaveSingle?content=exception:java.lang.RuntimeException%3A+...%0A%09at+
com.xxx.settlement.service...%0A%09at+com.xxx.settlement.service...%0A%09at+
com.sun.proxy...

全是 URL 编码过的异常上报报文和完整堆栈，栈帧是结算业务服务和监控切面的代理类。也就是说，这些是业务运行中真实发生的错误，被记进日志之后哪儿也没去，整段整段躺在内存里。每条平均 2.3 亿字节除以 47 万，约 490 字节，正是一条编码堆栈的体量，数字对得上。

那么问题变成：好好的日志为什么没走输出，全进了这个队列。

22 个没有委托的日志器

MAT 已经把线程和类名指出来了，剩下的是把责任钉死、顺便洗清 logback。用 jhat 把堆挂起来查 SLF4J 的替代日志器。中间有个小插曲：这个版本的 jhat 一跑 OQL 就报 not implemented，只好从主页面顺着类链接一个一个点进实例列表去翻，笨，但有效：

检查项	结果
替代日志器实例数	22 个：19 个来自 HTTP 异步客户端内部，3 个来自错误上报组件自身
委托字段	逐个检查，22 个全部为空，从未转正
对照组：logback 真日志器	4,341 个，工作正常
对照组：异步日志线程	4 个，线程栈里都在正常干活

logback 没坏，坏的是很小的一批对象，数量恰好是 22。委托字段为空意味着它们从出生起就没往任何地方输出过一条日志，只往队列里塞。

还有一个不起眼但指向性极强的细节，证据就藏在 MAT 给的对象地址里：泄漏队列在 0x730019490，替代日志器在 0x730019468，紧挨着堆基址（系统类加载器也就 0x7300148c8）；而引用它的消费线程对象在 0x73013a060，高出整整一段。JVM 分配对象大致按地址顺序往前推，低地址意味着出生在进程启动早期，而且此后从未被回收。雷不是运行期埋的。

带着这个结论去读错误上报组件的源码，一读就对上了：Appender 的启动钩子里，把整条上报链路一次性全建了出来，本地缓冲队列、10 个消费线程、HTTP 异步客户端，eager 到牙齿。而这个启动钩子的执行时机，恰恰是 logback 在解析配置文件的过程中。

机制：SLF4J 的绑定窗口期

到这里所有碎片凑齐了，剩下的就是把机制讲明白。

SLF4J 是个门面，第一次被调用时才去找类路径上真正的后端（本服务是 logback）做绑定。绑定不是瞬间完成的，要扫描类路径、解析日志配置文件，这段时间存在一个"初始化中"的窗口期。窗口期内谁来要日志器，框架只能先发一个替代品顶着：它没有任何输出能力，只会把每条日志包装成事件塞进一个等待队列，说好了等绑定完成再由真身接管。

事故的时序就串起来了。应用启动，某处第一次打日志，主线程开始执行绑定，窗口期打开。绑定的过程本身包含 logback 解析配置，配置里挂着错误上报的 Appender，旧版组件在配置解析阶段就把上报链路整个建好。链路里的消费线程和 HTTP 客户端去拿日志器，全部落在窗口期内，拿到的 22 个日志器全是临时工。绑定完成后，这批临时工无人接管（dump 里委托字段全空是实锤），而消费线程和客户端把它们牢牢攥在字段里，一攥就是整个进程生命周期。

此后每次处理业务错误，链路内部打的日志（带着 URL 编码的完整堆栈）就进那个等待队列。这个队列没有容量上限，没有消费者，永远不会被清空。每上报一个错误塞几条，匀速增长，正好对应监控上那条斜率不变的斜线。

补一句：上报主链路本身从头到尾是好的，业务异常经监控切面打 ERROR，Appender 收进缓冲，消费线程取出来 HTTP 上报告警平台，一天都没断过。坏的是链路自己内部那几条日志，旁路泄漏，最隐蔽的那种。

为什么表现为周期性重启

增长速度取决于业务错误量，稳定线性；其余堆占用平稳。进程总内存匀速爬向容器 limit，撞上就被内核杀掉（137），重启后队列清零，同样的曲线重新爬。周期取决于"错误产生速度 × 单条大小 ÷ 剩余内存余量"，几小时一轮，稳定得像闹钟。

修：把初始化挪出窗口期

定位到根因后反而轻松了，问题不在日志框架，在"日志系统还没就绪就去拿日志器"这个动作。修法一句话：全部推迟到首次上报时再初始化，那个时刻绑定早就完成，拿到的都是真日志器。

问题代码是典型的 eager 写法，对象创建时立即获取日志器：

public class ErrorConsumeThread extends Thread {

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

改成延迟到首次记录错误时获取，volatile 字段允许无害的重复获取竞态，重复获取也就是多问一次工厂，没有副作用：

// 错误日志器。延迟到首次记录错误时获取：本组件常在应用启动配置日志的过程中被创建，
// 该阶段日志框架尚未完成绑定，过早获取会得到无法被日志框架接管的临时日志器，
// 其后记录的错误会无限积压，最终耗尽内存
private volatile Logger logger;

private Logger logger() {
    Logger l = this.logger;
    if (l == null) {
        l = LoggerFactory.getLogger(ErrorConsumeThread.class);
        this.logger = l;
    }
    return l;
}

Appender 的启动钩子同样瘦身，只留参数校验；整条上报链路（含 HTTP 客户端）推迟到第一条错误日志到来时构建，双检锁保证并发首报只建一次，先完整初始化再发布出去：

// 首次上报时才构建上报链路：此时日志框架绑定早已完成，链路内部获取的都是真日志器
private BufferedErrorReporter ensureErrorReporter() {
    BufferedErrorReporter reporter = errorReporter;
    if (reporter == null) {
        synchronized (HttpPostErrorAppender.class) {
            reporter = errorReporter;
            if (reporter == null) {
                reporter = new BufferedErrorReporter();
                reporter.setErrorConsumer(new HttpPostErrorConsumer(targetUrl));
                reporter.init();
                errorReporter = reporter;
            }
        }
    }
    return reporter;
}

测试补了两类。一类是初始化时机的约束，断言配置阶段（构造、启动钩子、类加载）不获取日志器、不建 HTTP 客户端，防止将来有人改回 eager 写法；另一类是行为验证，起一个本地模拟接收端，确认推迟构建之后首次上报依然完整送达。四个模块 20 个测试全绿，组件发版，结算服务升级。

验证与收尾

升级后一条命令就能确认根因消除：

jmap -histo <pid> | grep SubstituteLoggingEvent

修复前这条命令能捞出一个 47 万计数的大类，修复后输出为空。容器内存曲线也平了，斜线消失，那台"闹钟"停了。

回头想，这次最值钱的一条经验是：没有报错的重启，先看退出码，137 说明内核动的手，JVM 没来得及说话，别在应用日志里白费劲。剩下的一路都是让数据牵着走：退出码给死因，斜率给性质，嫌疑报告给主体，直方图给规模，逐实例检查给结论，对象地址给时间。每一步都比拍脑袋快。

另外给服务侧留了个建议：把堆上限压到容器 limit 的 65% 到 70%。这样下次再出内存问题，JVM 会先于内核感知，以能诊断的报错暴露出来，而不是无声被杀后只剩一个 137。