GC日志分析示例

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.总结

根据以上分析，可以得到以下结论：

1. JVM会收集运行程序的执行过程信息，然后自动调整新生代、老年代的内存结构比例，进行优化。
2. JVM的自动优化效果主要体现在减少GC时间，提高每秒中应用执行时间的占比，从而达到提高应用执行效率的目的。

 

文章结束。