Press "Enter" to skip to content

一次诡异的 Spring Boot 发布后 Full GC 事件排查全记录

一、事故背景:风平浪浪静下的暗流

我们有一个稳定运行的 Spring Boot 应用,日常通过监控平台观察,其 JVM 堆内存(Heap Memory)使用率一直非常平稳,老年代(Old Gen)占用率低,看不出任何内存泄漏的迹象。然而,一个诡异的问题持续困扰着我们:每次发布新版本的程序后,应用启动阶段总会触发一次甚至多次 Full GC

这让人非常困惑,既然平时内存没问题,为什么偏偏在发布这个特定动作后就出现 Full GC?这就像一辆平时开得好好的车,只要一重新点火就必然会“咳嗽”几下。

二、初步分析:监控图表为何会“说谎”?

我们首先排除了常规的内存泄漏。因为如果是内存泄漏,老年代的内存使用率会像一个缓慢上升的斜坡,最终在高位触发 Full GC,而我们的监控曲线一直很平坦。

这里的关键在于,我们平时关注的监控图表,大多是采样数据,反映的是应用稳态运行(Steady-State)时的情况。而发布重启阶段是一个瞬时过程(Transient Phase),内存使用模型可能完全不同。监控图表因为采样率不够高,很可能完美地错过了启动时的内存“风暴”。

因此,我们断定问题一定出在启动过程中,并锁定了几个主要怀疑方向:

  1. 堆内存瞬时压力:启动时创建了海量对象,新生代装不下,导致大量对象过早晋升到老年代,撑爆了老年代。
  2. 元空间(Metaspace)不足:Spring Boot 应用启动需要加载大量的类。发布新版本意味着加载新类,如果旧的类无法被卸载,很容易撑爆元空间。
  3. 代码显式调用 System.gc():某些框架或代码可能会在特定时机“好心”地建议 JVM 进行垃圾回收。

三、深入排查:GC 日志是唯一的真相

为了找到根本原因,我们采取了最重要的一个行动:开启 GC 日志。无论监控图表多么华丽,GC 日志才是记录 JVM 垃圾回收活动最真实、最详细的“黑匣子”。

在 JVM 启动参数中加入:

# Java 8
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/your/gc.log

# Java 9+
-Xlog:gc*:/path/to/your/gc.log:time,level,tags

在下一次发布后,我们果然在 GC 日志中找到了线索。Full GC 的触发原因赫然写着 (Metadata GC Threshold)

真相大白:罪魁祸首是元空间(Metaspace)!

Spring Boot 应用在启动时会加载数千个类,包括框架自身的、第三方库的以及我们业务代码的。当元空间的使用达到一个阈值时,JVM 会尝试通过一次 Full GC 来回收不再使用的类加载器和类元数据。如果设置的元空间上限过小,启动过程中的类加载洪峰很容易就会触发这个机制。

四、解决问题:对症下药

定位到问题后,解决方案就非常直接了。我们为 JVM 添加了明确的元空间大小限制参数,给予其在启动时足够的空间。

-XX:MaxMetaspaceSize=512m

这个值需要根据你的应用实际情况调整,但 512MB 对于大多数中大型 Spring Boot 应用来说是一个比较安全和常见的初始值。

在配置了这个参数后,再次发布新版本,恼人的 Full GC 现象彻底消失了。

五、意外发现与深入理解:一次健康的内存“体检”

在解决了问题后,我们通过一款内存分析工具观察了应用的实时内存状况,这让我们对 JVM 的内存管理有了更深的理解。

第一次内存快照:

名称 使用量 总量 最大用量 使用率
ps_eden_space 1649M 1747M 1749M 94.27%
ps_old_gen 403M 3549M 3549M 11.37%
metaspace 232M 241M -1 0.00%

解读

  • 老年代(ps_old_gen):使用率仅 11.37%,非常健康,再次确认了应用没有内存泄漏。
  • 新生代 Eden 区(ps_eden_space):使用率高达 94.27%,这说明应用的对象创建速率非常快,即将触发一次 Minor GC。
  • 元空间(metaspace):稳态使用量在 232MB 左右,印证了之前默认的元空间大小确实不够用。

第二次内存快照(几分钟后):

名称 使用量 总量 最大用量 使用率
ps_eden_space 1208M 1736M 1736M 69.62%
ps_survivor_space 17M 17M 17M 99.44%
ps_old_gen 425M 3549M 3549M 12.00%
metaspace 243M 255M -1 0.00%

解读

  • Eden 区使用率下降,说明期间发生了一次 Minor GC,大部分对象被回收。
  • Survivor 区几乎被占满,说明有不少对象在 Minor GC 后存活了下来,等待下一次考验。
  • 老年代使用量有非常微小的增长(403M -> 425M),这是正常的对象晋升,增长速度缓慢,非常健康。

关键知识点:解惑 Metaspace 的“总量”与“最大用量”

在观察中,一个数据曾让我们困惑:
metaspace | 243M (使用量) | 255M (总量) | -1 (最大用量)
我们明明配置了 -XX:MaxMetaspaceSize=512m,为什么这里的“总量”是 255M,“最大用量”是 -1?

这里必须理解 JVM 内存管理的三个核心概念:Used(已使用)、Committed(已提交/总量)、Max(最大值)

  • Max (512M): 我们通过 -XX:MaxMetaspaceSize 告诉 JVM,元空间最多可以使用 512MB 的物理内存。这是一个上限。
  • Committed (255M): JVM 并不会在启动时就占用全部 512MB 内存。它会按需向操作系统申请,当前它已经申请并“承诺”会使用的内存是 255MB。这个值就是工具里显示的“总量”。
  • Used (243M): 在已经申请到的 255MB 内存中,JVM 当前实际已经用掉的部分是 243MB。

结论Used ≤ Committed ≤ Max。JVM 的这种动态扩容机制是为了节约系统资源。而监控工具显示的 -10.00% 使用率,是工具自身解析或显示的问题,我们不应被其误导。

我们可以通过 JDK 自带的 jinfo 命令来验证我们的配置是否生效:

jinfo -flag MaxMetaspaceSize <进程PID>
# 输出: -XX:MaxMetaspaceSize=536870912  (即512MB)

六、总结与反思

这次排查是一次宝贵的经历,我们收获了以下几点关键经验:

  1. GC 日志是第一现场:对于 GC 相关问题,GC 日志是最终的、最可信的证据来源,优先级远高于任何监控图表。
  2. 关注应用启动阶段:发布、重启等瞬时阶段的内存行为与稳态时可能截然不同,发布后的 Full GC 问题,元空间不足是首要怀疑对象。
  3. 理解 JVM 内存模型:清晰地区分 Used、Committed 和 Max 的概念,能帮助我们准确解读监控数据,避免被工具误导。
  4. 善用 JDK 原生工具jstat, jinfo 等命令行工具虽然朴素,但在关键时刻能提供最准确的信息。

通过这次事件,我们不仅修复了一个潜藏的问题,还深化了对 JVM 内存管理的理解,为未来更复杂的性能调优打下了坚实的基础。

发表回复

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