☰
JVM垃圾收集器与GC日志分析实战:从HotSpot到JDK1.8调优
2026/10/14 20:59:26 网站建设 项目流程

做Java后端这几年,每逢应用发布前被问最多的问题之一就是:JVM堆内存怎么设?垃圾收集器用哪个?其实很多时候答案早就在GC日志里躺着,只是没几个人肯耐心去看。JVM的垃圾收集器、GC日志分析、HotSpot、JDK1.8这四个关键词凑在一起,基本就是一次线上诊断的完整闭环。这篇文章不打算把规范文档复述一遍,而是想从HotSpot在JDK1.8环境下的真实行为出发,把“有哪些收集器、它们分别在什么场景下干活、日志里每一行都说了什么、怎么看日志发现问题”这条线彻底捋顺,最后给一份可以直接照着背的GC思维导图结构。不管你是刚接手线上服务的新人,还是已经有几年经验但一直靠经验猜配置的老手,这轮内容应该都能对得上。

1. JVM垃圾收集器全景:从分代模型到HotSpot实现

1.1 为什么JDK1.8默认组合是PS+ParallelOld

很多人一开始接触垃圾收集器的时候,都会被一堆名字砸晕,Serial、ParNew、Parallel Scavenge、CMS、G1,还有一堆Old。但如果把视角拉回到JDK1.8这个具体版本,会发现默认组合其实很固定:新生代用Parallel Scavenge,老年代用Parallel Old。这也是Oracle JDK和OpenJDK在8u系列里长期保持的默认策略。

这里首先要理解分代模型的出发点。HotSpot把堆分为新生代和老年代,目的是让不同生命周期的对象走不同的回收路径。绝大多数对象“朝生夕灭”,在新生代就能被清理掉,没必要把它们挪到老年代再花大代价整理。新生代内部又分成Eden区和两个Survivor区,默认比例是8:1:1。这个比例我见过不少项目改过,但说实话大多数业务场景默认值就够了,乱改反而会让对象在Survivor之间来回拷贝,或者提前晋升。

那为什么默认不是CMS,更不是G1,而是Parallel Scavenge + Parallel Old?因为JDK1.8的默认面向的是“吞吐量优先”场景。Parallel系列的核心理念是让垃圾收集线程和应用线程并行执行,尽可能让CPU花更多时间在业务上,而不是频繁停顿。用官方的话说,它关注的是“通过调整停顿时间上限来间接控制吞吐量”,但实际上PS系列更偏重吞吐量最大化。对大多数无状态服务、批量计算任务、内部管理系统来说,这种组合最省心。

这里有个容易踩的认知误区:很多人觉得CMS才是默认,因为网上文章提到CMS多,实际上那个时代CMS常见于低延迟场景,需要手动指定。如果你在启动命令里什么都没加,JDK1.8跑起来的收集器就是PS+PO。所以看GC日志时,看到PSCON和ParOld时不要慌,那不是异常,也不是配了什么怪东西,那就是默认组合的名字。

1.2 七大收集器核心对比与选型逻辑

要真正看懂GC日志,至少得先把HotSpot在JDK1.8里能用的收集器记个大概。我把它们整理成一个粗线条的对比表,重点不是参数,而是“它们关心什么”。

收集器分代线程模式主要目标典型场景
Serial新生代单线程简单、低内存开销客户端应用、小堆、单核
ParNew新生代多线程并行配合CMS服务端新生代并行回收
Parallel Scavenge新生代多线程并行吞吐量优先后台任务、批量计算
Serial Old老年代单线程兜底、CMS失败后备小堆、串行环境
Parallel Old老年代多线程并行吞吐量优先配合Parallel Scavenge
CMS老年代并发标记清除低延迟交互型服务、响应敏感
G1不分代(逻辑上Region)多线程+并发可预测停顿大堆、JDK8后期调优主流

这张表里有一个关键点:CMS是标记-清除,所以会产生碎片,而Parallel Old是标记-整理,会移动对象。碎片的影响在日志里不会直接显示,但会导致老年代明明还有大量空闲空间,却没办法给大对象分配连续区域,最后触发Full GC。这是CMS被嫌弃的核心理由之一。

