JVM优化之GC日志智能分析神器
以下都是基于JDK8来描述的.
1.开启并收集GC日志
在java命令后面加上
-verbose:gc -Xloggc:/xxpath/gc.log -XX:+PrintGCDetails-XX:+PrintGCDateStamps例如:
java -verbose:gc -Xloggc:/xxpath/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -jar app.jar上述三个参数的作用:
| 参数 | 作用 |
|---|---|
| -verbose:gc | 开启GC日志收集 |
| -Xloggc:/xxpath/gc.log | 指定GC日志输出文件路径 |
| -XX:+PrintGCDetails | 设置打印GC详细日志 |
| -XX:+PrintGCDateStamps | 设置GC点时间格式(2022-05-26T12:32:02.890+0800:), 如果不设置GC点时间格式默认是显示服务运行秒数 |
2.分析GC日志
加了上述参数等应用运行一段时间, 比如3天或7天, 把/xxpath/gc.log取下来.
原始GC日志是这样子的:
7.740: [Full GC (Metadata GC Threshold) [PSYoungGen: 6735K->0K(136704K)] [ParOldGen: 24401K->17510K(57344K)] 31136K->17510K(194048K), [Metaspace: 34368K->34368K(1081344K)], 0.1388583 secs] [Times: user=0.33 sys=0.12, real=0.14 secs] 10.494: [GC (Allocation Failure) [PSYoungGen: 123904K->11008K(137728K)] 141414K->28526K(195072K), 0.0838826 secs] [Times: user=0.21 sys=0.02, real=0.09 secs] 11.493: [GC (Allocation Failure) [PSYoungGen: 134912K->2865K(177152K)] 152430K->25831K(234496K), 0.0198848 secs] [Times: user=0.06 sys=0.01, real=0.02 secs] 13.930: [GC (Allocation Failure) [PSYoungGen: 165681K->12834K(177664K)] 188647K->37796K(235008K), 0.0345968 secs] [Times: user=0.04 sys=0.04, real=0.04 secs] 15.398: [GC (Metadata GC Threshold) [PSYoungGen: 94075K->9427K(226304K)] 119037K->41622K(283648K), 0.0364978 secs] [Times: user=0.04 sys=0.04, real=0.04 secs] 15.435: [Full GC (Metadata GC Threshold) [PSYoungGen: 9427K->0K(226304K)] [ParOldGen: 32195K->38354K(91648K)] 41622K->38354K(317952K), [Metaspace: 57372K->57372K(1101824K)], 0.3365935 secs] [Times: user=0.74 sys=0.10, real=0.33 secs] 19.276: [GC (Allocation Failure) [PSYoungGen: 210432K->13867K(226304K)] 248786K->52229K(317952K), 0.0226411 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 21.777: [GC (Allocation Failure) [PSYoungGen: 224299K->17382K(273920K)] 262661K->57830K(365568K), 0.0474308 secs] [Times: user=0.14 sys=0.04, real=0.04 secs] 264.295: [GC (Allocation Failure) [PSYoungGen: 273894K->10185K(276992K)] 314342K->63761K(368640K), 0.0621364 secs] [Times: user=0.06 sys=0.09, real=0.06 secs] 273.297: [GC (Allocation Failure) [PSYoungGen: 266697K->2908K(301056K)] 320273K->56511K(392704K), 0.0169761 secs] [Times: user=0.03 sys=0.02, real=0.02 secs] 我们取其中一行来解读它的意思:
7.740: [Full GC (Metadata GC Threshold) [PSYoungGen: 6735K->0K(136704K)] [ParOldGen: 24401K->17510K(57344K)] 31136K->17510K(194048K), [Metaspace: 34368K->34368K(1081344K)], 0.1388583 secs] [Times: user=0.33 sys=0.12, real=0.14 secs] | 字段 | 含义 |
|---|---|
| 7.740 | GC时间点(程序截止当前运行时间) |
| Full GC | GC类型 – 分GC和Full GC, GC是仅young heap进行垃圾回收, Full GC是young heap & old heap & Metaspace 都进行垃圾回收 |
| Metadata GC Threshold | GC原因 – 元空间使用达到临界点, JDK8元空间是使用本地内存, 但是如果不手动指定原空间大小XX:MetaspaceSize, 它默认的值是21M; (常见的还有Allocation Failure, 即分配内存失败, 可能是内存不足或者内存碎片太多, 不足存放新对象) |
| PSYoungGen: 6735K->0K(136704K) | 年轻代回收算法: 回收前内存大小->回收后内存大小(总内存大小) |
| ParOldGen: 24401K->17510K(57344K) | 老年代回收算法: 回收前内存大小->回收后内存大小(总内存大小) |
| 31136K->17510K(194048K) | 堆: 回收前内存大小->回收后内存大小(总内存大小) |
| Metaspace: 34368K->34368K(1081344K) | 元空间: 回收前内存大小->回收后内存大小(总内存大小) |
| 0.1388583 secs | GC耗时 |
| Times: user=0.33 sys=0.12, real=0.14 secs | user: GC需要各个cpu的总时间(各个cpu时间相加) sys: GC自身行为占用的cpu时间 real: 本次GC真实耗时 |
这样的gc日志用肉眼很难分析全面, 所以我们借助一个外部gc日志在线分析工具:
链接：https://gceasy.ycrash.cn/gc-index.jsp
上传GC日志到上述网站, 会生成一份GC分析报告, 我大概选几个地方说一下.
3.GC分析报告 – 长时间停顿警告
如上图, 该报告提示, 4个GC事件花费了超过5.0秒, 这个几秒的停顿对系统业务来说影响很大了.
4.GC分析报告 – 程序等待资源
如上图, 该报告提示, 应用程序由于缺乏计算资源(CPU/IO)而正在等待, 有3个GC事件中的real耗时 > user耗时 + sys耗时
这里我说明一下, 这个问题是由于我一台服务器上部署了太多了应用导致的.
5.GC分析报告 – JVM内存大小
如上图, 报告显示, 该应用Young代和Old代的已分配内存大小和峰值内存大小相当, 说明内存不足, 应该加大内存. 而Metaspace的已分配远大于峰值, 说明存在浪费, 应该缩小Metaspace的值. Young+Old+Metaspace的已分配远大于峰值, 结合上面Young和Old的内存不足, 说明Metaspace的内存分配存在严重的浪费, Young和Old的内存不足会导致频繁GC, 从而使应用性能严重下降.
假如以上面总内存2G来分配, 结合上面的峰值参数, 我会这样分配来测试:
-Xms1800m -Xmx1800m -Xmn900m -XX:MetaspaceSize=200m -XX:MaxMetaspaceSize=200m上面的参数是加在java命令之后,
-Xms: 初始堆的大小(年轻代+老年代)
-Xmx: 堆最大的大小(年轻代+老年代)
-Xmn: 年轻代的大小(老年代=Xmx-Xmn)
-XX:MetaspaceSize 元空间初始大小
-XX:MaxMetaspaceSize 元空间最大大小
当然最好是可以有更多的内存, 这样可以给年轻代和老年代分配更多. 当前这样分配后, 可以重启应用, 继续收集相同周期的GC日志, 然后生成新的分析报告, 在看新分析报告中JVM内存大小中的各项峰值是否接近已分配, 如果是, 说明内存仍然不足. 可以考虑加内存或者优化程序代码.
6.GC分析报告 – 关键性能指标
如上图, 报告可以显示吞吐量 & 平均停顿 GC 时间 & 最大停顿 GC 时间, 通过这些参数我们可以评估是否需要调优, 以及对比调优后的效果.
7.GC分析报告 – 堆内存GC前后大小对比
如上图, 可以通过年轻代、年老代的分配空间、GC前空间、GC后空间分析出对象存活率情况
8.GC分析报告 – GC持续时间
如上图, GC持续时间可以看出Young GC和Full GC的耗时情况, 针对耗时长的考虑做优化
9.GC分析报告 – Yound代已分配和晋升
如上图, 通过红线可以看出Young代晋升到Old代的大小情况
10.GC分析报告 – GC统计数据
GC统计数据可以很直观地看各项数据
11.GC分析报告 – GC原因统计
GC原因统计可以看出触发GC的原因, 然后再结合上面JVM
大小进行优化.