G1 GC日志分析

Posted 2022-12-14 zmycoco2

使用UseG1GC这个选项显示地要求JDK7或者JDK8对应的JVM采用G1 GC，据说JDK9开始默认GC会变更为G1 GC（现在是ParallelGC）,但一切皆有可能。

我们使用VM参数-XX:+PrintGCDetails-verbose:gc -Xloggc:gc.log -XX:+UseG1GC，日志输出如清单3-12所示。

代码清单3-12 -XX:+UseG1GC运行输出

Java HotSpot(TM) 64-BitServer VM (25.101-b13) for windows-amd64 JRE (1.8.0_101-b13), built on Jun 222016 01:21:29 by "Java_re" with MS VC++ 10.0 (VS2010)

Memory: 4k page, physical3922532k(1585004k free), swap 7843228k(5137568k free)

CommandLine flags:-XX:InitialHeapSize=62760512 -XX:MaxHeapSize=1004168192 -XX:+PrintGC-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers-XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation

Heap

 garbage-first heap   total 61440K, used 2048K[0x00000000c4200000, 0x00000000c43001e0, 0x0000000100000000)

 region size 1024K, 3 young (3072K), 0 survivors (0K)

 Metaspace      used 3953K, capacity 4716K, committed 4864K, reserved 1056768K

  class space   used 455K, capacity 468K, committed 512K, reserved 1048576K

 

G1 GC的日志输出和其他GC有所不同，它更加简洁。这里没有进入一个评估阶段，评估阶段就是确认有多少对象需要被回收，通常是针对年轻代或者年轻代+老年代。从上面的输出，我们可以看出一共有60M（61440/1024）的堆内存空间，其中使用了2M，Region是1M/个，有3个年轻代Region。元数据空间的使用情况也做了相应介绍，使用了3.8M，可用4.6M。

我们使用VM参数-XX:+PrintGCDetails-verbose:gc -Xloggc:gc.log -XX:+UseG1GC -XX:+PrintGCApplicationStoppedTime-XX:+PrintGCApplicationConcurrentTime运行应用程序，日志输出如清单3-13所示。

代码清单3-13 -XX:+ PrintGCApplicationStoppedTime运行输出

Java HotSpot(TM) 64-BitServer VM (25.101-b13) for windows-amd64 JRE (1.8.0_101-b13), built on Jun 222016 01:21:29 by "Java_re" with MS VC++ 10.0 (VS2010)

Memory: 4k page, physical3922532k(1449048k free), swap 7843228k(4974672k free)

CommandLine flags:-XX:InitialHeapSize=62760512 -XX:MaxHeapSize=1004168192 -XX:+PrintGC-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers-XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation

1.159: Application time:0.8766273 seconds

1.160: Total time for which applicationthreads were stopped: 0.0001140 seconds, Stopping threads took: 0.0000351seconds

4.159: Application time:2.9998299 seconds

4.160: Total time for which applicationthreads were stopped: 0.0002126 seconds, Stopping threads took: 0.0000724seconds

4.418: Application time:0.2587571 seconds

4.419: Total time for which applicationthreads were stopped: 0.0001491 seconds, Stopping threads took: 0.0000381seconds

5.462: Application time:1.0433280 seconds

5.462: Total time for which applicationthreads were stopped: 0.0000664 seconds, Stopping threads took: 0.0000360seconds

Heap

 garbage-first heap   total 61440K, used 2048K[0x00000000c4200000, 0x00000000c43001e0, 0x0000000100000000)

 region size 1024K, 3 young (3072K), 0 survivors (0K)

 Metaspace      used 3953K, capacity 4716K, committed 4864K, reserved 1056768K

 class space    used 455K, capacity468K, committed 512K, reserved 1048576K

5.463:Application time: 0.0007787 seconds

 

我们来看一下这两行输出，

1.159: Application time: 0.8766273 seconds

1.160: Total time for which application threads were stopped:0.0001140 seconds, Stopping threads took: 0.0000351 seconds

这里表示应用程序执行了0.87秒，GC线程造成的停顿时间大约为0.0001140秒。由于程序运行过程中进行了多次回收，所以你看到这里有多次时间打印。如果发现某个时间很长，那你要关注代码和设计了，哪里可能出现了实现或者设计弱点（不一定是缺陷），要根据实际情况进行优化，也许是代码逻辑复杂造成的，也可能是代码编写时频繁创建对象。

这里应用程序会被暂停是由于G1GC针对年轻代（有时候是年轻代+老年代）有一个评估阶段，这个评估阶段实质上是在做数据拷贝，既然是拷贝，一定需要一个基准点[1]，那么为了维护这个基准点，我们需要设置对应的应用程序暂停时间，这个时间段内就称为保护点（safepoint），这和Oracle的checkPoint很像。

欢迎关注麦克叔叔每晚十点说，感兴趣的朋友可以关注公众号，让我们一起学习与交流。

---

[1] 即大家都认为这个时间点的数据是完好无缺的，永远不要认为软件应该无缝隙保证数据完整性，这个和CAP原理相违背，一定是通过其他方式来确保数据的原子性、完整性。