欢迎您访问程序员文章站本站旨在为大家提供分享程序员计算机编程知识!
您现在的位置是: 首页  >  IT编程

深入学习JAVA GC日志的相关知识

程序员文章站 2024-01-04 13:45:16
gc环境模拟 首先我们给出如下代码用来触发gc public static void main(string[] args) { // 每100毫秒创...

gc环境模拟

首先我们给出如下代码用来触发gc

public static void main(string[] args) {
// 每100毫秒创建100线程,每个线程创建一个1m的对象,即每100ms申请100m堆空间
executors.newscheduledthreadpool(1).scheduleatfixedrate(() -> {
for (int i = 0; i < 100; i++) {
new thread(() -> {
try {
// 申请1m
byte[] temp = new byte[1024 * 1024];
thread.sleep(new random().nextint(1000)); // 随机睡眠1秒以内
} catch (interruptedexception e) {
e.printstacktrace();
}
}).start();
}
}, 1000, 100, timeunit.milliseconds);
}

我们要模拟的场景是年轻代不断地young gc,并有一部分对象晋升到老年代,当老年代空间不足时触发full gc。

程序逻辑:每100毫秒钟创建100个线程,每个线程创建一个1m的对象,即每100ms申请100m堆空间。之所以每个线程随机睡眠1s,是为了避免对象朝生夕灭,保证可以有一部分对象能晋升到老年代,更好的触发young gc 和 full gc,注意这个睡眠时间如果大了,会导致oom,如果小了,很难触发full gc。

虚拟机参数解释

启动java进程:java -xms200m -xmx200m -xmn100m -verbose:gc -xx:+printgcdetails -xloggc:./gc.log -xx:+printgcdatestamps -jar demo-0.0.1-snapshot.jar

-xms200m -xmx200m 最小/最大堆内存 200m

-xmn100m 年轻代内存 100m

-verbose:gc 开启gc日志

-xx:+printgcdetails -xloggc:./gc.log -xx:+printgcdatestamps 将gc日志详情输入到gc.log中

jmap分析

jcmd 获取我们java进程的id:6264

jmap -heap 6264查看堆信息

第一次查看,我们发现 eden区是98m,s0、s1是1m

深入学习JAVA GC日志的相关知识

第二次查看, eden区是99m,s0、s1是0.5m

深入学习JAVA GC日志的相关知识

eden区与survivor区的比例在动态的变化,并不是默认的8:1:1。

原来我们使用默认的垃圾收集器parallel scavenge+parallel old组合,而该收集器下-xx:+useadaptivesizepolicy是默认开启的,即eden区与survivor区比例根据gc情况会自适应变化。

我们加上参数,关闭年轻代自适应,年轻代比例设置为8:1:1

-xx:-useadaptivesizepolicy -xx:survivorratio=8

另外为了尽早的触发full gc,我们新增虚拟机参数

-xx:maxtenuringthreshold=10

晋升年龄由默认的15修改为10,使得年轻代的对象更容易晋升到老年代

重启虚拟机查看jmap

深入学习JAVA GC日志的相关知识

年轻代

  • eden区80m 已使用51m,当前使用率63.8%
  • s0区10m 已使用0.43m,使用率4.37%
  • s1区10m 使用率为空

老年代

  • 100m 已使用18.39m,使用率18.9%

gc日志内容分析

查看我们输出的gc日志gc.log,选取其中两段

2019-06-09t02:55:30.993+0800: 330.811: [gc (allocation failure) [psyounggen: 82004k->384k(92160k)] 184303k->102715k(194560k), 0.0035647 secs] [times: user=0.00 sys=0.00, real=0.00 secs]
2019-06-09t02:55:30.997+0800: 330.815: [full gc (ergonomics) [psyounggen: 384k->0k(92160k)] [paroldgen: 102331k->5368k(102400k)] 102715k->5368k(194560k), [metaspace: 16941k->16914k(1064960k)], 0.0213953 secs] [times: user=0.02 sys=0.00, real=0.02 secs]

young gc

2019-06-09t02:55:30.993+0800: 330.811: [gc (allocation failure) [psyounggen: 82004k->384k(92160k)] 184303k->102715k(194560k), 0.0035647 secs] [times: user=0.00 sys=0.00, real=0.00 secs]
2019-06-09t02:55:30.997+0800: 330.815: [full gc (ergonomics) [psyounggen: 384k->0k(92160k)] [paroldgen: 102331k->5368k(102400k)] 102715k->5368k(194560k), [metaspace: 16941k->16914k(1064960k)], 0.0213953 secs] [times: user=0.02 sys=0.00, real=0.02 secs]

解释:

  • 年轻代gc:[gc前年轻代80.08m->gc后0.37m(年轻代总大小90m)]gc前堆179.98m->gc后堆100.3m(堆总大小190m),用时]
  • 其中年轻代总大小是90m而不是100m,这里我理解是年轻代当前最大申请到90m
  • 100m*80%=80m 是eden区大小
  • 80m*80% = 64m eden区默认占用超过8成即64m就会触发younggc

full gc

[full gc (ergonomics) [psyounggen: 384k->0k(92160k)] [paroldgen: 102331k->5368k(102400k)] 102715k->5368k(194560k), [metaspace: 16941k->16914k(1064960k)], 0.0213953 secs] [times: user=0.02 sys=0.00, real=0.02 secs]

解释:

  • [gc前年轻代0.375m->gc后年轻代0m(年轻代总大小90m)][gc前老年代99.93m->gc后老年代5.24m(老年代总大小100m)]gc前堆100.3m->gc后堆5.24m(堆总大小190m),[元数据区:gc前16.5,gc后16.5(元数据区总大小1040m)],用时]
  • 可以推测出此次fullgc原因是年轻代晋升老年代空间不足导致

利用可视化工具分析

这里我们利用 分析一下

(1)统计年轻代、老年代、元数据区最大可用空间以及峰值,这里元数据区大小在我们的虚拟机参数没有配置,所以取的是默认值

深入学习JAVA GC日志的相关知识

(2)吞吐量、gc平均延迟、最大延迟以及延迟区间的统计

深入学习JAVA GC日志的相关知识

(3)堆所用大小的实时分析,红色位置是发生了fullgc使得堆总量直线下降

深入学习JAVA GC日志的相关知识

会发现虚拟机在刚启动不久的阶段触发大量的full gc,我的理解是我们申请的对象都随机睡眠一秒以内,刚启动时大部分还存在线程的引用,gcroot可达。在刚启动的时候触发full gc并不会完整清理掉老年代空间并由于空间不足不断触发full gc。

(4)gc空间总量和时间的统计

深入学习JAVA GC日志的相关知识

(5)各类gc时间、gc次数、gc总量等指标

深入学习JAVA GC日志的相关知识

总结

gc日志分析可以帮助我们宏观的监控gc运行情况。一方面如果频繁的fullgc会有严重的性能问题(stw),另一方面过于频繁的gc,即gc占用系统正常运行的比重过多,吞吐量低,则是一定程度上的性能资源浪费。若系统存在性能问题,根据gc分析各项指标的作为参考,我们也可以适当的在程序里或虚拟机参数做些调优。

以上就是本文的全部内容,希望对大家的学习有所帮助,也希望大家多多支持。

上一篇:

下一篇: