一. JVM的GC日志主要参数包括如下：

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2018-09-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

eg.
windows下面配置VM参数如下：

-XX:+PrintGCDetails -Xloggc:E:\workspace\workspace_java_tool\workspace_sunny_project\java-honey-collection\logs\gc.log -XX:+PrintGCTimeStamps  

Linux配置VM参数如下：

-XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:./logs/gc.log  

使用idea配置VM参数步骤：

image.png

image.png

image.png

Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for windows-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8240184k(2720372k free), swap 18201656k(8980516k free)
CommandLine flags: -XX:InitialHeapSize=131842944 -XX:MaxHeapSize=2109487104 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
0.490: [GC (System.gc()) [PSYoungGen: 9377K->1573K(37888K)] 9377K->1581K(123904K), 0.0016584 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.491: [Full GC (System.gc()) [PSYoungGen: 1573K->0K(37888K)] [ParOldGen: 8K->1447K(86016K)] 1581K->1447K(123904K), [Metaspace: 3530K->3530K(1056768K)], 0.0068323 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 37888K, used 328K [0x00000000d6180000, 0x00000000d8b80000, 0x0000000100000000)
  eden space 32768K, 1% used [0x00000000d6180000,0x00000000d61d2030,0x00000000d8180000)
  from space 5120K, 0% used [0x00000000d8180000,0x00000000d8180000,0x00000000d8680000)
  to   space 5120K, 0% used [0x00000000d8680000,0x00000000d8680000,0x00000000d8b80000)
 ParOldGen       total 86016K, used 1447K [0x0000000082400000, 0x0000000087800000, 0x00000000d6180000)
  object space 86016K, 1% used [0x0000000082400000,0x0000000082569f40,0x0000000087800000)
 Metaspace       used 3538K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 385K, capacity 388K, committed 512K, reserved 1048576K

二. GC日志解析

0.490: [GC (System.gc()) [PSYoungGen: 9377K->1573K(37888K)] 9377K->1581K(123904K), 0.0016584 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.491: [Full GC (System.gc()) [PSYoungGen: 1573K->0K(37888K)] [ParOldGen: 8K->1447K(86016K)] 1581K->1447K(123904K), [Metaspace: 3530K->3530K(1056768K)], 0.0068323 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 

 他们分别显示了JVM GC的过程，清理出了多少空间。第一行GC使用的是‘普通GC’(MinorCollections)，第二行使用的是‘全GC’(MajorCollections)。他们的区别很大，在第一行最后我们可以看见他的时间是real=0.00 secs，而第二行的FullGC的时间是 real=0.01 secs。第二行耗费的时间明显比第一个多很多，也就是我们调优的重点，减少FullGC的次数，以为FullGC会暂停程序比较长的时间，如果FullGC的次数比较多。程序就会经常性的假死。
 第一行：PSYoungGen、ParOldGen、PSPermGen属于Parallel收集器。其中PSYoungGen表示gc回收前后年轻代的内存变化；ParOldGen表示gc回收前后老年代的内存变化；PSPermGen表示gc回收前后永久区的内存变化；如果是Serial收集器中的新生代名为“Default New Generation”，则会显示DefNew; 紧跟后面的 9377K->1573K(37888K) 中的 9377K代表young generation 回收前大小，1573K代表回收后大小，括号中的37888K 代表young generation总大小(包含2个survivor)；9377K->1581K(123904K)则代表整个Heap(young+old)的变化与总量；Times: user=0.00 sys=0.00, real=0.00 secs： user代表GC 需要的各个CPU总时间(各个CPU时间相加)，sys代表回收器自身的行为所占用CPU时间，real则代表本次GC所耗费的真正耗时(在多核CPU中并行回收，它通常小于user) 。
 第二行：Full GC即代表 Major GC, 0.491（JVM 启动后经过的时间，单位为秒）: [Full GC (System.gc()（导致 GC 的原因，这里是手动调用System.gc()导致的）) [PSYoungGen（Parallel GC 年轻代内存区域名称，并行，多线程，标记-复制 Mark-Copy，STW）: PSYoungGen（GC前年轻代的使用量）->0K（GC 前后轻代的使用量）(37888K（年轻代总大小)] [ParOldGen（Parallel GC 老年代内存区域名称，并行，多线程，标记-清除-整理 Mark-Sweep-Compact，STW）: 8K（GC 前老年代的使用量）->1447K（GC 后老年代的使用量）(86016K（老年代代总大小）)] 1581K（GC 前整个堆的使用量）->1447K（GC 后整个堆的使用量）(123904K（整个堆的总大小）),[Metaspace(Parallel Scavenge收集器配套的永久代): 3530K->3530K(1056768K)], 0.0068323 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

 注意：1. 在 Parallel GC 中，real 约等于 (user + sys) / GC 线程数。请注意，总有一定比例的处理过程是不能并行进行的; 2. 年轻代的使用量从 524800K 变为 0K，一般 Full GC 的结果都是这样; 3. 老年代没有减，反而增加，是因为年轻代中没有被清除的对象被提升到了老年代

三. 案例

In this post, we will review how garbage collector logs look like and what useful information one can obtain from them. For this purpose, we have turned on GC logging for a JVM running with -XX:+UseSerialGC by using the following startup parameters:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

This resulted in the output similar to following:

2015-05-26T14:45:37.987-0200: 151.126: [GC (Allocation Failure) 151.126: [DefNew: 629119K->69888K(629120K), 0.0584157 secs] 1619346K->1273247K(2027264K), 0.0585007 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
2015-05-26T14:45:59.690-0200: 172.829: [GC (Allocation Failure) 172.829: [DefNew: 629120K->629120K(629120K), 0.0000372 secs]172.829: [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs] 1832479K->755802K(2027264K), [Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs] [Times: user=0.18 sys=0.00, real=0.18 secs]

The above short snippet from the GC logs exposes a lot of information about what is going on inside the JVM. As a matter of fact, in this snippet there were two Garbage Collection events taking place, one of them cleaning Young generation and the other one taking care of entire heap. Lets look at the first one of these events, a minor GC, taking place in Young generation:

2015-05-26T14:45:37.987-0200¹:151.126²:[GC³(Allocation Failure⁴) 151.126: [DefNew⁵:629119K->69888K⁶(629120K)⁷, 0.0584157 secs]1619346K->1273247K⁸(2027264K)⁹,0.0585007 secs¹⁰][Times: user=0.06 sys=0.00, real=0.06 secs]¹¹

1. 2015-05-26T14:45:37.987-0200– Time when the GC event started.
2. 151.126 – Time when the GC event started, relative to the JVM startup time. Measured in seconds.
3. GC – Flag to distinguish between Minor & Full GC. This time it is indicating that this was a Minor GC.
4. Allocation Failure – Cause of the collection. In this case, the GC is triggered due to a data structure not fitting into any region in Young Generation.
5. DefNew – Name of the garbage collector used. This cryptic name stands for the single-threaded mark-copy stop-the-world garbage collector used to clean Young generation.
6. 629119K->69888K – Usage of Young generation before and after collection.
7. (629120K)– Total size of the Young generation.
8. 1619346K->1273247K– Total used heap before and after collection.
9. (2027264K) – Total available heap.
10. 0.0585007 secs– Duration of the GC event in seconds.
11. [Times: user=0.06 sys=0.00, real=0.06 secs]– Duration of the GC event, measured in different categories:
    • user – Total CPU time that was consumed by Garbage Collector threads during this collection
    • sys – Time spent in OS calls or waiting for system event
    • real – Clock time for which your application was stopped. As Serial Garbage Collectoralways uses just a single thread, real time is thus equal to the sum of user and system times.

From the above snippet we can understand exactly what was happening with memory consumption inside the JVM during the GC event. Before this collection heap usage totaled at 1,619,346K. Out of this amount, the Young generation consumed 629,119K. From this we can calculate the Old generation usage being equal to 990,227K.

A more important conclusion is hidden in the next batch of numbers, indicating that after the collection young generation usage decreased by 559,231K, but total heap usage decreased only by 346,099K. From this we can again derive that 213,132K of objects had been promoted from Young generation to Old.

This GC event can be illustrated with the following snapshots depicting memory usage right before the GC started and right after it finished:

Serial GC Young Gen Java

参考

Understanding Garbage Collection Logs