一. JVM的GC日志主要參數(shù)包括如下：

-XX:+PrintGC 輸出GC日志
-XX:+PrintGCDetails 輸出GC的詳細(xì)日志
-XX:+PrintGCTimeStamps 輸出GC的時(shí)間戳(以基準(zhǔn)時(shí)間的形式)
-XX:+PrintGCDateStamps 輸出GC的時(shí)間戳（以日期的形式，如 2018-09-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在進(jìn)行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的輸出路徑

eg.
windows下面配置VM參數(shù)如下：

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

Linux配置VM參數(shù)如下：

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

使用idea配置VM參數(shù)步驟：

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)。他們的區(qū)別很大，在第一行最后我們可以看見他的時(shí)間是real=0.00 secs，而第二行的FullGC的時(shí)間是 real=0.01 secs。第二行耗費(fèi)的時(shí)間明顯比第一個(gè)多很多，也就是我們調(diào)優(yōu)的重點(diǎn)，減少FullGC的次數(shù)，以為FullGC會(huì)暫停程序比較長(zhǎng)的時(shí)間，如果FullGC的次數(shù)比較多。程序就會(huì)經(jīng)常性的假死。
?第一行：PSYoungGen、ParOldGen、PSPermGen屬于Parallel收集器。其中PSYoungGen表示gc回收前后年輕代的內(nèi)存變化；ParOldGen表示gc回收前后老年代的內(nèi)存變化；PSPermGen表示gc回收前后永久區(qū)的內(nèi)存變化；如果是Serial收集器中的新生代名為“Default New Generation”，則會(huì)顯示DefNew; 緊跟后面的 9377K->1573K(37888K) 中的 9377K代表young generation 回收前大小，1573K代表回收后大小，括號(hào)中的37888K 代表young generation總大小(包含2個(gè)survivor)；9377K->1581K(123904K)則代表整個(gè)Heap(young+old)的變化與總量；Times: user=0.00 sys=0.00, real=0.00 secs： user代表GC 需要的各個(gè)CPU總時(shí)間(各個(gè)CPU時(shí)間相加)，sys代表回收器自身的行為所占用CPU時(shí)間，real則代表本次GC所耗費(fèi)的真正耗時(shí)(在多核CPU中并行回收，它通常小于user) 。
?第二行：Full GC即代表 Major GC, 0.491（JVM 啟動(dòng)后經(jīng)過的時(shí)間，單位為秒）: [Full GC (System.gc()（導(dǎo)致 GC 的原因，這里是手動(dòng)調(diào)用System.gc()導(dǎo)致的）) [PSYoungGen（Parallel GC 年輕代內(nèi)存區(qū)域名稱，并行，多線程，標(biāo)記-復(fù)制 Mark-Copy，STW）: PSYoungGen（GC前年輕代的使用量）->0K（GC 前后輕代的使用量）(37888K（年輕代總大小)] [ParOldGen（Parallel GC 老年代內(nèi)存區(qū)域名稱，并行，多線程，標(biāo)記-清除-整理 Mark-Sweep-Compact，STW）: 8K（GC 前老年代的使用量）->1447K（GC 后老年代的使用量）(86016K（老年代代總大?。?] 1581K（GC 前整個(gè)堆的使用量）->1447K（GC 后整個(gè)堆的使用量）(123904K（整個(gè)堆的總大小）),[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 線程數(shù)。請(qǐng)注意，總有一定比例的處理過程是不能并行進(jìn)行的; 2. 年輕代的使用量從 524800K 變?yōu)?0K，一般 Full GC 的結(jié)果都是這樣; 3. 老年代沒有減，反而增加，是因?yàn)槟贻p代中沒有被清除的對(duì)象被提升到了老年代

三. 案例

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