选型逻辑其实不复杂。如果你的应用是Web接口、实时性要求高、单次请求响应时间重要,那CMS(或JDK8下的G1)通常更合适。如果你的应用是离线计算、吞吐量要求高、偶尔一次停顿可以接受,那默认的PS+PO就是好搭档。最怕的是“不知道自家默认是什么,却按网上CMS调优文章把参数抄一遍”,那样日志看不懂,问题也照不出来。

1.3 一个容易被忽略的点:收集器与内存分配策略的关系

垃圾收集器不是独立工作的,它跟对象分配策略耦合很深。很多GC日志看似奇怪的现象,根源其实在分配策略上,而不在收集器本身。

HotSpot的对象分配顺序大致是这样:新对象优先在Eden区分配,Eden区空间不足时触发Minor GC。如果一个对象体积太大,超过了“大对象直接进入老年代”的阈值,就会直接进老年代。这个阈值可以通过-XX:PretenureSizeThreshold设置,但需要注意它只对Serial和ParNew生效,对Parallel Scavenge并不直接生效。很多人在网上看到“通过这个参数避免大对象频繁在新生代拷贝”,结果发现没效果,就是因为默认收集器是Parallel Scavenge,该参数不生效。

除了大对象,还有一个动态年龄判定。对象在Survivor区每熬过一次Minor GC年龄加一,默认累积到15岁进入老年代。同时HotSpot还有一个动态机制:如果Survivor区中同一年龄的对象大小总和超过Survivor空间的一半,那么年龄大于等于这些对象的对象直接晋升老年代。这个机制在日志里不会打印,但会导致某些对象比预期更早进入老年代,进而影响Full GC频率。

明白了分配策略,再去看GC日志里的“Allocation Failure”就有另一个层次的理解。Allocation Failure是触发Minor GC最常见的GC Cause,解释为“我准备分配新对象,但Eden区空间实在不够了”。它不是一个错误,而是一个常规事件。你要是把日志里的Allocation Failure当成异常去查,大概率会空手而归。

2. GC日志分析实战:从一行日志读出完整故事

2.1 开启GC日志的正确姿势(JDK1.8参数)

在JDK1.8里,GC日志参数和后来的JDK11、JDK17风格完全不同,别用后者的UNIFIED LOGGING方式套在1.8上。常用的一组命令如下:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:/data/logs/gc.log

简单解释一下这组参数的作用。PrintGCDetails会打印详细的GC前后堆内存变化,这是必开的;PrintGCDateStamps会在每条GC日志前加上可读的日期时间,方便跟业务报障时间对齐;PrintHeapAtGC会在GC前后各打印一次堆内存快照,信息量最大,但日志文件会长一些;Xloggc指定GC日志输出路径,注意它一旦指定,GC日志就不再打到stdout,而是写到文件里,这是一个很多人会突然发现“控制台没有GC日志了”的原因。

如果还想额外带上进程启动的耗时,可以用-XX:+PrintGCTimeStamps,它会在GC日志里输出从JVM启动到当前的秒数。这两者不冲突,可以同时开。我自己的习惯是同时开DateStamps和TimeStamps,因为有时候要对比启动时长和GC间隔,秒数比日期更好用。

需要特别提醒的是JDK1.8的GC日志没有自动清理机制。如果不做外部处理,gc.log会一直膨胀,时间长了可以撑出几个GB。有两种常见解法:外部用logrotate定期切分,或者借助JVM参数里的-XX:+UseGCLogFileRotation配合-XX:NumberOfGCLogs和-XX:GCLogFileSize做滚动。后者比较简单,比如:

-Xloggc:/data/logs/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogs=5 -XX:GCLogFileSize=20M

这组参数表示日志滚动保留5个文件,每个文件最多20M。不过在JDK1.8里这个滚动方案有两个小毛病:一是滚动时可能会丢失少量日志,二是文件名后缀会带日期。我一般建议对核心服务既要滚动,也要把GC日志独立放在一个磁盘空间充足的分区,别和业务日志挤在一起。

2.2 逐字段拆解一次Minor GC日志

