Java开发日志：一次线上内存溢出问题的排查与反思

凌晨一点四十七分手机在床头柜上震动像一只被踩住翅膀的知了。我摸到屏幕钉钉群里的红色告警正一闪一闪生产A应用内存使用率超过95%服务已OOM并自动重启。这是当天第三次了。前两次我都以为只是流量峰值压垮了堆看着监控曲线跌回低点便转身睡去。但这一次我坐到了电脑前决定把问题彻底挖出来。同一批机器白天一切正常一到夜间定时任务跑起来就出问题。我打开监控面板调出最近24小时的内存曲线。内存从凌晨一点开始缓慢爬坡持续十分钟后突然断层——那是JVM崩掉、k8s拉起新Pod的信号。重启后内存回到低点但新Pod像踩了油门一样继续往上爬。故障日志里除了OutOfMemoryError还有一些任务超时的堆栈堆栈都指向同一个批处理入口。我先用jmap -histo:live快速扫了一遍存活对象的分布。结果并不意外排在前面的是byte[]但数量非常多。真正让我皱眉的是即使我在GC之后立刻执行histobyte[]的总量也没有明显下降。这说明这不只是“一次性大对象”的问题而是一些byte[]一直被别的东西引用着根本收不掉。生产环境最可怕的不是报错而是重启后一切如常。只要你没抓到时机的堆转储根本不知道是谁吃掉了内存。我决定等下一次内存爬到80%时直接抓全量堆转储。GC日志里的老年代像一条溺水者的手臂等待期间我翻了GC日志。Full GC几乎每隔一分钟就触发一次每次耗时两三秒。老年代回收前后的占用率差不了多少每次只降几个点又立刻涨回去。这是典型的“持续泄漏”特征——堆里存在一批可以被GC标记、但永远无人回收的对象。更奇怪的是这种上涨不是从0开始的而是从凌晨一点批处理启动后才出现。白天同样有大量请求却没有增长。内存溢出是会在不同实例间“轮岗”的谁能触发取决于它当时手里攒了多少垃圾。我横向对比了所有节点发现每个Pod在批处理时段都有内存抬升只是幅度不同。有些Pod因为白天流量高内存本来就不低反而没有触发阈值偏偏那几个空闲节点的内存底数低抬升之后就越过了90%。把堆摊开顺着强引用往上游走凌晨两点半监控告警再次响起。我立刻让运维执行jmap -dump:live,formatb抓下一份三四个G的堆转储。下载到本地后我用MAT打开点开Dominator Tree按保留堆排序。排在第一的是一个byte[][]数组大小接近300MB。它太惹眼了但我克制住了“就是它”的冲动因为Java里byte[][]太常见了可能是网络缓冲、文件缓存也可能是业务数据。必须找到是谁引用了它。在MAT里勾掉弱引用和软引用只保留强引用路径顺着这个byte[]往上走。路径很快收窄到一个类UserContextHolder。这是一个ThreadLocal的静态引用而ThreadLocal的value里挂着一个包含了完整用户资料、权限列表的UserProfile对象。这个对象里有一个字段是byte[]正好指向了那300MB的数组。把堆摊开看你会发现所有疯狂的对象背后都站着一个看似无辜的持有者。UserContextHolder的代码很简单一个静态ThreadLocal提供set/get/clear三个方法。看起来人畜无害。但搜索代码库时我发现在拦截器里只有set和get没有clear。请求结束时谁都没有调用clear。ThreadLocal留下的“遗产”这里有一个关键认知拦截器在每个请求进来时调用UserContextHolder.set(profile)下一次请求又会用新的profile覆盖旧的引用。只要请求是并发的每个线程各自维护自己的ThreadLocal旧值会被新值替换变成垃圾后正常被GC回收内存不会持续增长。但批处理任务打破了这种平衡。夜间批处理从同一个线程池里拿线程执行任务。任务内部调用了一个老接口这个老接口在实现时顺手把当前用户信息set进了UserContextHolder。批处理循环每次处理一个用户就set一次从不remove。关键是批处理的任务量与线程数不匹配——线程池里只有十几个线程而循环可能跑几百次。同一个线程执行多次循环ThreadLocal里的旧值永远被下一个用户覆盖但问题来了覆盖前旧值是强引用不可回收覆盖后旧值虽然成为垃圾可如果新值里带着一个巨大的byte[]内存就会迅速膨胀。线程池复用线程也复用了上一位请求留下的“遗产”。这比在普通请求里泄漏更隐蔽因为你永远不知道上一次在同一个线程里跑任务的是谁。为什么偏偏是在白天不爆呢因为白天的请求量足够大线程被高频复用每个线程上的ThreadLocal几乎每毫秒都被新请求覆盖旧对象很快变成垃圾GC能及时收走。而夜间批处理并发低很多线程长时间闲置但ThreadLocal的值并不会因为线程闲置而消失。更糟的是批处理里set进去的用户对象画像字段为了省一次外部RPC被序列化成base64再转成byte[]直接变成了接近300MB的庞然大物。一个线程跑几十次循环内存里就有几十个版本的引用虽然最后只留着最后一个但每一次替换都意味着几百MB的垃圾需要GC去回收。GC速度赶不上生产速度老年代就满了。任何“用完就不管”的代码都是在给下一场故障埋单。尤其当你把“用完”的边界定义在请求生命周期上却忘了线程的寿命比请求长得多。修复只差一个finally定位到这一步修复方案已经清晰。第一件事在拦截器的finally块里加上UserContextHolder.remove()确保每个请求无论成功失败都不留下任何线程局部残留。第二件事在批处理的任务入口处做一个防御性清理先clear()再执行业务执行完毕后再clear()一次。这两行代码成本极低却直接消掉了整条泄漏路径。还有一个细节那个老接口为什么会在内部set因为它是历史接口为了让上层代码能够访问当前用户上下文它在实现里自行做了set。但兼容不能以泄漏为代价。我给这个接口内部也套上了try/finally让set显式配对。三处改动部署后观察了三个夜间周期内存曲线平稳下来老年代没有持续抬升Full GC的频率从每分钟一次降到一天个位数。我们没有给这条ThreadLocal套上finally的保险绳。任何人都知道finally是干什么的但真正写代码时总会有人忘记我put进去的凭什么还要我来remove这个“凭什么”就是灾难的起点。这口锅到底谁来背排查到这里很多公司会选择写一篇复盘把责任归给“没加remove的人”。但我不这么认为。那个写代码的人只是沿着现有的便利路径走了一步看到别人都在用ThreadLocal传上下文看到这个老接口有set方法他自然会认为“框架会在合适的时候清理”。真正的问题在于我们从来没有在代码库层面定义过ThreadLocal对象的生命周期规则。它是不是必须和请求同生共死是不是线程池中的线程可以被视为安全的上下文载体这些规则没有写下来于是每个人都在做局部最优解最后拼出一个全局失控。内存泄漏很少是一个瞬间的错误往往是一连串约定俗成的简化。为了省一次RPC而缓存大对象为了方便取用而使用ThreadLocal因为相信“下次会被覆盖”而不清理每一个单独看都说得通合在一起就是定时炸弹。另外我们的监控体系也有短板。如果当时有按线程维度展示ThreadLocal引用大小的能力或者有自动堆转储的规则不需要人到半夜爬起来抓dump故障时间可以缩短三分之二。排查内存问题最怕的就是盯着堆的大小。堆只是结果真相在引用链里。定位内存问题最忌讳只看堆的大小要追的是谁还握着那把“不放手”的强引用。掌握引用链分析的能力比记住任何JVM参数都重要。反思三个用事故换来的约定这次事故之后团队做了三件事。第一给监控加了维度除了内存使用率还要导出老年代大小和GC耗时并设定“老年代在非高峰期持续增长”的告警规则而不是等到OOM才通知。第二调整了压测场景测试环境必须模拟生产环境的线程池复用和定时任务调度不能只跑功能用例。第三在代码规范里明确了一条死规矩任何用到ThreadLocal的地方必须在同一个逻辑单元的finally里调用remove不允许有例外。代码评审时这条作为必查项。也许有人会觉得这是小题大做一条ThreadLocal泄漏而已。但我知道真正昂贵的不是事故本身而是那些没有被写进复盘里的细节。比如那个base64转byte[]的“优化”如果没有把这根线捋出来下一次换一种写法可能又是一场OOM。再比如批处理任务与请求任务共享同一个线程池这本来是为了提高利用率但同时也让请求上下文泄漏到了批处理线程里。这些细节事故后如果不沉淀三个月后再犯一遍是迟早的事。真正昂贵的不是事故本身而是那些没有被写进复盘里的细节。写这篇文章时我还会想起那个凌晨为什么第一次OOM时我没有立刻去抓dump因为我默认它像以前一样重启就好了。事实上每一次自动恢复都在掩盖一个正在腐坏的结构。修复上线后的某天下午我打开那个老接口的代码看到finally里那行UserContextHolder.clear()忽然觉得安心了不少。这行代码不是锦上添花而是底线。Java的GC帮我们解决了大部分内存回收但它也关掉了一扇门开了一扇窗我们不再关心内存于是更容易在不知不觉中留下强引用。对象是谁创建的谁负责销毁——这句老话至今仍然有效。内存是有限的线程是复用的生命周期是需要管理的。别再相信“以后会清理”这种鬼话。用代码去兜底而不是用人脑去记。如果你也遇到线上反复OOM记住第一件事停掉自动重启把现场保住。因为每一次重启都是给下一次故障留的引子。