本文 的 原文 地址原始的内容,请参考 本文 的 原文 地址本文 的 原文 地址 尼恩说在前面在40岁老架构师 尼恩的读者交流群(50+)中,最近有小伙伴拿到了一线互联网企业如得物、阿里、滴滴、极兔、有赞、希音、百度、网易、美团的面试资格,遇到很多很重要的面试题: - 看过GC日志吗?
- 看 gc日志 , 要关注哪些核心点?
最近有小伙伴在面试京东、 阿里、希音等大厂,又遇到了相关的面试题。 小伙伴 没系统梳理, 支支吾吾的说了几句,面试官不满意, 挂了。 接下来 尼恩结合互联网上的一些实际案例, 大家做一下系统化、体系化的梳理。 使得大家内力猛增,可以充分展示一下大家雄厚的 “技术肌肉”,让面试官爱到 “不能自已、口水直流”,然后实现”offer直提”。 当然,这道面试题,以及参考答案, 会收入咱们的 《尼恩Java面试宝典PDF》V175版本,供后面的小伙伴参考 ,帮助大家进大厂/做架构。 最新《尼恩 架构笔记》《尼恩高并发三部曲》《尼恩Java面试宝典》的PDF,请关注本公众号【技术自由圈】获取,回复:领电子书 一、GC 是心电图, 记住尼恩看GC日志的10字口诀GC 日志不是天书,而是运行时体检表。 也可以 把GC 日志 当成心电图,先找“心跳节拍”和“血压余量”。 尼恩给大家 梳理一个 尼恩看GC日志的 10字口诀中 ——三停三大小,升降失败抛。 像老中医搭脉,三指搭下去, healthy 还是 critical,十秒就有答案。 记住尼恩看GC日志的 10字口诀 “三停三大小,升降失败抛”——像老中医一样,搭脉十秒,辩证三分钟,下药一生效。 线上毛刺、Full GC、OOM 都能在“图穷匕见”之前被摁住。 1、三停(GC 异常信号):STW 的“心脏骤停”,冻住全世界10字口诀中的 三停 把 Young 停顿、Full 停顿、连续停顿三种“场景”合称“三停”,日志里只出现 real 值。 其实只有 1 个停:Pause Young 或 Pause Full 后面的 real=xx.xxs 日志里最扎眼的,莫过于 Pause Young 或 Pause Full 后面跟着的 real=0.123s。 这就是 JVM 世界里的“心脏骤停”——整个世界冻住的时间。 Young GC 的 real 时间,最好像眨眼一样,百毫秒以内; Young GC 的 real 时间 , 偶尔一次 120 ms 尚可原谅,连续两次飙过 100 ms,就要拉警报了——接口毛刺、用户抖屏、链式超时,往往从这儿开始。 Full GC 的 real 时间,是“大手术”,目标别超过 1 秒; 一旦看到 2 s、3 s,基本等于给用户发了一张“503 体验券”。 记住,real 才是真实停顿,user/sys 只是 CPU 的“忙碌假象”,别被迷惑。 2、三大小(内存余量):内存的“血压余量”10字口诀中的 三大小 就是 3 组容量数字: - Young 区 total
- Old 区剩余(capacity − used)
- Metaspace 剩余(capacity − used)
把内存想成三座水库,Young、Old、Metaspace,日志里分别写着: [code] PSYoungGen total 1024M, used 800M ParOldGen total 2048M, used 1700M Metaspace used 480M, capacity 512M [/code] 一眼扫过去,算差值: - Young 区大小则像“心率”,如果 total 值忽大忽小, 说明 JVM 在动态调整,频繁调整本身就意味着“压力不稳”,值得继续往下翻日志找原因。
- Old 区剩余 348 M,不足 30 %?——警戒线,再晋升一波对象就可能溢出。
- Metaspace 只剩 32 M,占用率 > 80 %?——如果 类加载再猛一点,就会触发 FGC 扩容甚至 OOM。
3、升降(对象晋升速率):对象晋升的“流速”10字口诀中的 升降 指的都是 1 个流速: 每次 Young GC 后 Old 区增长的数值 ÷ 间隔时间,即“晋升速率”。 (from→to→Old 的箭头里只取 Old 增量,所谓“升降”是代称)。 比如, 每次 Young GC 都会打印一串箭头: [code] from 40960K->4096K, to 4096K->8192K, Old 700000K->750000K [/code] 如果要计算 对象晋升的“流速”,把 Old 区前后的差值拎出来,再除以 本次 GC 与上次 GC 的间隔秒数,就能算出“每秒晋升量”。 - < 20 MB/s,风平浪静;
- 20–50 MB/s,略有压力;
- > 50 MB/s,就是“晋升洪峰”——相当于把 Eden 的幸存者一股脑儿灌进老年代,Survivor 区瞬间成摆设。
如果出现 “晋升洪峰” , 这时要嘛把 Survivor 调大,要嘛让对象早点“死”,否则老年代水位会肉眼可见地上涨,Full GC 就在不远处招手。 4、失败(GC 异常信号):担保与回退的“急救信号”10字口诀中的 失败 → 只要看见这三个字符串任一即可: promotion failedconcurrent mode failureEvacuation Failure- 它们都代表“担保/并发/复制”失败,将触发意料之外的 Full GC。
日志里一旦出现三个 失败,等于 JVM 发出了“急救车鸣笛” : [code] promotion failed concurrent mode failure Evacuation Failure [/code] - promotion failed:Minor GC 时发现老年代“装不下”晋升对象,只能退化到 Full GC。
- concurrent mode failure:CMS 或 G1 并发阶段没跑完,老年代就满了,被迫 STW 回收。
- Evacuation Failure:G1 的复制阶段找不到空闲 Region,直接卡死。
看到这三个词,立刻翻前面的 Old 剩余、Survivor 占比、晋升速率, 赶紧去找根因; 同时盯紧 GC 次数是否瞬间翻倍,这往往是性能断崖式下跌的拐点。 5、抛(OOM 前兆):OOM 的“临终心电图”10字口诀中的 抛 → 也只有一处: - 日志末尾出现
OutOfMemoryError - 或 连续打印
Full GC (Ergonomics) 且回收率 < 2 %(预示即将 OOM)。这就是“抛异常”前的临终信号。
最末尾,如果 Full GC (Ergonomics) 像复读机一样出现: [code] Full GC (Ergonomics) 耗时 3.2s,回收 1 % Full GC (Ergonomics) 耗时 3.5s,回收 0.8 % [/code] 连续 5 次回收率 < 2 %,基本等于宣判“抢救无效”——再往下,即将就是熟悉的 java.lang.OutOfMemoryError: Java heap space。 此时距离进程被杀只剩 分钟级,需要进行立刻急救: - 抢 dump(
jmap -dump:format=b), - 抢扩容(加 Pod、加
-Xmx), - 抢下线(摘掉流量,别让用户陪葬)。
GC 日志不是天书,而是运行时体检表。 记住“三停三大小,升降失败抛”——像老中医一样,搭脉十秒,辩证三分钟,下药一生效,线上毛刺、Full GC、OOM 都能在“图穷匕见”之前被摁住。 6、 尼恩10字口诀 总结记住尼恩看GC日志的10字口诀, 直接让面试官 目瞪口呆、口水直流,吊打面试官。 二、GC 基础原理想要看懂GC日志,需要对GC基础原理有基本认识,下面对于GC基础原理,做系统的总结梳理 1、GC分代思想现代 GC 普遍采用分代收集策略,其核心思想是根据对象存活时间的不同,将堆内存划分为新生代和老年代两个主要区域,并采用不同的回收算法提升效率。 新生代:专门存放生命周期短的对象,内部划分为Eden区和两个Survivor区。 新对象首先分配在Eden区,当空间不足时触发Minor GC。存活的对象会转移到Survivor区,每经历一次GC年龄增加1岁,当超过阈值(默认15次)后晋升到老年代。 老年代:存放长期存活的对象。由于对象存活率高,通常采用标记-清除或标记-整理算法进行Full GC。 元空间: 此外,Java 8用元空间取代了持久代,将类元数据存储到本地内存,避免了之前持久代容易内存溢出的问题。 2、GC 事件分类根据垃圾收集回收的区域不同,垃圾收集主要分为: - Young GC / Minor GC(年轻代GC / 小型GC)
- Old GC / Major GC(老年代GC / 大型GC)
- Full GC(完全GC)
- Mixed GC(混合GC)G1收集器特有
2.1 Young GC / Minor GC(年轻代GC / 小型GC)这两个术语指的是同一种GC。当年轻代(Young Generation) 中的 Eden区 被对象填满时,就会触发一次Young GC。 年轻代GC目标回收年轻代中的死亡对象,并将存活的对象转移到Survivor区(From或To),或者晋升(Promote) 到老年代。 年轻代GC 触发非常频繁, 速度通常较快(但取决于存活对象的数量)。 Young GC 会发生 "Stop-The-World"(STW),即暂停所有应用线程。 2.2 Old GC / Major GC(老年代GC / 大型GC)Old GC 指的是只回收老年代(Old Generation) 的垃圾收集。 纯粹的 Old GC 其实很少见。 - 像 CMS 这样的收集器的主要工作模式是并发收集老年代,可以算作一种 Old GC。
- 而 G1 中的 Mixed GC 不仅回收老年代,也回收年轻代。
注意: Major GC 这个术语在官方规范中并没有明确的定义。有人用它指代 Old GC,也有人用它指代 Full GC。 2.3 Full GC(完全GC)指一次回收整个堆内存的垃圾收集,包括年轻代、老年代,通常还会包括方法区(元空间)。 Full GC 基本触发条件: - 条件1: 老年代空间不足:当对象从年轻代晋升到老年代,但老年代剩余空间不足时触发。
- 条件2: 空间分配担保失败:在发生Young GC之前,JVM会检查老年代, 确定 老生代 最大可用空间是否大于年轻代所有对象总和。如果小于,则触发Full GC。
- 条件3: 方法区(元空间)空间不足。
- 条件4: 显式调用
System.gc()。
2.4 Mixed GC(混合GC)这是 G1(Garbage-First)收集器的特有概念。 混合GC 既回收年轻代,也回收一部分老年代区域。 混合GC 触发条件:在G1的并发标记周期之后,G1已经知道哪些老年代区域(Region)包含的垃圾最多。 Mixed GC会: - 像Young GC一样,回收所有的年轻代区域。
- 同时,选择性地回收一部分垃圾最多的老年代区域。
Mixed GC目标:在可控的停顿时间内,获得尽可能高的回收效率。 | GC类型 回收范围 触发条件 特点 追求目标 | | Young GC (Minor GC) | 只回收年轻代 | Eden区满 | 频繁、快速、STW | 速度 | | Old GC (Major GC) | (理论上)只回收老年代 | 老年代满(少见) | 含义模糊,尽量避免使用此术语 | (不明确) | | Full GC | 回收整个堆 (Young+Old+Metaspace) | 空间分配担保失败、老年代/元空间满 | 停顿时间长,需避免 | 彻底回收 | | Mixed GC (G1特有) | 回收全部年轻代 + 部分老年代 | G1并发标记周期后 | 停顿时间可控 | 效率与停顿的平衡 |
Mixed GC 是G1避免Full GC的关键手段。 3、内存分配规则JVM 通过几条核心规则来管理对象的内存分配,确保内存使用的高效性。 规则1:对象优先在 Eden 区分配大多数新创建的对象会在新生代的 Eden 区进行分配。当 Eden 区空间不足时,会触发 Minor GC 进行垃圾回收。 规则2: 大对象直接进入老年代通过 -XX:PretenureSizeThreshold参数可设置大对象阈值。超过该大小的对象将直接在老年代分配,避免在新生代中产生大量内存复制。 规则3:长期存活对象进入老年代每个对象都有年龄计数器,每经历一次 Minor GC 且存活则年龄加1。 当年龄超过阈值(-XX:MaxTenuringThreshold,默认15)时,对象晋升到老年代。 规则4:动态年龄判定如果某岁年龄及以上对象总大小, 超过 Survivor 区容量一半, 则这些对象直接晋升老年代,无需达到最大年龄阈值。 也就是说此时 S0 或者 S1 区即将容纳不了 某岁年龄及以上 的存活新生代对象,则这些对象直接晋升老年代,无需达到最大年龄阈值。 规则5:空间分配担保进行 Minor GC 前,JVM 会按以下逻辑判断是否可以安全执行: 1、检查老年代最大可用连续空间是否大于新生代所有对象总大小: - 若是:Minor GC 安全,直接执行;
- 若否:进入空间分配担保判断。
2、检查是否启用空间分配担保(JDK 6 + 默认启用): - 若未启用(仅旧版本可能):直接执行 Full GC,再进行 Minor GC;
- 若启用:检查老年代最大可用连续空间是否大于历次晋升到老年代的对象平均大小:
3、检查老年代最大可用连续空间 是否 大于历次晋升到老年代的对象平均大小: - 若是:尝试执行 Minor GC(有风险,若本次晋升对象超过老年代剩余空间,会触发 “promotion failed”,进而执行 Full GC);
- 若否:先执行 Full GC,再进行 Minor GC。
流程示意图 如下: 该流程的核心是通过 “预先判断老年代能否容纳可能晋升的对象”,平衡 GC 效率与内存安全性。 优先尝试轻量的 Minor GC,必要时才触发代价较高的 Full GC。 结合以上对比,空间分配担保在现代JVM(以HotSpot为例,JDK 6 Update 24之后)中的决策流程可以简化为以下两步: 1、安全检查:Minor GC前,JVM首先检查老年代最大可用连续空间,是否大于新生代所有对象的总大小。 - 如果大于:这次Minor GC是安全的,直接执行。
- 如果小于:进入下一步风险评估。
2、风险评估:检查老年代最大可用连续空间,是否大于历次晋升到老年代对象的平均大小。 - 如果大于:则“冒险”尝试进行一次Minor GC。这里的“冒险”是指赌本次GC后存活的对象不会突然远高于历史平均水平。
- 如果小于:说明冒险失败的风险很高,则改为进行一次Full GC,以便在老年代腾出更多空间。
空间分配担保是发生在 Minor GC 之前的一种安全检查机制。它的核心目的是:确保在本次 Minor GC 后,新生代的所有存活对象能够成功晋升到老年代,从而避免晋升失败(Promotion Failure)进而导致更耗时的 Full GC。 如果没有这个机制,JVM 可能会在 Minor GC 进行到一半时才发现老年代空间不足,此时只能被迫触发 Full GC,导致不必要的性能损耗。 4、常见垃圾回收器垃圾回收器主要以下几种: - 串行垃圾回收器(Serial Garbage Collector):gc单线程内存回收、会暂停所有用户线程
- 并行垃圾回收器(Parallel Garbage Collector):收集是指多个GC线程并行工作,但此时用户线程是暂停的
- 并发标记扫描垃圾回收器(CMS Garbage Collector):GC线程和用户线程并发并发执行
- G1垃圾回收器(G1 Garbage Collector):通过分区(Region) 和可预测的停顿模型,在吞吐量与延迟之间取得平衡的垃圾收集器
- ZGC:基于着色指针和读屏障技术,实现全阶段并发,追求亚毫秒级极致低停顿的垃圾收集器
上图是HotSpot里的收集器,中间的横线表示分代,有连线表示可以组合使用。 常见垃圾回收器详细内容参考如下: - 美团面试:CMS 原理什么?漏标+多标+浮动垃圾 如何解决?90%的程序员都答错了!
- 美团面试:G1 垃圾回收 底层原理是什么?说说你的调优过程?
- 京东面试: 垃圾回收器 CMS、G1 区别是什么?
- 阿里面试:如何选 GC?ZGC 底层原理是什么?染色指针、转发表 是什么 ?90%的程序员都答错了!
- 大厂(转转、携程、京东)都用分代ZGC,卡顿降低20倍,吞吐量提升4倍。分代ZGC 这么牛?底层原理是什么?
5、GC调优目标GC的日志分析,也是重点关注这三点,GC停顿、吞吐量、GC前后的内存情况。 GC 调优通常围绕以下三个核心目标展开,它们之间存在著名的 “不可能三角” 关系,即很难同时达到极致,需要根据应用类型进行权衡和取舍。 1)低延迟 (Low Latency): 缩短垃圾收集引起的停顿(STW)时间,让应用程序的响应更及时。 比如,用户订单查询响应时间,对响应速度要求很高的系统,较大的停顿时间是不可接受的。调优的重点是在短的时间内快速响应。 2)高吞吐量 (High Throughput) 最大化应用程序的生命周期内,业务线程的执行时间占比。简单说,就是让系统在单位时间内能处理更多的业务任务。计算公式为 运行用户代码时间 / (运行用户代码时间 + 运行GC时间)。例如,95% 的吞吐量表示 GC 时间占比为 5%。 GC 开销:GC 消耗的 CPU 时间。 例如每小时批处理系统能完成的任务数量,在吞吐量方面优化的系统,较长的 GC 停顿时间也是可以接受的,因为高吞吐量应用更关心的是如何尽可能快地完成整个任务,不考虑快速响应用户请求。 3)小的内存占用 (Small Footprint) 在满足需求的前提下,尽量减少堆内存的使用。 | 优先级 场景 首要目标 推荐收集器 关键参数 | | 高 | Web服务、API、微服务 | 低延迟 | G1 (平衡) 或 ZGC (极致) | -XX:MaxGCPauseMillis=200, -Xmx | | 高 | 大数据、批处理 | 高吞吐量 | Parallel GC | -XX:GCTimeRatio=99 | | 中 | 管理后台、客户端应用 | 小内存 | Serial GC | 减小 -Xmx |
所以GC的日志分析,也是重点关注这三点,GC停顿、吞吐量、GC前后的内存情况 三、GC 日志基础下面将详细介绍如何生成 GC 日志。 1、示例程序下面是一个专门设计用于生成 GC 日志的演示程序: [code] package demo.jvm0204; import java.util.Random; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.LongAdder; /** * GC日志生成与分析演示类 * 通过生成不同大小的对象来模拟内存分配和回收 */ public class GCLogAnalysis { // 随机数生成器,用于生成随机大小和类型的对象 private static Random random = new Random(); public static void main(String[] args) { // 记录程序开始时间 long startMillis = System.currentTimeMillis(); // 设置程序运行时长(1秒),可根据需要调整 long timeoutMillis = TimeUnit.SECONDS.toMillis(1); // 计算程序结束时间 long endMillis = startMillis + timeoutMillis; // 使用LongAdder计数,保证多线程环境下的计数准确性 LongAdder counter = new LongAdder(); System.out.println("正在执行..."); // 创建缓存数组,模拟对象晋升到老年代 int cacheSize = 2000; Object[] cachedGarbage = new Object[cacheSize]; // 主循环:在指定时间范围内持续生成对象 while (System.currentTimeMillis() < endMillis) { // 生成垃圾对象,最大大小为100KB Object garbage = generateGarbage(100 * 1024); counter.increment(); // 增加对象计数 // 随机决定是否将对象放入缓存 int randomIndex = random.nextInt(2 * cacheSize); if (randomIndex < cacheSize) { cachedGarbage[randomIndex] = garbage; // 缓存对象,延长其生命周期 } } System.out.println("执行结束!共生成对象次数:" + counter.longValue()); } /** * 生成指定最大大小的垃圾对象 * @param max 对象最大大小 * @return 生成的随机对象 */ private static Object generateGarbage(int max) { int randomSize = random.nextInt(max); // 随机对象大小 int type = randomSize % 4; // 随机对象类型 Object result = null; // 根据类型创建不同种类的对象 switch (type) { case 0: result = new int[randomSize]; // 整型数组 break; case 1: result = new byte[randomSize]; // 字节数组 break; case 2: result = new double[randomSize]; // 双精度数组 break; default: // 字符串对象,通常占用更多内存 StringBuilder builder = new StringBuilder(); String randomString = "randomString-Anything"; while (builder.length() < randomSize) { builder.append(randomString); builder.append(max); builder.append(randomSize); } result = builder.toString(); break; } return result; } } [/code] 该程序的工作流程如下: 这个图表展示了程序的主要控制逻辑,包括初始化、循环生成对象以及缓存管理。 generateGarbage 方法这个图表详细展示 generateGarbage 生成垃圾对象的具体逻辑,包括类型判断和不同对象的创建过程。 2、启用GC日志JVM参数要获取详细的GC信息,需要在JVM启动时添加相应参数: [code] # 基本GC日志输出 java -XX:+PrintGCDetails demo.jvm0204.GCLogAnalysis # 输出GC日志到文件并添加时间戳 java -Xloggc:gc.demo.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps demo.jvm0204.GCLogAnalysis # 添加日期时间戳 java -Xloggc:gc.demo.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps demo.jvm0204.GCLogAnalysis # 指定堆内存大小 java -Xms512m -Xmx512m -Xloggc:gc.demo.log -XX:+PrintGCDetails demo.jvm0204.GCLogAnalysis # 指定具体G1收集器 java -XX:+UseG1GC -Xloggc:gc-%p-%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps demo.jvm0204.GCLogAnalysis [/code] 1)-XX:+UseG1GC:指定使用 G1 (Garbage-First) 垃圾收集器。 2)-Xloggc:gc-%p-%t.log:将 GC 日志输出到指定的文件,并使用包含进程ID和时间戳的动态文件名。 %p:是一个动态占位符,会被替换为当前 JVM 进程的 PID (Process ID)。%t:也是一个动态占位符,会被替换为 JVM 启动时的时间戳(格式通常是 YYYYMMDDHHMMSS)
3)-XX:+PrintGCDetails:在 GC 日志中输出详细的信息。 4)-XX:+PrintGCDateStamps:在每一条 GC 日志前添加一个可读的日期时间戳。 5)-Xms512m:设置 JVM 初始堆内存为 512 MB。 6)-Xmx512m:设置 JVM 最大堆内存为 512 MB。 7)其他参数:JVM 里还有一些 GC 日志相关的参数,例如: -XX:+PrintGCApplicationStoppedTime 可以输出每次 GC 的持续时间和程序暂停时间;-XX:+PrintReferenceGC 输出 GC 清理了多少引用类型。- ......
这里如果使用 GC 组合 不对的,就会 报fatal exception。 比如, CMS要配合年轻代ParNewGC:-XX:+UseConcMarkSweepGC -XX:+UseParNewGC 如配置-XX:+UseConcMarkSweepGC -XX:+UseParallelGC,让CMS配置ParallelGC,报fatal exception,大家可以试一下 3、GC日志基本解读3.1 GC日志基本结构一个GC日志大概分为三部分 - 第一部分:JVM 环境信息 (第1-3行)
- 第二部分:应用程序运行与GC事件 (第4行 - 第46行)
- 第三部分:Heap 堆内存使用情况(第47行之后)
第一部分:JVM 环境信息 (第1-3行)[code] Java HotSpot(TM) 64-Bit Server VM (25.162-b12) # JVM 版本信息 Memory: 4k page, physical 16777216k(1551624k free) # 系统内存:16GB物理内存,1.5GB空闲 CommandLine flags: # 启动参数配置 -XX:InitialHeapSize=536870912 # 初始堆大小:512MB -XX:MaxHeapSize=536870912 # 最大堆大小:512MB -XX:+PrintGC # 打印GC基本信息 -XX:+PrintGCDateStamps # 打印GC日期时间戳 -XX:+PrintGCDetails # 打印GC详细信息 -XX:+PrintGCTimeStamps # 打印GC相对时间戳 -XX:+UseCompressedClassPointers # 使用压缩类指针 -XX:+UseCompressedOops # 使用压缩普通对象指针 -XX:+UseParallelGC # 使用Parallel垃圾收集器 [/code] 第二部分:GC事件记录 (第4行 - 第46行)[code] # 第一次GC:Minor GC(年轻代GC) 2019-12-18T00:37:47.463-0800: 0.690: # 时间戳:绝对时间 + JVM启动后0.69秒 [GC (Allocation Failure) # GC原因:分配失败(Eden区空间不足) [PSYoungGen: 104179K->14341K(116736K)] # 年轻代:回收前104MB -> 回收后14MB (总容量114MB) 383933K->341556K(466432K), 0.0229343 secs] # 整个堆:383MB -> 341MB (总容量455MB),耗时0.023秒 [Times: user=0.04 sys=0.08, real=0.02 secs] # 耗时统计:用户态0.04s + 内核态0.08s = 实际0.02s # 第二次GC:Full GC(全堆GC) 2019-12-18T00:37:47.486-0800: 0.713: # 时间戳:0.713秒 [Full GC (Ergonomics) # GC原因:JVM自适应机制触发 [PSYoungGen: 14341K->0K(116736K)] # 年轻代:14MB -> 0MB [ParOldGen: 327214K->242340K(349696K)] # 老年代:327MB -> 242MB (总容量341MB) 341556K->242340K(466432K), # 整个堆:341MB -> 242MB [Metaspace: 3322K->3322K(1056768K)], # 元空间:无变化 0.0656553 secs] # 耗时0.066秒 [Times: user=0.30 sys=0.02, real=0.07 secs] # 耗时统计:用户态0.3s + 内核态0.02s = 实际0.07s [/code] 第三部分:堆内存使用详情(第47行之后)[code] Heap # 堆内存分区详情 PSYoungGen total 872960K, used 32300K [0x......) # Parallel Scavenge年轻代:总852MB,已用31.5MB eden space 792576K, 4% used [0x......) # Eden区:774MB,使用率4% from space 80384K, 0% used [0x......) # Survivor From区:78.5MB,使用率0% to space 138240K, 0% used [0x......) # Survivor To区:135MB,使用率0% ParOldGen total 481280K, used 278814K [0x....) # 老年代:总470MB,已用272MB(使用率57%) object space 481280K, 57% used [0x....) # 对象空间使用情况 Metaspace used 3449K, capacity 4494K, committed 4864K, reserved 1056768K # 元空间:使用3.4MB,容量4.4MB,提交4.7MB,保留1GB class space used 366K, capacity 386K, committed 512K, reserved 1048576K # 类空间:使用0.36MB,容量0.38MB,提交0.5MB,保留1GB [/code] 分别看下日志的每一部分内容 3.2 第一部分: JVM环境信息第一部分:JVM 环境信息 (第1-3行) [code] Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ...... # JVM版本:HotSpot 64位服务端虚拟机(build 25.162-b12) Memory: 4k page, physical 16777216k(1551624k free) # 系统内存:4KB内存页,物理内存16GB(当前空闲1.5GB) CommandLine flags: # JVM启动参数配置: -XX:InitialHeapSize=536870912 # 初始堆大小:512MB -XX:MaxHeapSize=536870912 # 最大堆大小:512MB(固定堆) -XX:+PrintGC # 启用基础GC日志打印 -XX:+PrintGCDateStamps # 在日志中添加日期时间戳 -XX:+PrintGCDetails # 打印详细GC信息 -XX:+PrintGCTimeStamps # 添加JVM启动后的相对时间戳 -XX:+UseCompressedClassPointers # 启用类指针压缩(节省内存) -XX:+UseCompressedOops # 启用普通对象指针压缩(节省内存) -XX:+UseParallelGC # 使用Parallel垃圾收集器(吞吐量优先) [/code] 第一行:JDK版本 第二行:物理内存约 16GB,剩余大约 1.5GB; 第三行:关键JVM参数: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912:堆内存初始值和最大值都设置为 512MB
-XX:+UseParallelGC:使用了 Parallel Scavenge(并行)垃圾收集器。
-XX:-UseLargePagesIndividualAllocation:禁用了大内存页的按需分配(对于 Parallel GC,此参数通常无关紧要)。
其他参数(UseCompressedOops, PrintGCDetails等)是常规设置。 JVM 在一个内存充足的操作系统上,分配了 512MB 的固定堆,并使用 Parallel 收集器启动。 3.2 第二部分:GC事件日志一段典型的GC日志如下所示: [code] 2019-12-15T15:09:59.235-0800: 0.296: # 时间戳:绝对时间2019-12-15T15:09:59.235-0800,JVM启动后0.296秒 [GC (Allocation Failure) # GC类型:Minor GC,触发原因:内存分配失败 [PSYoungGen: 63844K->10323K(76288K)] # 年轻代内存变化:GC前63844K → GC后10323K(总容量76288K) 63844K->20481K(251392K), 0.0087896 secs] # 堆变化:GC前63844K → GC后20481K(总容量251392K),耗时0.0088秒 [Times: user=0.02 sys=0.02, real=0.01 secs] # 时间统计:用户态CPU时间0.02秒,内核态0.02秒,实际暂停时间0.01秒 [/code] 各部分的含义: - 时间信息:
2019-12-15T15:09:59.235-0800:GC发生的具体时间(带时区)0.296:JVM启动后到GC发生的时间(秒)- GC类型:
GC:表示Minor GC/Young GCAllocation Failure:触发原因(内存分配失败)- 内存变化:
PSYoungGen: 63844K->10323K(76288K):PSYoungGen:垃圾收集器的名称,年轻代回收前->回收后(总容量)63844K->20481K(251392K):整个堆回收前->回收后(总容量)- 耗时信息:
0.0087896 secs:GC持续实际时间user=0.02 sys=0.02, real=0.01:CPU用户时间/系统时间/实际时间
[GC (Allocation Failure) :GC触发原因,下面总结下常见的GC触发原因,日志如下:
| 触发原因 (Cause) 常见于 含义与影响 | | Allocation Failure | 所有收集器的 YGC | 新生代空间不足,触发 Minor GC | | Ergonomics | Parallel GC | JVM 自适应机制触发的 Full GC | | Promotion Failure | Parallel Old | 老年代空间不足,无法接纳晋升的对象,触发 Full GC | | Metadata GC Threshold | 所有收集器 | Metaspace 空间不足 | | System.gc() | 所有收集器 | 代码显式调用 | | to-space exhausted | 所有收集器 | Survivor 区空间不足 | | Evacuation Pause (mixed) | G1 | G1 混合回收(Young+Old) | | Humongous Allocation | G1 | 分配大对象 | | Concurrent Mode Failure | G1, CMS | 并发收集跟不上分配速度,退化为 Full GC |
3.3 第三部分:Heap 堆内存使用情况[code] Heap # 堆内存分区详情 PSYoungGen total 872960K, used 32300K [0x......) # Parallel Scavenge年轻代:总852MB,已用31.5MB eden space 792576K, 4% used [0x......) # Eden区:774MB,使用率4% from space 80384K, 0% used [0x......) # Survivor From区:78.5MB,使用率0% to space 138240K, 0% used [0x......) # Survivor To区:135MB,使用率0% ParOldGen total 481280K, used 278814K [0x....) # 老年代:总470MB,已用272MB(使用率57%) object space 481280K, 57% used [0x....) # 对象空间使用情况 Metaspace used 3449K, capacity 4494K, committed 4864K, reserved 1056768K # 元空间:使用3.4MB,容量4.4MB,提交4.7MB,保留1GB class space used 366K, capacity 386K, committed 512K, reserved 1048576K # 类空间:使用0.36MB,容量0.38MB,提交0.5MB,保留1GB [/code] 分别看下日志的每一部分内容 首先是 PSYoungGen,年轻代总计 872960K,使用量 32300K,后面的方括号中是内存地址信息。 [code] PSYoungGen total 872960K, used 32300K [0x......) eden space 792576K, 4% used [0x......) from space 80384K, 0% used [0x......) to space 138240K, 0% used [0x......) [/code] - 其中 eden space 占用了 792576K,其中 4% used
- 其中 from space 占用了 80384K,其中 0% used
- 其中 to space 占用了 138240K,其中 0% used
其次 是 ParOldGen,老年代总计 total 481280K,使用量 278814K。 [code] ParOldGen total 481280K, used 278814K [0x......) object space 481280K, 57% used [0x......) [/code] 其中老年代 的 对象空间 object space 占用了 481280K,其中 57% used 最后是 Metaspace 元数据区总计使用了 3449K,容量是 4494K,JVM 保证可用的大小是 4864K,保留空间 1GB 左右。 [code] Metaspace used 3449K, capacity 4494K, committed 4864K, reserved 1056768K class space used 366K, capacity 386K, committed 512K, reserved 1048576K [/code] 其中类空间: class space 使用了 366K,capacity 386K。 也就是 使用0.36MB,容量0.38MB,提交0.5MB,保留1GB 四、Serial GC 日志解读Serial GC 是 最古老、最简单的垃圾收集器。 Serial GC 的核心特点是单线程 GC,在进行 GC 时会暂停所有应用线程(Stop-The-World)。 Serial GC 现在很少在生产环境使用,但理解 Serial GC 的日志对于掌握 JVM 内存管理基本原理至关重要。 Serial GC 的核心特点 - 单线程工作:所有垃圾回收操作由单个线程完成
- 分代收集:采用年轻代(Young Generation)和老年代(Old Generation)的分代模型
- 算法组合: 年轻代:使用复制算法(Copying) 老年代:使用标记-整理算法(Mark-Compact)
- 适用场景:客户端应用、小型微服务或硬件资源极度受限的环境
1、启用 Serial GC[code] # 启用Serial垃圾收集器 java -XX:+UseSerialGC \ # 设置堆内存初始值和最大值均为512MB(固定堆大小避免动态调整开销) -Xms512m -Xmx512m \ # 指定GC日志输出文件 -Xloggc:gc.demo.log \ # 在GC日志中输出详细信息 -XX:+PrintGCDetails \ # 在GC日志中添加时间戳 -XX:+PrintGCDateStamps \ # 运行演示程序 demo.jvm0204.GCLogAnalysis [/code] 启用串行垃圾收集器,程序执行后输出的 GC 日志类似这样: [code] Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ...... Memory: 4k page,physical 16777216k(1551624k free) CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseSerialGC 2019-12-15T15:18:36.592-0800: 0.420: [GC (Allocation Failure) 2019-12-15T15:18:36.592-0800: 0.420: [DefNew: 139776K->17472K(157248K),0.0364555 secs] 139776K->47032K(506816K), 0.0365665 secs] [Times: user=0.02 sys=0.01,real=0.03 secs] ...... 2019-12-15T15:18:37.081-0800: 0.908: [GC (Allocation Failure) 2019-12-15T15:18:37.081-0800: 0.908: [DefNew: 156152K->156152K(157248K),0.0000331 secs] 2019-12-15T15:18:37.081-0800: 0.908: [Tenured: 299394K->225431K(349568K),0.0539242 secs] 455546K->225431K(506816K), [Metaspace: 3431K->3431K(1056768K)], 0.0540948 secs] [Times: user=0.05 sys=0.00,real=0.05 secs] ...... Heap def new generation total 157248K, used 24352K [0x...) eden space 139776K, 17% used [0x...) from space 17472K, 0% used [0x...) to space 17472K, 0% used [0x...) tenured generation total 349568K, used 349557K [0x...) the space 349568K, 99% used [0x...) Metaspace used 3811K, capacity 4604K, committed 4864K, reserved 1056768K class space used 420K, capacity 428K, committed 512K, reserved 1048576K [/code] 为了方便大家阅读,已手工折行,去掉部分重复日志 2、Minor GC(年轻代回收)日志分析[code] 2019-12-15T15:18:36.592-0800: 0.420: # 时间戳:绝对时间 + JVM启动后时间 [GC (Allocation Failure) # GC类型:Minor GC,原因:内存分配失败 2019-12-15T15:18:36.592-0800: 0.420: # 时间戳:GC开始时间 [DefNew: 139776K->17472K(157248K), 0.0364555 secs] # 年轻代:GC前139776K->GC后17472K(总157248K),耗时0.036秒 139776K->47032K(506816K), # 堆内存:GC前139776K->GC后47032K(总506816K) 0.0365665 secs] # 总耗时:0.0365665秒 [Times: user=0.02 sys=0.01, real=0.03 secs] # 时间统计:用户态0.02s,内核态0.01s,实际暂停0.03s [/code] 从中可以解读出这些信息: 2.1. 时间信息:2019-12-15T15:18:36.592-0800:GC发生的绝对时间(带时区,东8区)
0.420:JVM启动后到GC发生的时间(秒)
2.2. GC类型与原因:GC:表示Minor GC(年轻代垃圾回收)
Allocation Failure:触发原因,本次 GC 事件,是由于对象分配失败,年轻代中没有空间来存放新生成的对象引起的
2.3. 年轻代内存变化(核心信息):DefNew:Serial GC中年轻代的名称(Default New Generation)
139776K->17472K(157248K):回收前→回收后(总容量) ,回收效果:从136MB回收到17MB,清除了119MB垃圾
进一步分析可知:GC 之后年轻代使用率为 17472K / 157248K = 11% 2.4. 整个堆内存变化:139776K->47032K(506816K):堆回收前→回收后(总容量)
计算晋升对象:年轻代回收119MB,但堆只减少91MB,说明有28MB对象晋升到老年代 进一步分析可知:GC 之后堆内存使用量为 47032K / 506816K 9% 2.5. 老年代内存变化:在此次垃圾收集之前,堆内存总的使用量为 139776K,其中年轻代使用了 139776K。可以算出,GC 之前老年代空间的使用量为 0。(实际上这是 GC 日志中的第一条记录) 这些数字中蕴含了更重要的信息: GC 前后对比,年轻代的使用量为 139776K->17472K,减少了 122304K。 但堆内存的总使用量 139776K->47032K,只下降了 92744K。 可以算出,从年轻代提升到老年代的对象占用了“122304K-92744K=29560K”的内存空间。当然,另一组数字也能推算出 GC 之后老年代的使用量:47032K-17472K=29560K。 2.6. 耗时信息0.0365665 secs:GC总耗时
[Times: user=0.02 sys=0.01, real=0.03 secs]:
user 部分表示所有 GC 线程消耗的 CPU 时间; sys 部分表示系统调用和系统等待事件消耗的时间。 real 则表示应用程序暂停的时间。因为串行垃圾收集器(Serial Garbage Collector)只使用单个线程,所以这里 real=user+system,0.03 秒也就是 30 毫秒。 重点关注的主要是两个数据:GC 暂停时间,以及 GC 之后的内存使用量 、使用率。 此次 GC 事件的示意图如下所示: 3、Full GC(完全回收)日志分析当老年代空间不足时,会触发Full GC: [code] 2019-12-15T15:18:37.081-0800: 0.908: # 时间戳:绝对时间 + JVM启动后时间 [GC (Allocation Failure) # GC类型:Full GC,原因:内存分配失败 2019-12-15T15:18:37.081-0800: 0.908: [DefNew: 156152K->156152K(157248K), 0.0000331 secs] # 年轻代:使用量无变化156152K->156152K(总157248K),耗时0.0000331秒 2019-12-15T15:18:37.081-0800: 0.908: [Tenured: 299394K->225431K(349568K), 0.0539242 secs] # 老年代:GC前299394K->GC后225431K(总349568K),耗时0.0539242秒 455546K->225431K(506816K), # 堆内存:GC前455546K->GC后225431K(总506816K) [Metaspace: 3431K->3431K(1056768K)], # 元空间:使用量无变化3431K->3431K(总1056768K) 0.0540948 secs] # 总耗时:0.0540948秒 [Times: user=0.05 sys=0.00, real=0.05 secs] # 时间统计:用户态0.05s,内核态0.00s,实际暂停0.05s [/code] 相似的日志不再做分析,关键差异点: 3.1、 年轻代回收无效:DefNew: 156152K->156152K:年轻代回收前后无变化, 表明年轻代已满且无法有效回收
0.0000331 secs:此次垃圾收集消耗了 0.0000331 秒,基本上确认本次 GC 事件没怎么处理年轻代
3.2老年代回收:Tenured:Serial GC中老年代的名称
299394K->225431K:老年代回收了74MB垃圾 使用了标记-整理算法,避免内存碎片
0.0539242 secs 是清理老年代所花的时间
3.3、元空间信息:[Metaspace: 3431K->3431K(1056768K)]:此次 GC 过程中 Metaspace 也没有什么变化。
3.4、 耗时信息:[Times: user=0.05 sys=0.00,real=0.05 secs]:GC 事件的持续时间,分为 user、sys、real 三个部分。因为串行垃圾收集器只使用单个线程,因此“real=user+system”。
50 毫秒的暂停时间,比起前面年轻代的 GC 来说增加了一倍左右。这个时间与 GC 后存活对象的总数量关系很大。 和年轻代 GC 相比,比较明显的差别是此次 GC 事件清理了老年代和 Metaspace。 此次 GC 事件的内存变化情况,可以表示为下面的示意图: 五、Parallel GC 日志解读Parallel GC(并行垃圾收集器)是 Java 中一款以吞吐量优先的垃圾收集器,其核心设计目标是充分利用多核处理器的优势,通过并行执行垃圾回收任务来最大化应用程序的吞吐量。 Parallel GC 采用"吞吐量优先"的设计理念,主要特点包括: - 并行处理:使用多个 GC 线程同时执行垃圾回收工作
- 分代收集:年轻代采用标记-复制算法,老年代采用标记-整理算法
- STW 机制:所有垃圾回收阶段都会触发 Stop-The-World 暂停
- 适用场景:适合后台处理、批处理任务等对吞吐量要求高但对暂停时间不敏感的应用
1、启用Parallel GC启用 Parallel GC 有多种等价配置方式:下面的三组命令行参数是等价的,都可用来指定并行垃圾收集器: [code] -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+UseParallelGC -XX:+UseParallelOldGC [/code] 完整启动参数示例: [code] # 使用ParallelGC,设置堆大小为512MB,输出详细GC日志到文件 java -XX:+UseParallelGC \ -Xms512m -Xmx512m \ # 设置堆内存初始值和最大值均为512MB -Xloggc:gc.demo.log \ # 指定GC日志输出文件 -XX:+PrintGCDetails \ # 打印GC详细信息 -XX:+PrintGCDateStamps \ # 在GC日志中添加时间戳 demo.jvm0204.GCLogAnalysis # 运行示例程序 [/code] 启用并行垃圾收集器,程序执行后输出的 GC 日志类似这样(为了方便大家阅读,已手工折行,去掉部分重复日志): [code] CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC ...... 2019-12-18T00:37:47.463-0800: 0.690: [GC (Allocation Failure) [PSYoungGen: 104179K->14341K(116736K)] 383933K->341556K(466432K),0.0229343 secs] [Times: user=0.04 sys=0.08,real=0.02 secs] 2019-12-18T00:37:47.486-0800: 0.713: [Full GC (Ergonomics) [PSYoungGen: 14341K->0K(116736K)] [ParOldGen: 327214K->242340K(349696K)] 341556K->242340K(466432K), [Metaspace: 3322K->3322K(1056768K)], 0.0656553 secs] [Times: user=0.30 sys=0.02,real=0.07 secs] ...... [/code] 2、Minor GC 日志分析[code] 2019-12-18T00:37:47.463-0800: 0.690: # 时间戳:绝对时间 + JVM启动后时间 [GC (Allocation Failure) # GC类型:Minor GC,原因:内存分配失败 [PSYoungGen: 104179K->14341K(116736K)] # 年轻代:GC前104179K->GC后14341K(总116736K) 383933K->341556K(466432K), 0.0229343 secs] # 堆内存:GC前383933K->GC后341556K(总466432K),耗时0.0229343秒 [Times: user=0.04 sys=0.08, real=0.02 secs] # 时间统计:用户态0.04s,内核态0.08s,实际暂停0.02s [/code] Minor GC 日志解读 1、 时间戳与相对时间 2019-12-18T00:37:47.463-0800: 0.690:: GC 事件发生的绝对时间与 JVM 启动后的相对时间(秒) (2) GC 类型与原因 GC (Allocation Failure): 表明是一次 Minor GC,触发原因是内存分配失败 3、 年轻代内存变化 PSYoungGen: 104179K->14341K(116736K): PSYoungGen: Parallel Scavenge 年轻代收集器
104179K->14341K:GC 前年轻代使用量 → GC 后年轻代使用量 (116736K):年轻代总空间 计算:回收了 89838K,年轻代使用率降至 12.3%
4、 堆内存总体变化 383933K->341556K(466432K): GC 前堆使用量 → GC 后堆使用量 (466432K):堆总容量 计算:整体回收了 42377K,堆使用率降至 341556K/466432K=73% 5、 耗时统计:[Times: user=0.04 sys=0.08, real=0.02 secs]: user:GC 线程消耗的 CPU 时间总和
sys:系统调用和等待时间
real:应用实际暂停时间(关键指标) 注意:real ≠ user + sys,因为多线程并行工作,real 约等于 user+system/GC 线程数,测试机器是 8 个线程,如果使用串行 GC,可能得暂停 120 毫秒,但并行 GC 只暂停了 20 毫秒,实际上性能是大幅度提升了。
6、 内存变化分析: 通过日志数据可以进一步分析: - GC 前老年代使用量:383933K - 104179K = 279754K
- GC 后老年代使用量:341556K - 14341K = 327215K
- 晋升到老年代的对象:327215K - 279754K = 47461K
- 老年代总空间:466432K - 116736K = 349696K
- 老年代使用率:327215K/349696K ≈ 93.6%(已接近满负荷)
提示:当老年代使用率过高时,很可能紧接着就会发生 Full GC。 此次 GC 的内存变化示意图为: 3、Full GC 日志分析[code] 2019-12-18T00:37:47.486-0800: 0.713: # 时间戳:绝对时间 + JVM启动后时间 [Full GC (Ergonomics) # GC类型:Full GC,原因:JVM自适应机制触发 [PSYoungGen: 14341K->0K(116736K)] # 年轻代:GC前14341K->GC后0K(总116736K),完全清空 [ParOldGen: 327214K->242340K(349696K)] # 老年代:GC前327214K->GC后242340K(总349696K),回收约85M 341556K->242340K(466432K), # 堆内存:GC前341556K->GC后242340K(总466432K),回收约99M [Metaspace: 3322K->3322K(1056768K)], # 元空间:使用量无变化3322K->3322K(总1056768K) 0.0656553 secs] # 总耗时:0.0656553秒 [Times: user=0.30 sys=0.02, real=0.07 secs] # 时间统计:用户态0.30s,内核态0.02s,实际暂停0.07s [/code] 1、 GC 类型与原因 Full GC (Ergonomics): Full GC 表明本次 GC 清理年轻代和老年代,
Ergonomics 是触发 GC 的原因,表示 JVM 内部环境认为此时可以进行一次垃圾收集。
(2) 年轻代回收 PSYoungGen: 14341K->0K(116736K): 年轻代被完全清空,一般 Full GC 中年轻代的结果都是这样 3、 老年代回收 ParOldGen: 327214K->242340K(349696K): ParOldGen:Parallel Old 老年代收集器
老年代使用量从 327214K 降至 242340K 回收了 84874K,使用率从 327214K/349696K=93% 降至 242340K/349696K=69% 4、 堆内存总体变化 341556K->242340K(466432K): 堆使用量下降 99216K,GC 之前堆内存使用率为 341556K/466432K=73%,GC 之后堆内存的使用率为:242340K/466432K=52%。 5、 元空间情况 Metaspace: 3322K->3322K(1056768K): 元空间使用量未变化 6、 耗时统计 [Times: user=0.30 sys=0.02,real=0.07 secs]: GC 事件的持续时间,含义参见前面。 此次 Full GC 实际暂停时间为 0.07 秒 Full GC 时我们更关注老年代的使用量有没有下降,以及下降了多少。如果 FullGC 之后内存不怎么下降,使用率还很高,那就说明系统有问题了。 此次 GC 的内存变化示意图为: 六、CMS 的 GC 日志解读请参见原文 七、G1 的 GC 日志解读请参见原文 八、ZGC的GC日志解读请参见原文 九、GC 可视化日志解读与分析请参见原文 JVM调优圣经系列文章京东面试:什么是gc尖刺? 怎么 解决由于 gc 导致的 尖刺? 凌晨零点,一个 TODO,差点把我们整个部门抬走 希音面试:频繁 fullgc,如何排查? 听说你是高手?说说你的 JVM调优方法论 吧?(美团面试,问的贼细) 《cms圣经:cms 底层原理和调优实战》 《G1圣经:G1 底层原理和调优实战》 《ZGC 圣经:ZGC 底层原理和调优实战》 《分代 ZGC 圣经:分代ZGC 底层原理和 大厂实战案例学习》 来源:程序园用户自行投稿发布,如果侵权,请联系站长删除 免责声明:如果侵犯了您的权益,请联系站长,我们会及时删除侵权内容,谢谢合作! |