下面是一次真实的Minor GC日志(字段已脱敏),我用默认PS+PO组合跑出来的:

2024-07-15T10:32:15.123+0800: 382.456: [GC (Allocation Failure) [PSYoungGen: 655360K->87372K(761856K)] 1048576K->475848K(1992192K), 0.0380010 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

第一次看这行日志,可以按顺序拆成六块。

第一块是时间戳,2024-07-15T10:32:15.123+0800,这是PrintGCDateStamps输出的带时区的时间。后面跟的382.456是JVM启动秒数,也就是说这个GC发生在JVM启动约6分22秒之后。

第二块是GC类型标记,[GC (Allocation Failure) [PSYoungGen: ...]]。这里的GC表示一次Minor GC,并不代表系统停顿非常严重。Allocation Failure是触发原因,前面说了,就是分配新对象时Eden区空间不够。

第三块是PSYoungGen内部变化,655360K->87372K(761856K)。箭头左边是GC前新生代已用内存,右边是GC后新生代已用内存,括号里是新生代总容量。新生代总容量761856K不是固定的,Parallel Scavenge会根据运行情况做动态调整,这跟-XX:UseAdaptiveSizePolicy有关系。如果你希望手工固定,可以用-XX:SurvivorRatio和-Xmn来显式配置,但默认自适应调整也不是坏事。

第四块是整堆变化,1048576K->475848K(1992192K),这就是新生代+老年代合计的已用空间和总量。GC后整堆还有475MB,这是正常现象,因为存活对象总要留在某个地方。

第五块是耗时,0.0380010 secs,大约38毫秒。

第六块是[Times: user=0.04 sys=0.00, real=0.04 secs],user是CPU用户态耗时,sys是内核态耗时,real是实际墙钟时间。在多线程GC时real通常会小于user,因为多个GC线程并行处理。

这一行日志能告诉我们什么?如果它频繁出现,而且每次GC后新生代占用都基本持平,说明新生代对象分配速率很高,但绝大多数存活不下来,这就是典型的“新生代吞吐高,没有内存泄漏”的信号。如果GC后新生代已用从87372K慢慢爬升到两三百M,就得怀疑是不是有对象一直在Survivor区来回存活,导致动态晋升过快。

2.3 Full GC日志与CMS/G1日志特征

Full GC日志比Minor GC要沉重得多。在默认PS+PO下,一次Full GC日志往往长这样:

2024-07-15T11:20:03.789+0800: 1081.233: [Full GC (System.gc()) [PSYoungGen: 0K->0K(761856K)] [ParOldGen: 1258291K->1256683K(1398272K)] 1258291K->6683K(1992192K), [Metaspace: 11823K->11823K(1056768K)], 0.8726090 secs]

注意这里有个很扎眼的现象:老年代从1258291K变成1256683K,只释放了1.6M左右,而且Full GC之后老年代几乎没降。触发原因是System.gc(),说明有代码显式调用了垃圾收集。这种情况在JDK1.8下要额外小心,因为System.gc()在默认参数下会直接触发Full GC,不是建议性调用。遇到这种日志,第一反应是去代码里查谁在调System.gc(),最常见的情境是某些框架清理缓存、堆外内存管理、或者有人写测试代码时随手加了一句。

在启用CMS的情况下,日志结构会完全不同。你会看到大量带CMS阶段的日志,比如:

2024-07-15T10:40:00.111+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1398272K(1398272K)] ... 2024-07-15T10:40:00.211+0800: [CMS-concurrent-mark-start] 2024-07-15T10:40:00.523+0800: [CMS-concurrent-mark: 0.312/0.312 secs] 2024-07-15T10:40:00.523+0800: [CMS-concurrent-preclean-start] ...

CMS的Initial Mark和Remark阶段会造成STW(Stop The World),但是通常比Full GC短很多,中间Concurrent Mark阶段应用线程跟GC线程是并发跑的,所以整体用户体验要平滑一些。有没有坑?当然有,CMS最经典的问题就是Concurrent Mode Failure:并发清理的速度跟不上老年代增长,CMS被迫退化到Full GC,一次停顿可能几百毫秒甚至一秒以上。这个问题会在日志里明确打印“Concurrent Mode Failure”字样,看到就该立刻关注老年代增长曲线。

