概述
排查问题的一般思路是:现象 ——> 直接原因 ——>根本原因。
从问题现象出发,可以分为 应用逻辑问题、资源使用问题、虚拟机异常:
- 应用逻辑可能导致报错增加、死锁、程序退出等;
- 资源问题主要集中在CPU上升和内存上升(OOM Kill);
- 虚拟机问题通常包括GC问题、进程crash;
当然,不同的问题可能导向同一现象(比如crash和spring启动失败都会导致程序退出),从现象出发排查需要逐步验证、做排除法,最终定位根因。
1.0. 虚拟机行为排查
Java应用逻辑经由JVM虚拟机得以运行,JVM负责解释/编译 Java代码,并且管理运行时应用所需要的各种资源,维护应用状态。JVM的管理行为大多通过异步执行+Barrier的方式完成,不会对业务造成明显影响。但GC、Crash以及个别情况下的编译问题可能会对业务产生性能上的体感变化。
1.1. GC问题排查
1.1.1 GC算法
GC主要任务就是,自动回收掉应用不在需要的内存,保证应用程序运行过程中,使用内存可以控制在预设的Size范围内。由于Java进程的运行会持续伴随着内存分配,但Java用户几乎不需要主动归还内存,于是,归还内存的任务就交给了JVM,这个过程就叫做垃圾清理(Garbage Collect),且需要保证清理效率不低于应用使用内存的需求,否则就会出现积压,造成OOME的风险。
因此以时间维度来看,可以将Java运行分为3个阶段:
分配内存阶段 ——> 识别垃圾阶段 ——> 清理垃圾阶段;
如此一来,一个最简单的GC算法就出现了。我们进一步会考虑到,识别垃圾的同时能不能分配内存?清理垃圾的同时能不能也分配内存?如果我随时可以分配内存,那么GC不就影响不到应用运行了吗?JDK的发展就伴随着诸如此般优化,产生了不同的GC算法。
目前业界使用比较广泛的GC算法有:ParallelGC、G1GC、PauselessGC(Shenandoah && ZGC),小红书还有极个别场景使用Serial GC。这些GC算法的发展可以概述为几个方向:
- 【并发化(异步化)】:让更多GC的工作可以和应用同时并发进行,减少对应用运行的阻塞;例如G1的Concurrent Mark、ZGC的并发回收、异步GC log等;不管是哪种GC算法,都无法做到完全并发,这些无法与应用并发完成的工作会在STW(stop the world)中进行,STW的时长会导致应用的卡顿。
- 【并行化】:从 SerialGC 到 ParallelGC,JVM会开启多个GC线程同时完成GC任务。另外G1也是JDK9之后逐渐支持FullGC并行处理。并行处理GC可以降低JVM处在STW阶段的时长,降低对应用的影响。
- 【分代】:所有GC算法都基于分代假说成立而设立,对年轻代和老年代采取不同的策略可以大大减小GC的开销;新一代的ZGC和Shenandoah通常不分代,这是由于分代GC更难实现。JDK21已经Release分代Gen-ZGC,JDK25有机会Release分代Shenandoah;
- 【预测】:根据GC收集到的历史信息,预判未来应用行为,提前作出规划以满足更好的性能和卡顿要求。例如G1的动态预测、ZGC的Alloc Pacing等;
1.1.2 观察 GC 行为
监控
监控可以比较得看到GC变化趋势,快速定位问题时间点,从监控中通常可以获得几个GC指标:
GC频率
GC Pause时间(stw)
GC原因
各分区用量
对于RPC服务,GC频率、Pause、分区用量可以在 Xray 面板或调用链监控(Grafana)中找到,GC原因仅后者支持。
结合GC算法可以初步定位一些问题,例如:
- G1GC发生Old GC(也就是FGC)是异常行为,可以根据GC原因初步判断。
- GCCause::System.GC()则往往代表DirectMemory满了;
- GCCause::Metaspace Threshold代表metaspace不足需要扩充;
- GCCause::Evacuation Pause 代表对象分配过快,回收效率不匹配;
- 遇到Old GC问题,连续发生多次且Old区使用量不降低,基本可以确定为内存泄漏或内存size过大。接下来可以通过heapdump(1.1.3介绍)分析
- 如果使用Parallel GC,则发生Old GC为正常行为;仅需要关注GC次数/时间的变化曲线。
打开 GC Log
查看GC Log可以细致得知道历史时刻中GC的变化,根据GC变化反推产生变化的原因,从而定位具体问题。
使用JDK参数模版,默认会打开gc*,safepoint的info等级log,通过info log可以基本确定问题直接原因,有时继续定位根因需要进一步打开更多log,方式为:
//排查GC卡顿时间:打开gc+phases=debug
-Xlog:gc*=info,safepoint=info,gc+phases=debug:gc.log:time,tags,tid:filesize=20M