1.准备工作
1.1.应用程序
GCQuerySampleApplication.jar
代码如下:
/**
* 模拟用户请求
* 设定最大内存1024m
* 每100毫秒创建100个线程,每个线程创建一个1mb的对象,最多一秒同时存在1000线程,最多占用内存1024MB(100%)
* 对象存活在1秒左右的场景,远远超过平时接口的响应时间要求,场景应该为吞吐量优先
*/
public class GCQuerySampleApplication {
public static void main(String[] args) {
Executors.newScheduledThreadPool(1).scheduleAtFixedRate(() -> {
new Thread(() -> {
for (int i = 0; i < 100; i++) {
try {
// 不干活,专门生成1mb的小对象
byte[] temp = new byte[1024 * 1024];
// 随机睡眠1秒以内
Thread.sleep(new Random().nextInt(1000));
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}).start();
}, 100, 100, TimeUnit.MILLISECONDS);
}
}
1.2.分析工具
1)、实时分析工具:jstat命令
2)、离线分析工具:gcviewer-1.35.jar 双击打开即可。
2.GC分析
2.1.实时分析
2.1.1.启动程序
java -Xmx1024m GCQuerySampleApplication.jar
2.1.2. 查询GC类型
1)、先查询程序的进程号
命令:jcmd | findstr "GCQuerySampleApplication.jar"
执行结果:41628 GCQuerySampleApplication.jar
2)、查询指定java程序的启动参数
命令:jcmd 进程号 VM.flags
执行结果:
-XX:CICompilerCount=3 -XX:InitialHeapSize=264241152 -XX:MaxHeapSize=1073741824
-XX:MaxNewSize=357564416 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=88080384
-XX:OldSize=ssedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps
-XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
从中可以看出,使用的是ParallelGC。
2.1.3.实时分析GC日志
接下来,我们使用jstat命令(jstat -gc -h10 进程号 1000),实时分析10秒钟的数据。
分析:
jstat命令的结果包含新生代内存占用、老年代内存占用、其他区内存占用和GC等四大方面的指标。
Heap分为新生代(PS YoungGeneration)和老年代(PS Old Generatio)以及其他区等。本文把元数据区和指针压缩归入到其他区的统计范围。
【新生代内存占用情况】
新生代分为Eden 区(Eden Space)和两个Survivor 区(分别是From Space和To Space)。
S0和S1指的是Survivor两个区,即From区和To区。
S0C和S1C指的是Survivor两个区的当前容量,单位是kB。
从下图我们可以看出,S0的当前容量为84-94MB,相对稳定一些,而S1的当前容量变化相对来说比较大一些,从73-96MB。可以看出Survivor的两个区的容量均比较小。
注:本文对kB转化成MB计算不规范,正常应该是除以1024,我这里也是偷懒,直接除以1000。不够严谨,希望读者别介意。
S0U和S1U指的是Survivor两个区的利用率,单位是kB。
从下图我们可以看出,S0和S1两个区中,总有一个区的利用率为0——究其原因,是为了支持复制算法。
另外,S1U在短短的10秒中,从78MB降至0,再从0升到84MB,接下来又降至0——说明Survivor区的内存空间变化非常大,内存操作频繁。根据Java内存模型规范,Survivor区的变化将影响到Eden区。
EC和EU分别指的是Eden区的容量和利用率,单位是kB。
从下图我们可以看出,Eden区的容量在153-176MB左右。而利用率变化比较大,在短短的10秒内,从开始的50MB变化到0,再从0增加到146MB,然后再缩小到42MB,后又增加到138MB,最后缩小到76MB。
可以看出Eden区的内存空间变化也非常频繁。究其原因,Survivor区内存空间频繁变更将导致Eden区内存空间持续增加。而当Eden内存空间占满后,数据将会“转移”到老年代区。
【老年代内存占用情况】
OC和OU分别指的是老年代区的容量和利用率,单位是kB。
从下图我们可以看出,老年代的容量是从355MB开始,在10秒内慢慢增加大381MB。说明了老年代的容量不够用,在慢慢申请更多的内存。
而老年代的利用率在从143MB增加到241MB,再减少到143MB,后又增加到274MB,然后减少到144MB,之后继续增加到288MB,最后减到237MB。老年代利用率增加大致有两个途径,一是从Eden区“转移”过来,另外一种是大内存申请,直接占用老年代空间。由于我们的程序每个线程申请1MB内存,不涉及大内存占用情况,因此会先写新生代区的内存,不会直接写老年代区,老年代这边的内存增量是从Eden区“转移”而来的数据。另一个方面看,老年代的内存利用率在减少,说明了发生了Full GC,因为正常情况下老年代区的内存只会增加,当空间不够用时,将通过Full GC来释放空间。
【其他区内存占用情况】
MC和MU指的是元数据区(Metaspace)的容量和利用率,单位是kB。
从下图我们可以看出,元数据区占用4.8MB容量,而利用率在3.8MB左右。可以看出,利用率还是挺高的,占79%,虽然10秒钟内有所变化,从开始3869kB,到第4秒升了1kB,不过,到了第6秒后就保持在3891kB,总体来说,比较稳定。
另外一个就是类指针压缩空间,CCS。
CCSC和CCSU分别指的是类指针压缩空间的容量和利用率,单位是kB。
从下图我们可以看出,类指针压缩空间占用512kB容量,而利用率在446kB左右。可以看出,利用率还是挺高的,占87%,不过相对来说比较稳定,10秒钟内没有变化。
【GC-新生代GC】
YG指的是Young GC,新生代GC。
YGC指的是新生代GC活动的数量。
YGCT指的是新生代GC时间,单位秒。
从下图我们可以看出,在短短的10秒内,发生了29次GC(68-39=29)。而且时间为(0.888-0.826)/(42-39)=0.021,即21毫秒。
【GC-Full GC]
FGC指的是Full GC。
FGC这个指标指的是Full GC的数量。
FGCT指的是Full GC时间。
从下图我们可以看出,在这10秒内,发生了15-9=6次的Full GC。Full GC发生的很频繁。一次Full GC的时间是(0.216-0.192)/(10-9)=0.024,即24毫秒。
[GC-GCT]
GCT指的是GC总时间,包括Young GC和Full GC的总时间。
从下图可以看出,平均每秒发生GC的时间是(1.720-1.018)/10=0.0702,即70毫秒。相对来说,GC占用时间较大。
【10几个小时后,再次分析】
10几个小时后,我们再次使用jstat命令(jstat -gc -h10 进程号 1000),实时分析10秒钟的数据。
图中上半部分是之前的实时分析结果,后半部分是10几个小时后的结果。
从图中,我们可以看出,以下几个变化:
Survivor区变化
从图中可以看出,Survivor区发生了很大变化,内存容量从原来的90MB减少到现在的512kB。
Eden区变化
从图中可以看出,Eden区发生了很大变化,内存容量从原来的170多MB左右增加到现在的300多MB左右。
老年代区变化
从图中可以看出,老年代区发生了很大变化,内存容量从原来的370多MB左右增加到现在的512MB。
其他区变化
从图中可以看出,元数据区和类指针压缩空间几乎没有变化。尤其是元数据区的利用率,之前还有在慢慢增加,现在利用率完全没有变化,固定3927kB这个值上。
GC变化
Young GC的次数,由之前的29次变成现在的31次,总体上变化不大。
Young GC的时间,由之前的56毫秒变成现在的8毫秒,时间减少很多。
Full GC的次数,由之前的6次变成现在的0次,变化明显。
Full GC的时间,由之前的24毫秒变成现在的0毫秒,变化明显。
平均每秒发生总GC的时间,由原来的70毫秒减少到目前的8毫秒,变化明显。
2.2.离线分析
2.2.1.收集日志
通过命令收集离线日志:
java -Xmx1024m -Xloggc:d:/run/gcquery.log -jar GCQuerySampleApplication.jar
这次收集的日志是在程序运行74秒后进行的。
2.2.1.1.使用工具辅助分析日志
我们可以通过GCviewer对日志文件进行分析,从不同角度分析当前的GC情况。具体包括查询Chart图、查看GC类型、查看Event details信息、查询Memory信息、查询GC的Pause信息、查询概要信息等。
查询Chart图
该图反映整体的GC情况。
在图中,第一分钟的信息是完整的,而第二分钟的由于还没有结束,因此,不作参考。
在第一分钟的图中,红色部分代表的是总Heap的大小,蓝色是代表已占用Heap大小,说明内存使用频率较高。黑色线是Full GC,说明这段时间内Full GC发生频繁。
图形显示由于多种颜色的线叠加在一起,可能会产生错觉,或者不直观,此时需要把其他线去掉,例如,我们想查看GC耗时线,在上面的图中看不出来。此时我们把其他线去掉,只显示GC耗时线,从而可以看出有一段时间GC耗时超过50毫秒,具体如下:
查询GC类型
我们在Parser窗口处,查看GC类型的情况。
可以看出,现在使用的是ParallelGC。
查看GC的Event details信息
【查看Young GC的统计信息】
我们在Event details窗口的“GC pauses”处,查看GC停顿的情况。
从下图可以看出在这段时间内,发生了329次的Young GC,其中GC引起的总停顿时间是4.8秒。
【查看FullGC的统计信息】
我们在Event details窗口的“Full GC pauses”处,查看Full GC停顿的情况。
从下图可以看出在这段时间内,发生了31次的Full GC,其中GC引起的总停顿时间是0.74秒。
【查看并发GC的统计信息】
我们在Event details窗口的“Concurrent GSs”处,查看并发GC停顿的情况。
从下图可以看出在这段时间内,发生了0次的并发 GC,其中GC引起的总停顿时间是0秒。这是由于我们使用的是ParallelGC——这是并行GC。
查询Memory信息
Memory这里的统计信息,包括整个堆内存最大空间、已使用空间、Full GC完后当前最大内存空间、GC累积释放多少内存空间、GC平均释放多少内存空间等信息。
如下图所示,最大堆内存占用是730MB,目前已经使用660.1MB,占用率为90.4%。在最近一次Full GC完后,剩余141.1MB可用。
Freed by Full GC说明Full GC总共释放了8.2G的内存空间。
Freed by GC说明Young GC总共释放了72.7G的内存空间。
Avg freed FullGC说明每次Full GC平均释放266.3MB的内存空间。
Avg freed GC说明每次Young GC平均释放221.2MB的内存空间。
查询GC的Pause信息
Pause这里的统计信息,除了Event details有的GC总次数和GC总时间,还包括平均停顿时间,最长停顿时间和最短停顿时间。
如下图所示,平均停顿时间是15毫秒,最长一次停顿时间是56毫秒,最短一次停顿时间是1毫秒。
除了总停顿的统计信息,还包括FullGC以及新生代GC的统计信息。
查询Summy信息
Summy这里的统计信息,是对Memory和GC Pause信息的一个概览。另外还包括总用时(Total Time)、吞吐量(Throughput)、Full GC Performance以及Young GC Performance等信息。
如下图所示,总用时(Total Time)1分42秒,吞吐量为94.59%,Full GC 性能是每秒11GB,Young GC 性能每秒15GB。
3.总结
根据以上分析,可以得到以下结论:
- JVM会收集运行程序的执行过程信息,然后自动调整新生代、老年代的内存结构比例,进行优化。
- JVM的自动优化效果主要体现在减少GC时间,提高每秒中应用执行时间的占比,从而达到提高应用执行效率的目的。
文章结束。