G1在JDK1.8上的日志风格又不一样,典型特征是带“pause”字样,比如:

[GC pause (G1 Evacuation Pause) (young) (initial-mark) 512M->200M(2048M), 0.0234321 secs]

G1把停顿分为Young-Only和Mixed两种,重点看“Mixed”停顿,那是清理老年代对象的阶段。这篇博文以JDK1.8默认PS为主,CMS/G1日志细节不展开太多,但你要有能力“认出”它们,别在日志里看到ParOldGen就以为系统出错。

3. 思维导图式记忆框架:GC知识体系化

3.1 以思维导图形式整理核心节点

给出一份文字版思维导图,方便大家当索引用。把所有关键节点列成树状结构,你可能需要根据自己习惯增减。

JVM GC 知识框架 ├── 1. 内存区域 │ ├── 线程私有:虚拟机栈、本地方法栈、程序计数器 │ └── 线程共享:堆、方法区(JDK8中为Metaspace) │ ├── 堆:新生代(Eden+Survivor×2)、老年代 │ └── Metaspace:类元数据,默认无固定上限 ├── 2. 分代与分配 │ ├── 新对象优先Eden │ ├── 大对象直接进老年代(PretenureSizeThreshold) │ ├── Survivor动态年龄判定 │ └── Minor GC / Major GC / Full GC 概念 ├── 3. HotSpot收集器 │ ├── 新生代:Serial / ParNew / Parallel Scavenge │ ├── 老年代:Serial Old / Parallel Old / CMS │ └── 全局:G1(Region化) ├── 4. 关键参数 │ ├── -Xms / -Xmx 堆初始和最大 │ ├── -Xmn 新生代大小 │ ├── -XX:NewRatio 老年代与新生代比例 │ ├── -XX:SurvivorRatio Eden与Survivor比例 │ ├── -XX:MaxTenuringThreshold 晋升年龄 │ ├── -XX:+PrintGCDetails / PrintGCDateStamps / PrintHeapAtGC │ └── -XX:+UseGCLogFileRotation 日志滚动 ├── 5. GC日志字段 │ ├── 触发原因 Allocation Failure / System.gc / Concurrent Mode Failure │ ├── GC类型 Minor GC / Full GC / CMS阶段 / G1撤离停顿 │ ├── 内存变化 区域名 前->后(容量) │ ├── 耗时 用户态/内核态/墙钟时间 │ └── Metaspace 单独一行 ├── 6. 指标观察 │ ├── 吞吐量 = 业务时间 /(业务时间+GC时间) │ ├── 停顿时间 单次GC的real耗时 │ ├── GC频率 适合用jstat观察趋势 │ └── 晋升情况 老年代增长曲线 └── 7. 调优手段 ├── 调整堆大小 ├── 调整新生代大小 ├── 更换收集器(CMS/G1) ├── 降低Full GC频率 └── 代码层面:减少短命大对象、避免System.gc

这张思维导图是我整理给自己的,并不追求覆盖全部参数,但把“内存结构->收集器->日志字段->调优”串成一条主线。初学者可以照着这个框架去逐项展开,有经验的人也可以拿它来检查自己是否在某个分支上有缺口,比如“我熟悉CMS但不知道Metaspace日志怎么看”这类盲区。

3.2 如何把GC日志分析变成性能调优的输入

日志是给人看的,不只是用来事后追责。GC日志真正的价值在于它能告诉你系统的内存行为是否健康,进而给你调优方向。在JDK1.8默认PS+PO下,我习惯先用三个维度去评估,再决定要不要动手。

第一个维度是GC频率。记一下每分钟Minor GC次数和Full GC次数。如果Minor GC每秒都好几次,说明新生代容量相对于对象分配速率太小。更优解往往是调大-Xmn,给新生代更多空间,或者干脆调大整个堆。但如果对象分配速率本身就高,光调堆也只是延缓现象,需要从业务代码减少临时对象数量。

