ARTICLE DETAIL

资讯详情

深耕郑州网站建设与运营推广的一线实战洞察。

JDK自带jstat命令:生产环境JVM性能监控与GC排查实战

JDK自带jstat命令:生产环境JVM性能监控与GC排查实战 Java应用上了生产之后迟早要面对“CPU飙高、接口变慢、GC频繁”的故障。我见过不少团队第一反应是拉jmap堆栈、刷jconsole监控面板唯独把JDK自带的命令行小工具jstat晾在一边。实际上jstat是JDK自带、无需额外安装的轻量级监控工具它能在不影响业务进程的前提下把堆内存使用率、新生代和老年代占用、GC次数、GC暂停耗时一次性输出在终端里。尤其是手头只有一台Linux服务器、一个SSH窗口、没有任何图形界面和监控平台时jstat往往是我敲下的第一句排查命令。有人觉得“监控JVM一定要上普罗米修斯、Grafana那套全家桶”其实未必。jstat小、快、准它不依赖外部组件也不需要在应用里埋点平时用来做快速体检、定位GC问题、判断是否需要调优完全够用。这篇内容我把jstat的参数、输出列、实战用法和踩坑点一次讲透力求你拿到手就能直接照着敲。1. 认识jstat它在一个JVM监控体系里站在哪个位置1.1 jstat到底在监控什么先说结论jstat是JDK自带的性能统计工具全称JVM Statistics Monitoring Tool一般位于$JAVA_HOME/bin目录下和jps、jmap、jstack属于同一族工具。它通过JVM内部的Attach机制读取进程的统计计数器performance counters不需要你在应用里开JMX端口也不需要额外装agent也就是说对业务代码完全无侵入。有个经典的误解jstat只能看GC。实际上它的监控范围比GC宽得多。按我平时使用的频率排序它至少能看四类数据类加载和类卸载的数量、耗时即时编译JIT编译了多少方法、失败次数、最近编译的方法堆内存中Eden、Survivor、老年代、元空间等区域的使用量和使用率GC次数、GC累计耗时以及最近GC触发的原因如果拿开车来类比jmap、jstack那些工具类似把引擎盖打开去检查零部件而jstat更像坐在驾驶座看仪表盘转速、油量、水温一目了然。它能帮你快速判断“车是不是快没油了”“发动机是不是过热了”但具体哪个零件坏了还需要再配合其他工具去定位。1.2 为什么即便有监控平台“裸敲”jstat也值得学我在不同公司待过有的团队监控体系建得很完善Grafana大盘上堆内存、GC、CPU曲线一应俱全。但真正出故障的时候我还是习惯先打开一个终端敲jstat。原因有三点。第一监控平台的采集粒度通常不够细。很多监控系统把JVM指标设置成15秒或30秒采集一次平时看趋势没问题但故障发生时GC可能一两秒内密集发生这种粒度根本看不出突变点。jstat可以做到几百毫秒采样一次连续输出几十条GC频率的变化顿时清晰可见。第二生产环境登录服务器后你未必有权限打开图形界面甚至监控平台的账号都可能要临时申请。而jstat只要你有JDK环境的操作系统账号即可使用几乎不需要额外授权。在“快速止血”的黄金五分钟里打开终端敲jstat比登录监控平台再层层点开面板更直接。第三一台物理机上可能跑着多个Java进程监控平台显示的是某个服务整体的指标没法简单区分具体是哪个PID引起的问题。jstat直接指定进程号采样问题归属非常明确。我并不是说jstat能取代监控平台它当然不能做历史趋势回溯、告警通知、多实例对比这些事情。但它是JVM排障链路里“最前一步”的最佳选择先靠jstat确认嫌疑区域再决定要不要上jmap、jstack、MAT这些重家伙。这一套由轻到重的思路才是排障的正确姿势。2. 基础用法找到进程、敲出第一条jstat命令2.1 先明确jstat的通用语法jstat的命令格式并不复杂套用下面这个模板就行jstat [generalOption | outputOptions vmid [interval[s|ms] [count]]]拆开来看generalOption一般是-options用来列出当前JDK支持的输出选项属于一次性查询。outputOptions这才是核心比如-gcutil、-gc、-class决定你要看哪一类统计数据。vmid虚拟机标识本地场景下通常直接写Java进程的PID。远程场景写成protocol:host:port但日常排查用得很少。interval采样间隔单位默认毫秒可以写成1000也可以写成1s。count采样次数不填就无限输出直到你按CtrlC。所以下面这条命令的意思就很好理解了jstat -gcutil 12345 1000 10对PID为12345的JVM进程每隔1000毫秒即1秒采样一次共输出10条-gcutil格式的数据。在实际操作中我一般先执行jstat -options看一下当前JDK支持哪些选项尤其服务器上JDK版本不一的时候确认一下最稳妥$ jstat -options -class -compiler -gc -gccapacity -gccause -gcmetacapacity -gcnew -gcnewcapacity -gcold -gcoldcapacity -gcutil -printcompilation看到这个列表再对照JDK文档心里基本就有数了。需要注意的是不同JDK版本输出的列会有细微差别比如JDK8之后多了Metaspace和CCS相关列JDK9以后的容器环境还能看到线程栈大小等信息以实际输出为准。2.2 一条最常用的命令与输出解读假设我们在服务器上用jps找到了业务进程$ jps -l 12345 com.example.order.OrderService然后执行$ jstat -gcutil 12345 1000 5输出大概长这样S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 63.21 78.50 42.35 86.21 80.33 1024 15.214 12 2.138 17.352 0.00 63.21 81.66 42.35 86.32 80.45 1025 15.241 12 2.138 17.379 0.00 63.21 85.10 42.35 86.51 80.67 1026 15.308 12 2.138 17.446第一眼很花拆开看其实就三类信息堆各区使用率、GC次数、GC累计耗时。列名全称说明S0Survivor区0新生代中Survivor区0的使用率百分比S1Survivor区1新生代中Survivor区1的使用率百分比EEden区新生代Eden区使用率百分比O老年代老年代使用率百分比M元空间元空间使用率百分比CCS压缩类空间类指针压缩空间使用率百分比JDK8及以后常见YGC新生代GC次数也就是Minor GC发生的次数YGCT新生代GC耗时所有Minor GC累计耗时单位秒FGCFull GC次数老年代或整堆Full GC发生的次数FGCTFull GC耗时所有Full GC累计耗时单位秒GCTGC总耗时新生代GC和Full GC的累计耗时总和单位秒这里有个经验点观察GC数据不能只看绝对值要看变化趋势。比如一分钟之内YGC从1024涨到1200那相当于一分钟发生了176次Minor GC平均每秒接近3次这个频率对大多数业务系统已经偏高了。更值得警惕的是FGCT如果有明显增长说明系统在做Full GC老年代会不断被扫描回收停顿时间很容易以“秒”为单位。第一条命令拿到后先看两边趋势一边是YGC与YGCT的增速一边是O区的占比变化基本就能判断是否进入“内存压力”状态。3. 参数详解按监控目标把jstat选项逐个吃透3.1 类加载与即时编译-class、-compiler、-printcompilation多数人排查GC问题时会忽略类加载和编译这两个维度但它们恰恰能解释一些诡异现象比如CPU突然飙高、单次GC间隔异常。先看类加载情况命令是jstat -class 12345输出示例Loaded Bytes Unloaded Bytes Time 3568 7893.2 102 1534.1 1.35Loaded已加载的类数量Bytes已加载类占用的空间单位KBUnloaded已卸载的类数量Bytes已卸载类占用的空间Time类加载和卸载累计耗时单位秒类加载数量异常增长时要警惕是否有反射生成类、频繁创建动态代理、或者元空间泄漏的苗头。比如某个框架在运行期不断生成新的ClassLoaded数量持续爬升最终就会把Metaspace顶到上限。再看即时编译状态命令是jstat -compiler 12345输出示例Compiled Failed Invalid Time FailedType FailedMethod 4626 0 0 12.87 0Compiled成功编译的方法数量Failed编译失败的方法数量Invalid编译后又被判定为无效的方法数量Time编译累计耗时单位秒FailedType编译失败的类型FailedMethod编译失败的方法名JIT编译本身是好事方法被编译成机器码后执行效率更高。但如果Invalid数量剧烈增大说明编译结果频繁作废通常和代码逻辑频繁变化、类被重复加载有关。还有一种场景启动初期Compiled数量会迅速增长业务还没预热完成就把流量打进来CPU会被JIT编译分走大量资源这在大流量发布时很常见。最后是-printcompilation它显示的是最近被JIT编译的方法列表jstat -printcompilation 12345输出示例Compiled Size Type Method 63 128 1 java/lang/String.hashCode ...这个方法在实际排障中我会用在“CPU飙高但不知道热点在哪”的场景配合-compiler看有没有大量方法在编译。注意这个方法只能显示最近一次编译信息不是历史编译清单所以更适用于对比正常情况下编译数量平稳异常时编译量突然激增。3.2 堆内存与GC主视角-gc、-gcutil、-gccause这三个参数是日常排障的主力重点展开。-gc参数输出的是堆内存各区域的“容量和使用量”单位是KB不同JDK版本略有差异但基本都是KB。命令jstat -gc 12345 1000 5输出示例S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT 8192.0 8192.0 0.0 5192.0 65664.0 54320.1 175648.0 74262.3 65432.0 56320.1 8192.0 7680.2 1026 15.241 12 2.138 17.379看着比-gcutil复杂理解规律其实很简单每个区域都有C和U两个列C表示该区域当前容量CapacityU表示该区域已使用量Used。比如S0C是Survivor区0的容量S0U是Survivor区0的使用量EC是Eden区容量EU是Eden区使用量OC是老年代容量OU是老年代使用量MC是元空间容量MU是元空间使用量CCSC是压缩类空间容量CCSU是压缩类空间使用量。-gcutil就简单了它直接给出使用率百分比和-gc的数据其实是同一件事的两种表达方式。一个看绝对值一个看百分比。在我看来如果只想快速判断内存压力-gcutil更直观如果要计算“Eden区还剩多少容量”来推算分配速率那-gc更合适。两者互补着用。-gccause则在-gcutil的基础上多了两列LGCC最近垃圾回收原因和GCC当前垃圾回收原因。命令jstat -gccause 12345 1000 5输出大致这样S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC 0.00 63.21 88.10 43.20 86.40 80.30 1028 15.400 12 2.138 17.538 Allocation Failure Allocation Failure这两列非常有用。最常见的原因是Allocation Failure意思是“分配内存失败被迫触发GC来腾地方”本质说明当前内存不够用或者分配速率过快。如果是G1垃圾回收器还可能看到G1 Evacuation Pause、G1 Humongous Allocation这类原因。G1 Humongous Allocation表示有大对象超过Region大小一半直接在老年代分配往往是大数组、大缓存引起的这种对象频繁出现很容易造成老年代碎片。我在定位问题时先扫LGCC和GCC的出现频率如果反复出现Allocation Failure基本可以断定是内存压力如果出现频率很低那GC频次高可能是代码里频繁创建大对象引起的此时就应该转向jmap和代码排查了。3.3 容量与分段视角-gccapacity、-gcnew、-gcold及对应capacity这几个参数适合观察堆内存容量边界和动态扩容状态。-gccapacity展示了各区域的最小容量、最大容量、当前容量以及段大小。命令jstat -gccapacity 12345输出列很长重点看这些NGCMN新生代最小容量NGCMX新生代最大容量NGC新生代当前容量OGCMN老年代最小容量OGCMX老年代最大容量OGC老年代当前容量MCMN元空间最小容量MCMX元空间最大容量MC元空间当前容量为什么要关注容量因为很多服务启动时不会立刻把堆撑到-Xmx设定值而是随着使用量逐渐扩容。如果发现NGC已经等于NGCMX说明新生代已经到了上限接下来如果还需要更多Eden空间就只能触发GC后复用空间这个阶段最容易出现GC频率上升。老年代同理。-gcnew只看新生代细节jstat -gcnew 12345 1000 5输出里包含S0C、S1C、S0U、S1U、MTMin Tenuring阈值、EC、EU、YGC、YGCT等列。MT是对象晋升到老年代的年龄阈值默认通常是15但动态年龄判定Dynamic Tenuring会调整这个值。如果你发现老年代OU在快速上涨但YGC并没有很多次那可能是MT太小对象过早晋升了。-gcold则只看老年代jstat -gcold 12345输出包括OGCMN、OGCMX、OGC、OC、OU、YGC、FGC、FGCT、GCT。重点观察OU老年代使用量的曲线如果它一直增长、从不清零那么不管YGC次数多低最终都逃不过Full GC。另外还有-gcnewcapacity和-gcoldcapacity它们更多用于容量分配分析和-gccapacity类似不过细分到新生代老年代各自的最小、最大、当前容量。这几个参数我不建议一开始就用容易看花眼。先掌握-gcutil和-gccause遇到内存边界问题时再看容量类参数这样节奏最舒服。4. 实操复盘用jstat定位一次真实接口变慢4.1 现象与第一轮观察有一次线上订单服务接口的RT从20ms涨到300ms还有持续上升的趋势。接到告警以后我登录服务器先看了CPU和负载CPU使用率并不高内存也没满这让我第一反应是“可能不是单纯的计算量增加”而是GC停顿在作祟。当时我用jps找到进程号后直接敲了这条命令jstat -gcutil 21456 1000 10前两秒的输出让我立刻警惕起来S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 88.10 99.20 65.30 85.20 79.80 26021 218.32 38 96.25 314.57 0.00 62.00 98.70 65.31 85.25 79.85 26022 218.36 38 96.25 314.61Eden区使用率一直在98%以上YGC在一秒内涨了一次FGCT已经累计96秒FGC一共38次平均一次Full GC耗时2.5秒以上。这说明系统已经处在非常危险的状态每次Full GC都冻结业务线程2秒以上接口RT被拉高到300ms完全对得上。4.2 连续采样与趋势观察光有两条数据还不够我继续执行jstat -gcutil 21456 500 20每500毫秒采样一次连续20条这样能看到更细的GC节奏。结果发现一个规律每隔3到5秒YGC次数就涨一次每次YGC之后S1区从接近满的状态降到很低Eden又从接近满重新开始积累。这说明新生代对象频繁触发Minor GC但大部分对象在Minor GC之后并没有被清掉而是熬过了几次复制后进入老年代导致OU老年代使用量也在肉眼可见地增长。我又敲了-gccause确认触发原因jstat -gccause 21456 1000 5LGCC列反复出现Allocation Failure这更加确认了判断内存分配速率远大于回收速率老年代空间也在持续消耗最终每隔一段时间就有一次Full GC来“填坑”。4.3 定位结论与辅助操作第一轮定位到这里还不能轻易下结论说是“内存泄漏”因为有一种常见情况是流量突增导致对象总量变大。所以我接下去做了两个动作。首先看老年代容量设置。我用jstat -gccapacity 21456看到OGCMX是2GBOGC是老年代当前容量1.5GB左右说明堆还有空间但老年代既然已接近1.5GB且持续上升问题肯定真实存在。然后我把jmap和jstack作为辅助工具继续深挖。jmap -histo 21456 | head -30可以看到占用实例数最多的类jstack 21456则看业务线程在做什么。最终定位到某条缓存线程在频繁往一个静态Map里写数据key不重复导致Map无限膨胀。这个Map里的对象被老年代引用GC回收不掉OU自然越来越高。整个排查过程耗时大约10分钟前5分钟基本靠jstat就锁定了“GC停顿拖垮RT”这条主线后面jmap和代码审查是验证根因。如果没有jstat我可能还要先翻监控平台看曲线再推断是不是数据库慢查询导致RT升高完全走错方向。5. 实战避坑常见问题排查与工具配合顺序5.1 S0/S1一直为0是正常情况吗很多刚接触jstat的人会问为什么我的S0和S1长期是0是不是监控错了大多数情况是正常的。我在JDK8和JDK11下的常见GC组合里都见过这种现象。原因有几个第一当你使用SerialGC或者ParallelGC时如果新生代里绝大多数对象在Minor GC之后直接晋升到老年代Survivor区可能根本没有对象存活S0和S1自然可能为0。第二如果你的服务对象生命周期很短每次GC前Eden区对象本来就不多Minor GC直接清空那么Survivor区可能会被清成0。这本身说明“回收很干净”。第三G1和ZGC这类垃圾收集器的逻辑和传统分代GC差异很大G1在-gcutil输出里的Survivor列也不一定会像ParallelGC那样持续有数据。比如ZGC在某些版本里对Survivor区的概念和传统解释完全不同所以不能拿CMS的老经验硬套。判断是否异常不应该只看S0/S1而要看整体趋势。如果S0/S1长期为0但Eden区每次都大量存活对象晋升老年代OU不断上涨那才值得我们担心。5.2 jstat与jmap、jstack的配合顺序排障工具的使用顺序非常重要。我总结的经验是先看统计再抓现场最后分析堆栈。jstat属于统计类jmap和jstack属于抓现场类。顺序颠倒很容易踩坑。一个典型的错误是线程卡顿问题一上来就jstack看到一堆线程在等待锁就急着分析锁关系。但如果不先用jstat确认GC状态完全有可能这堆线程只是在等GC停顿结束它们所谓的“等待锁”其实是阻塞之后的表现形式。等GC停下来锁等待自然消失。先jstat排除GC因素再上jstack分析出的线程状态才真实可靠。jmap的情况更要注意。jmap -dump:live,formatb,fileheap.bin pid会先触发一次Full GC再生成堆转储在高峰期执行这个操作等于给服务雪上加霜。所以我通常建议能只靠jstat和jstack判断的问题就不轻易jmap确实需要堆转储先保证服务允许短暂停顿或者等低峰期再执行。排障的完整顺序我个人比较推荐这样jps确认进程号jstat -gcutil和jstat -gccause看GC趋势和原因jstack看线程状态快速确认是否因GC停顿造成大规模阻塞必要时jmap -histo看对象分布最后再做堆转储深入分析5.3 易错写法与JDK版本差异我用jstat这些年遇到过几个非常容易踩的坑。第一个坑把进程名当成PID。jstat的vmid必须是数字PID你直接写进程名它不认识。每次都要先jps或pgrep查进程号很多人想省这一步结果报错Unknown host或者Illegal vmid白白浪费时间。第二个坑采样参数顺序写错。jstat -gcutil 12345 1000 5表示每1000毫秒采样5次但如果你写成jstat -gcutil 12345 5 1000意思就变成每5毫秒采样1000次。5毫秒一次的采样间隔对jstat本身影响不大但输出几千行数据肉眼根本看不过来。单位尽量用秒级比如1s、2s简单不易错。第三个坑权限问题。某些容器环境或者云服务器上当前操作系统的用户不是Java进程的启动用户jps可能看不到进程jstat执行时也会报permission denied。这时候要用sudo -u 启动用户执行或者直接切换到目标用户下操作。还有一些高度受限的容器里JVM的/tmp目录perfdata文件可能无法创建jstat会报无法获取统计信息的错误需要先确认容器的临时目录是否可写。第四个坑JDK版本差异导致输出列不一样。比如JDK8的-gcutil有CCS列JDK11的ZGC输出又可能没有传统Survivor概念。还有JDK8中的Metaspace使用率M列如果用了-XX:MaxMetaspaceSize和未设置时显示逻辑也不同。所以不同机器之间对比时先把JDK版本对齐否则你会拿不同的口径在比较数据。建议每次换一台新服务器排查之前先执行java -version和jstat -options两个命令确认环境不要靠记忆硬写。6. 写在最后的一些个人经验最后聊几句我用了这么久jstat的真实感受。第一它能解决80%的“Java进程变慢但不知道从哪下手”的问题。每次有人来问我服务卡了怎么排查我永远先让他们敲一次jstat -gcutil。结果往往立刻就有方向要么YGC频繁到离谱要么FGC一涨就是几十秒。先把GC问题排除掉剩下的代码、锁、数据库问题才会浮现出来。这个顺序帮我少走了很多弯路。第二jstat的输出不要只看一条要连续观察一段时间。我习惯用jstat -gcutil 12345 1s 60这种方式看一分钟趋势。如果YGC增长速率稳定GC总耗时也平稳服务可能就是正常状态一旦速率异常上升马上就能抓住。只截一张图看瞬时值很难区分“这一秒恰好GC”和“持续都在快速GC”这两种情况。第三jstat还能用来验证调优效果。比如我调整了新生代比例或者换了GC算法隔半小时跑一次jstat把YGC频率和FGCT做前后对比效果一目了然。这种轻量级的验证方式比起专门搭一套压测环境要简单得多。工具终究是工具真正值钱的是把它放到合适的问题上下文里。jstat给我最大的帮助不是它本身有多炫而是它让JVM从“黑盒”变成“透明盒”。当你能一眼看出Eden区飞速膨胀、老年代缓慢上涨、Full GC越来越频繁的时候那些关于内存分配、对象生命周期、GC参数的话题才真正开始有了现实意义。
返回列表