多彩编程 多彩编程MZPH · CODE BLOG
ARTICLE DETAIL

文章详情

深耕前端与后端开发技术的一线实战笔记与踩坑复盘。

jstat实战:从JVM内存模型到GC全过程解析

jstat实战:从JVM内存模型到GC全过程解析 线上排查Java服务内存问题时我最先跑的命令几乎永远是jps加jstat。有一次同事盯着监控面板说老年代快满了但又说不清对象究竟是怎么分配进去的我让他jstat -gc连续采了十几秒问题立刻缩小到“大对象直接晋升老年代”上。这就是jstat的定位JDK自带、零侵入、一行命令就能让你看清JVM对象分配的过程和GC的全貌比任何图形化监控工具都来得直接。这篇文章我会从JVM内存模型讲起把jstat最常用的参数和每一列输出都拆开讲透再用一个可以复现的示例程序完整走一遍“对象分配→Eden打满→Minor GC→Survivor交换→晋升老年代”的观察过程。后端开发、性能调优、线上问题排查的同学都可以直接抄作业面试前拿它梳理一遍JVM内存分配逻辑也很有用。1. 先搞明白JVM内存模型再看jstat输出才不懵1.1 JVM内存模型与对象分配的主战场jstat输出的每一列都对应JVM内存模型里的一块区域所以看不懂内存模型看输出就只是看数字。JVM堆内存按代划分核心思路是“不同年龄的对象放在不同区域用不同的回收策略处理”主要分两大块年轻代和老年代。年轻代又分成Eden区和两块Survivor区S0和S1大部分对象刚创建时都分配在Eden区。对象分配的基本流程是新对象先进入Eden区Eden满了以后触发Minor GCMinor GC时依然存活的对象被复制到Survivor区并且每经历一次Minor GC年龄加一当对象年龄超过阈值或者Survivor区放不下时对象晋升到老年代。另外如果对象很大超过-XX:PretenureSizeThreshold设定的值会直接进入老年代这也是jstat里OU老年代使用量突然跳涨的常见原因。我用一个仓库分拣的类比帮助理解Eden是收货区所有货物先堆在这里Minor GC相当于分拣员定期把“还要留着的货”挪到暂存区Survivor暂存区翻了几轮还活着的货才搬到长期仓库老年代。jstat能看到的就是每个区的容量和使用量以及分拣GC发生了多少次、每次花了多久。1.2 为什么观察“分配过程”比只看“堆占用”更有价值很多人排查内存问题一上来就盯堆占用率但堆占用只是一个瞬时快照它回答不了“对象是怎么变成这样的”。一个应用堆内存水位并不高但Minor GC极其频繁说明对象分配速率极快、存活率极低典型的表现就是YGC次数疯狂增长而堆占用却保持平稳。另一种情况是堆占用缓慢爬升FGC偶发说明有对象晋升速度偏快可能是Survivor空间不足也可能是大对象在持续产生。jstat的核心价值在于能连续采样让你从时间序列里看出对象分配的趋势。比如10秒内Eden从10MB涨到30MB说明这10秒分配了大约20MB对象又比如每次Minor GC后老年代都增加一点说明存在晋升。这些信息都是单看堆占用拿不到的也是定位“分配过快还是回收不力”这类问题的关键依据。2. jstat到底能看什么常用参数与输出列逐行拆解2.1 jstat的使用方式与常用选项jstat的用法比较固定基本格式是jstat -option [-t] [-hlines] vmid [interval [count]]。其中vmid就是Java进程的PID一般先用jps -lv拿到interval是采样间隔毫秒数count是采样次数。比如jstat -gc 12345 1000 10表示对PID 12345的进程每隔1秒采一次一共采10次。jstat的选项很多但实际排查高频用的就那么几个我整理了一个对照表选项作用常见使用场景-class查看类加载统计检查类加载器是否泄漏-gc各分区的容量、使用量、GC次数与耗时最常用看整体堆情况-gcutil各分区使用率百分比 GC统计快速定位哪个区比例异常-gccapacity各分区容量及其边界确认线程栈之外的代容量配置-gcnew年轻代明细重点观察Eden和Survivor变化-gcold老年代明细重点观察老年代增长-gcmetacapacity元空间容量统计Metaspace溢出排查这里有个容易踩的坑如果系统里只装了JRE而不是完整JDK大概率找不到jstat。JRE只是Java运行环境JDK才包含编译器、jps、jstat这些诊断工具。这个细节也正好解释了JRE和JVM的关系JVM是运行Java字节码的核心引擎JRE在JVM之上补齐了运行所需的类库而JDK又在JRE之上添加了开发和诊断所需的工具链。2.2 输出列到底什么意思从S0到FGC一次说清拿最常用的-gc来做逐列拆解以下面这行输出为例S0C S1C S0U S1U EC EU OC OU MC MU YGC YGCT FGC FGCT GCT 512.0 512.0 128.0 0.0 20480.0 10240.0 40960.0 20480.0 8192.0 6000.0 12 0.180 2 0.320 0.500S0C和S1C是两块Survivor区的容量S0U和S1U是它们当前的使用量。EC和EU是Eden区的总容量与使用量OC和OU是老年代总容量与使用量。MC和MU代表Metaspace的容量与使用量。YGC是年轻代GC次数YGCT是年轻代GC累计耗时FGC是Full GC次数FGCT是Full GC累计耗时GCT是所有GC的总耗时。阅读顺序上有讲究。我先看YGC有没有在涨如果每次采样YGC都在递增说明年轻代回收非常频繁再看EU是不是总是在高位附近波动如果EU每次都能降下来说明对象能正常回收最关键的看OU如果OU持续上升且YGC后也不回落就要警惕晋升率过高或者大对象问题。S0U和S1U正常情况下总有一块是0因为Minor GC后存活对象只会复制到其中一块Survivor两块同时有大量数据反而不正常。2.3 对比-gc 和 -gcutil 的适用场景-gc输出的是各区域的绝对值单位是KB适合关注内存水位和计算分配速率-gcutil输出的则是使用率百分比比如Eden区使用率80%、老年代使用率65%适合快速判断“哪个区快满了”。两者底层数据源相同只是展示形式不同。我实际排查时通常是两个配合使用先用-gcutil扫一眼如果看到老年代使用率持续高于70%并且还在爬马上用-gc连续采样看绝对值变化计算每分钟老年代增长量。举个例子-gcutil看到老年代使用率从60%涨到72%只花了几分钟再切到-gc算一下OU增量基本就能判断是老年代增长过快而不是FGC之后的容量调整。3. 实操记录用jstat盯完一整个对象分配与GC周期3.1 准备一个会“分配对象”的测试程序理论说再多不如亲手跑一遍。我写一个简单的Java程序循环创建对象模拟业务中常见的“短生命周期对象大量产生”的场景。堆大小设小一点GC会快速发生jstat采样时效果更明显。import java.util.ArrayList; import java.util.List; public class JstatDemo { private static final int BATCH_SIZE 1024 * 1024; public static void main(String[] args) throws Exception { Listbyte[] keep new ArrayList(); for (int i 0; i 50; i) { // 模拟一批临时对象用完即可回收 byte[] tmp new byte[BATCH_SIZE]; tmp[0] (byte) i; // 每5轮保留一个对象模拟部分存活 if (i % 5 0) { keep.add(new byte[BATCH_SIZE]); } Thread.sleep(200); } System.out.println(done, keep size keep.size()); } }这个程序每200毫秒分配一个1MB的临时数组每5个保留一个1MB的数组用来模拟“大部分对象可回收、少部分对象存活”的典型模式。为了完整观察整个分配过程我把循环次数放大到200次左右否则短短几十秒就结束了来不及采样。运行前先编译javac JstatDemo.java3.2 关键启动参数把堆调小、把日志打开直接运行默认参数的话堆默认只占物理内存的1/4年轻代也很大GC要等很久才发生jstat短时间内看不出明显变化。为了让效果可见我把堆限制在64MB年轻代32MBSurvivorRatio设为8意思就是Eden和单个Survivor的容量比例是8:1。java -Xms64m -Xmx64m -Xmn32m -XX:SurvivorRatio8 -XX:UseParallelGC -Xlog:gc* -jar jstat-demo.jarJava 8及以前打开GC日志用-XX:PrintGCDetailsJava 9以后建议用-Xlog:gc*。这里强调两点一是-Xms和-Xmx必须相等避免堆自动扩容引入干扰二是GC日志和jstat数据要对照着看jstat告诉你发生了什么GC日志告诉你具体原因。如果你是通过IDE或者某些启动器比如常见的游戏启动器HMCL它也有JVM参数设置入口启动Java程序同样可以加上类似参数原理完全一致。3.3 采样过程实录先jps找PID再jstat盯每一秒启动程序后先开一个终端跑jps -lv找到进程号jps -lv输出里会列出PID和启动参数确认我们加在命令行里的-Xms64m -Xmx64m都生效了。这一步别省我曾经用ps -ef | grep java找到过PID结果那是IDE自身的进程数据完全对不上。拿到PID之后立刻执行jstat -gc 12345 1000 30每秒采样一次共30次刚好覆盖一个完整的Minor GC周期。注意把12345换成实际的进程ID。下面是早期采样的几行输出我整理成表格更好看采样点S0US1UECEUOCOUYGCt10.00.029.5MB15.2MB32.0MB3.1MB2t20.00.029.5MB22.6MB32.0MB3.1MB2t30.03.4MB29.5MB0.8MB32.0MB3.5MB3t40.03.4MB29.5MB8.9MB32.0MB3.5MB3从t1到t2Eden使用量从15.2MB涨到22.6MB说明这两秒内我们分配了大约7MB对象到t3的时候YGC从2变成3EU从22.6MB骤降到0.8MB说明Eden满了触发Minor GCEden里的对象被清空少量存活对象进了S1S1U从0涨到3.4MB同时OU从3.1MB微涨到3.5MB说明有个别对象这次GC后直接走进了老年代。这就是一次标准的“对象分配→Eden打满→Minor GC”过程。多采几轮之后你会非常直观地看到Eden的使用量像锯齿一样一涨一落这就是动态分配和回收的节奏。3.4 从数据反推对象分配速率既然jstat能连续给出EU的变化那对象分配速率就能算出来。最简单的办法两次采样间隔内Eden的使用量增量加上可能发生的Minor GC清空量除以间隔时间就是这期间的分配速率。实操中因为Minor GC会瞬间清零Eden我更习惯用这个近似公式分配速率 ≈本次EU - 上次EU 最近一次Minor GC前的EU峰值/ 采样间隔不过这样手算太累。工程上偷懒的办法是直接看YGC频次如果60秒内YGC增加了20次Eden容量是24MB那往多了估这60秒大约分配了20 × 24MB 480MB对象。这个数字是上限估算不够精确但用来判断“分配速率是否过高”已经足够。比如一个本该每秒只分配几MB的后端服务算出来每秒分配30MB那不用看别的代码里一定有大量的临时对象或者数组在循环里创建。4. 别只盯着jstat把这些指标串起来看才能定位问题4.1 判断GC压力的三个组合指标单看任何一项指标都容易误判我习惯把三个指标放一起看YGC频率、YGCT耗时增速、FGC次数。下面是我实际排查时常用的判断逻辑症状可能原因排查方向YGC次数高YGCT不高堆占用平稳短命对象分配速率过快查代码中的大循环、频繁new对象、字节数组拷贝YGC次数高YGCT也高老年代缓慢上升Survivor空间不足导致过早晋升检查SurvivorRatio、MaxTenuringThresholdFGC次数持续增加老年代使用率居高不下大对象、内存泄漏或堆过小配合jmap转储堆分析对象分布YGC不多但FGC一来耗时数秒老年代碎片化或GC线程数过少查看FGC耗时、考虑GC收集器选型每次排查的时候我会在脑子里过一遍这个矩阵。比如有次服务老年代持续上涨但YGC并不频繁一开始我怀疑泄漏后来用jstat一看FGC也很少就意识到可能是某些长生命周期对象在缓慢布局换成jmap看了下发现是一个缓存Map没有做容量控制一直在往里面塞数据。4.2 怎么用jstat量化晋升速率晋升速率也是一个能算出来的关键指标。方法不复杂取两个时间点的OU差值除以中间经历的时间就得到这段时间老年代的增长速率。如果中间发生过FGC要把FGC清理掉的那部分算进去否则会低估晋升速率。举个例子10分钟内OU从120MB涨到240MB期间没有FGC那晋升速率就是12MB/分钟。参考这个数字再想业务数据量如果这个服务每秒正常创建的对象只有几MB那12MB/分钟的晋升速率显然是异常的很可能有对象不该进老年代却被塞进去了。这时候再用-gcnew采样看Survivor变化如果S0U和S1U频繁清零基本可以断定Survivor空间设置偏小对象被提前晋升了。4.3 给新手的建议先定基准再调参数我看到很多人调JVM参数全凭感觉——YGC频繁就加大年轻代FGC频繁就加大堆。其实正确顺序是先用jstat观察5到10分钟建立基线数据记录常态下的YGC频率、晋升速率和FGC次数再决定动哪个参数。一次只动一个参数改完再采一轮数据对比用数据说话而不是拍脑袋。我自己在这个环节踩过不小的坑。有一阵子某个服务YGC频繁我以为是Eden太小把-Xmn从1GB调到2GB结果YGC确实少了老年代上涨却更快了。原因是Survivor空间没有跟着调晋升阈值被打破倒逼更多对象进入老年代。后来我把SurvivorRatio也从默认8改到6情况才好转。这个案例让我养成一个习惯改任何一个堆参数都要把年轻代、Survivor、晋升阈值一起审视而不是只盯单个数值。5. 常见问题与排查技巧实录5.1 问题速查表实际使用jstat的过程中下面这些问题几乎人人都遇到过我整理成一张速查表问题可能原因处理建议提示jstat: command not found只装了JRE没有JDK安装完整JDK并确认JAVA_HOME指向JDK目录jstat能跑但输出全为空或拒绝连接PID不存在或权限不够用jps -lv确认PID必要时加sudo采样间隔设得很短但数据不变化进程刚启动尚未触发GC拉长观察窗口适当间隔5秒采样输出里各容量全为0使用了不支持jstat的特定容器或虚拟化回到宿主机进程视角或改用容器内PID命名空间采样数据波动很大单次GC周期和采样周期不匹配加大采样间隔连续观察多个GC周期再下结论老年代使用率持续高位但FGC不启动GC触发阈值未到或对象可被部分回收看-gcutil里的O区百分比结合FGC历史判断5.2 我在线上踩过的一些坑第一个坑是只看瞬时值。有一回我看到OU采样结果很高差点判断老年代马上要打满结果下一秒Minor GC之后OU回落了一大截原来上一个采样点刚好是大量对象晋升后的瞬间。从那以后我采样至少看20个点以上用趋势判断而不是单个点。第二个坑是忘记留GC日志。jstat能告诉你“发生了什么”但“某一次GC的具体原因”是需要GC日志来佐证的。生产环境只要条件允许我都会建议保留GC日志文件并滚动归档出问题时jstat和GC日志配合回溯效率翻倍。所以即使本文主要讲jstat我也会强调一句jstat负责现场侦查GC日志负责事后复盘。第三个坑是没确认参数是否真的生效。有些配置在框架的启动脚本里被覆盖了你以为-Xmn512m生效实际运行的是默认值。用jstat -gccapacity或jcmd VM.flags验证一下确认各代容量与预期一致再开始分析能省掉很多无用功。第四个坑是只数GC次数不计算GC耗时。有次一个服务YGC次数并不高但YGCT持续在涨单次YGC耗时从几十毫秒飙到几百毫秒。这不是对象分配速率的问题而是GC线程竞争或者复制对象量过大的问题。所以除了数次数一定要同时关注耗时YGCT和FGCT的变化往往比次数更敏感。我自己这几年代码没少写线上问题也没少排查最大体会是jstat不是万能的它看不到具体是哪个类创建了大量对象也看不到引用关系。但它是排查对象分配问题的第一刀几秒钟采样、几分钟观察就能把问题的方向从“完全没头绪”缩小到“年轻代分配过快”或者“老年代晋升异常”。等你再用jmap或者专业的JFR/JMC工具去深挖时至少已经知道该往哪个方向看。把这个工具用熟了以后调堆、调GC参数心里会踏实很多。
返回列表