第二个维度是停顿耗时。单次Minor GC一般都在几十毫秒以内,超过100ms就要警惕。单次Full GC如果超过300ms,基本已经会对RT敏感业务产生可感知影响。停顿时间高低跟GC线程数、对象数量、GC算法都有关系,必要时可以显示指定-XX:ParallelGCThreads,但不要盲目调大线程数,线程太多反而引起竞争。

第三个维度是晋升情况。通过前后对比老年代占用,如果老年代每次Full GC前都逼近容量上限,说明晋升速率太快,可能有大量长生命周期对象,或者Survivor空间配置不合理。此时单纯增大老年代只会把Full GC往后挪,真正的问题是对象本身寿命长,应该考虑是否为这些对象设计了正确的容器大小,甚至重构缓存策略。

GC日志分析不该是救火工具,而应该是日常监控。拿到几天前的gc.log,把Full GC次数和业务发布、流量高峰对齐,很多内存问题是可以提前发现的。比如“发布新版本后老年代增长斜率明显变大”,这就是一个非常典型的回归信号,甚至不需要看业务日志就能定位到大致时间点。

4. 常见问题与排查技巧实录

4.1 GC日志时间与系统时间不一致

这个问题踩过的人很多。JDK1.8里PrintGCDateStamps输出的是JVM打印日志那一刻从操作系统取到的时间,而操作系统时间一旦被NTP校准或人工调整,GC日志里的时间会突然跳变。如果发现某一天的GC日志时间对不上业务报障时间,先别怀疑GC日志参数,先看看系统时间和时区。

另外PrintGCTimeStamps输出的是JVM启动后的秒数,这个值是单调递增的,不受系统时间调整影响。所以在做时间对比时,我经常优先看JVM启动秒数。比如业务日志记录的时间是10:32:15,对应GC日志里的382.456秒,反过来就能计算出启动时间。一旦系统时间被改过,日期时间戳会乱,但秒数不会骗人。

排查技巧:在JVM启动参数里加上-XX:+PrintGCTimeStamps,和业务日志中的相对时间配合使用。如果业务日志有自带的启动秒数,做一次换算就能把GC和请求的时间对齐。这个方法在大量历史日志需要复盘时特别好用。

4.2 GC日志文件过大与滚动策略

GC日志能撑出多大,完全看业务的分配压力和配置的详细程度。开了PrintHeapAtGC之后,单次GC日志长度会明显变长,如果一天几千次GC,一个文件几个GB不是玩笑。

前面提到过UseGCLogFileRotation,这在JDK1.8里是官方支持的滚动方案。要注意的是,JDK1.8的滚动日志文件命名有坑:当文件滚动时,老文件会在文件名后自动追加.0、.1这样的后缀,但如果你同时开了PrintGCDateStamps,控制台输出与文件输出混排时可能导致日志记录丢失。在一些极端情况下还会出现“滚动文件数量超过NumberOGCLogs后旧日志被删除但新日志没写进去”的怪问题,重启应用后会发现gc.log缺失一截。

我个人的实践是:核心服务把GC日志放在独立目录,用外部logrotate按天或按大小切分,保留最近7天。这样即使JVM滚动方案有问题,外部系统也能兜底。如果有容器或云原生环境,直接把GC日志输出到标准输出然后由日志采集系统统一采集,也是一个可靠的方向。

4.3 GC日志缺失或未生成的具体排查

你明明加了-Xloggc参数,但发现gc.log里没内容,或者压根没生成文件。这种情况按下面顺序排查,基本都能定位。

第一步看启动命令有没有生效。用ps -ef | grep java确认进程完整启动参数,好多时候改完脚本忘了重启,或者脚本里有两份JVM_OPTS,后一份覆盖了前一份。

第二步看权限。JVM进程启动用户对日志目录有没有写权限,目录是否存在。如果目录不存在,JVM一般不会自动创建,而是直接报错或悄悄跳过。你可以先手动mkdir -p让目录存在再启动。

第三步看是否被容器日志重定向。在Docker或K8s中,如果Xloggc指向的是容器内路径,而容器重启后文件就被清掉,要注意挂载卷是否覆盖了路径。这种情况表面上是“没GC日志”,实际上是“日志写进了另一个临时文件系统”。

第四步用jcmd验证:

jcmd <PID> GC.rotate_log

这个命令在JDK1.8里可以手动触发GC日志滚动。如果命令返回正常,说明JVM的GC日志模块是活的。如果返回Unknown command,说明JVM启动时可能没有开启对应的日志打印参数。

4.4 一组实战调优案例(模拟)

这里用一个模拟场景演示日志分析思路。假设你有一个后台数据处理应用,堆设置是-Xms2g -Xmx2g,新生代默认。没有显式指定收集器,也就是PS+PO。

打开gc.log,发现每隔一分钟就有一次Full GC,每次Full GC耗时接近800ms,老年代回收前后从1.5G降到1.2G,但很快又涨回去。再往上看Minor GC记录,发现新生代每次GC后Survivor占用从几十M缓慢爬到几百M,而且对象晋升年龄往往在2左右就有一批进入老年代。

这个模式说明什么?Survivor空间过小,动态年龄判定提前触发,对象过早晋升到老年代,老年代空间被迅速填满,导致Full GC频繁。重点不是老年代不够大,而是晋升年龄太低。针对这种情况,可以考虑把-Xmn调大,让新生代拥有更大内存,同时用-XX:MaxTenuringThreshold调整晋升年龄,或者用-XX:SurvivorRatio=8给Survivor更合理空间。

于是做两步调优:把-Xms和-Xmx保持2g不变,但-Xmn从默认调整到1g,同时SurvivorRatio设为8。之后再观察日志,Minor GC频率下降,晋升到老年代的对象减少,Full GC从一分钟一次变成几小时一次。整个过程没有改业务代码,纯粹通过Log Mining定位到晋升策略异常。

这里有个原则必须强调:调优不要一次改一堆参数,逐项验证效果才能知道哪个参数真正起作用。模拟场景里我同时改了-Xmn和SurvivorRatio,虽然结果不错,但如果效果不好,定位就比较麻烦。遇到线上服务,更稳妥的做法是先只调-Xmn,观察一天,再动SurvivorRatio。

4.5 辅助命令:jstat与GC日志搭配使用

GC日志是事后分析,jstat是实时观察,两者结合,判断效率会高很多。常用的jstat命令如下:

jstat -gc <PID> 1000 5

这表示每隔1000毫秒输出一次GC统计,共输出5次。各列的含义不再逐一展开,但关键关注S0C、S1C、EC、OC这几个容量列,以及YGC、FGC、GCT这几个累计值。一个实用技巧是观察FGC(Full GC次数)是否持续增长,结合GCT看累计停顿时间。如果FGC在某个时间点突然跳动,立刻去回看那一时间段的GC日志,定位触发原因,比盲猜要精准得多。

jstat配合jmap或jcmd,还可以查看类加载和堆转储信息。不过本篇主题是GC日志,这些辅助工具点到为止。我的经验是:把jstat定时采集结果也存下来,例如借助监控系统每5秒采样一次,持续几天,就能做GC趋势曲线。趋势线比单条日志信息量大多了,尤其能发现“老年代容量每周缓慢上涨”这种早期泄漏特征。

结尾

真要说GC日志分析有什么诀窍,我觉得就四个字:养成习惯。很多内存问题不是一出事就知道的,而是潜伏几周甚至一个月才爆发出来。如果应用一上线就把完整GC日志打开,同时配好滚动和采集,你会比别人多出一大截“历史视野”。等到线上出问题时,翻日志定位原因,比临时加参数重启快得多。

一个小技巧收尾:在JDK1.8下排查GC问题,如果发现某一段日志里Full GC的“System.gc()”字样反复出现,别急着调堆参数,先用jstack抓一下线程栈看看是谁在调用System.gc。有时候是框架自动触发的,有时候是代码里一行“好心”注释掉的测试语句,找到源头比调整堆结构更省力。把GC日志当成一个常开的体检仪,而不是一台救火车的警铃,这份功夫绝对值得下。

需要专业的网站建设服务?

联系我们获取免费的网站建设咨询和方案报价,让我们帮助您实现业务目标

立即咨询