JVM探祕：GC日誌收集與分析

阿新 • • 發佈：2020-01-05

本系列筆記主要基於《深入理解Java虛擬機器：JVM高階特性與最佳實踐第2版》，是這本書的讀書筆記。

收集GC日誌

不同的垃圾收集器，輸出的日誌格式各不相同，但也有一些相同的特徵。熟悉各個常用垃圾收集器的GC日誌，是進行JVM調優的必備一步。
解析GC日誌，首先需要收集日誌，常用的有以下JVM引數用來列印輸出日誌資訊：

引數	說明
-XX:+PrintGCDetails	列印GC詳細資訊
-XX:+PrintGCTimeStamps	輸出GC的時間戳（以基準時間的形式）
-XX:+PrintGCDateStamps	輸出GC的時間戳（以日期的形式）
-XX:+PrintHeapAtGC	在進行GC的前後打印出堆的資訊
-XX:+PrintTenuringDistribution	在進行GC時列印survivor中的物件年齡分佈資訊
-Xloggc:$CATALINA_HOME/logs/gc.log	指定輸出路徑收集日誌到日誌檔案

例如，我使用如下引數啟動：

-Xms28m
-Xmx28m
-XX:PermSize=14M
-XX:MaxNewSize=14m
-XX:MaxPermSize=14m
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-Xloggc:E:/logs/gc.log

如果要指定垃圾收集器，還需要新增對應的JVM引數，例如-XX:+UseG1GC

、-XX:+UseConcMarkSweepGC等

-XX:+UseParallelGC日誌解析

JDK1.8的預設收集器為Parallel收集器+Serial Old收集器組合（-XX:+UseParallelGC），日誌如下：

Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8303556k(2789672k free), swap 16215992k(6967912k free)
CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
2018-05-08T19:23:01.815+0800: 0.574: [GC (Allocation Failure) [PSYoungGen: 11264K->1531K(12800K)] 11264K->2283K(27136K), 0.0039021 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:01.906+0800: 0.664: [GC (System.gc()) [PSYoungGen: 6560K->1516K(12800K)] 7311K->2625K(27136K), 0.0030390 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:01.908+0800: 0.667: [Full GC (System.gc()) [PSYoungGen: 1516K->0K(12800K)] [ParOldGen: 1109K->2005K(14336K)] 2625K->2005K(27136K), [Metaspace: 5955K->5955K(1056768K)], 0.0102082 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-08T19:23:01.954+0800: 0.714: [GC (Allocation Failure) [PSYoungGen: 11263K->64K(12800K)] 13269K->2069K(27136K), 0.0005071 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:01.988+0800: 0.748: [GC (Allocation Failure) [PSYoungGen: 11327K->64K(12800K)] 13333K->2069K(27136K), 0.0003509 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:02.019+0800: 0.779: [GC (Allocation Failure) [PSYoungGen: 11328K->128K(12800K)] 13333K->2133K(27136K), 0.0003730 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:02.049+0800: 0.809: [GC (Allocation Failure) [PSYoungGen: 11391K->64K(9728K)] 13397K->2077K(24064K), 0.0003454 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:24:28.365+0800: 87.124: [GC (System.gc()) [PSYoungGen: 306K->32K(11264K)] 2320K->2045K(25600K), 0.0005228 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:24:28.365+0800: 87.124: [Full GC (System.gc()) [PSYoungGen: 32K->0K(11264K)] [ParOldGen: 2013K->1706K(14336K)] 2045K->1706K(25600K), [Metaspace: 6027K->6021K(1056768K)], 0.0135435 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 11264K, used 324K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 3% used [0x00000000ff200000,0x00000000ff2513a0,0x00000000ffa00000)
  from space 3072K, 0% used [0x00000000ffa00000,0x00000000ffa00000,0x00000000ffd00000)
  to   space 3072K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x0000000100000000)
 ParOldGen       total 14336K, used 1706K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  object space 14336K, 11% used [0x00000000fe400000,0x00000000fe5aa8f8,0x00000000ff200000)
 Metaspace       used 6032K, capacity 6242K, committed 6400K, reserved 1056768K
  class space    used 688K, capacity 756K, committed 768K, reserved 1048576K

第三行把當前使用的JVM引數列印了出來，初始化了堆大小，設定了最大堆，最後打印出來GC引數-XX:+UseParallelGC。

第四行開始是垃圾收集記錄，首先是垃圾收集的時間。然後是發生GC的原因，GC (Allocation Failure)物件分配失敗，GC表示新生代Young區的GC，Full GC則包含老年代。[PSYoungGen: 11264K->1531K(12800K)]表示Young區回收前大小是11264K，回收後是1531K，總大小是12800K。緊接著中括號外，11264K->2283K(27136K)表示回收前整個堆大小是11264K，回收後堆大小2283K，堆總大小27136K。0.0039021 secs是垃圾回收用的時間。可以看出，新生代由11M變為了約1.5M，而整個堆由11M變為了約2.2M，也就是這次GC後，老年代約為0.7M。

後面的格式都是類似的，再看第六行Full GC的日誌。

第六行，首先也是GC發生的時間。然後是發生GC的原因，Full GC (System.gc())由於程式碼System.gc()發起了Full GC。[PSYoungGen: 1516K->0K(12800K)]表示回收前新生代是1516K，回收後0K，新生代總大小是12800K。[ParOldGen: 1109K->2005K(14336K)]表示回收前老年代是1109K，回收後2005K，老年代總大小14336K。緊接著中括號外，2625K->2005K(27136K)回收前堆大小2625K，回收後2005K，堆總大小27136K。[Metaspace: 5955K->5955K(1056768K)]回收前元空間大小5955K，回收後5955K，總大小1056768K。這次GC用時0.0102082 secs。

日誌的最後打印出了堆的資訊，新生代總大小11264K，已使用324K，新生代中的eden區大小8192K，已用3%，兩個survivor區都是3072K。老年代總大小14336K，已使用1706K。元空間已使用6032K。

-XX:+UseSerialGC日誌解析

Serial收集器+Serial Old收集器組合（-XX:+UseSerialGC）的日誌如下：

Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8303556k(2575660k free), swap 16215992k(7063788k free)
CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseSerialGC 
2018-05-08T19:31:03.644+0800: 0.676: [GC (Allocation Failure) 2018-08-08T19:31:03.644+0800: 0.676: [DefNew: 11520K->1408K(12928K), 0.0049897 secs] 11520K->2234K(27264K), 0.0051851 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:31:03.744+0800: 0.775: [Full GC (System.gc()) 2018-08-08T19:31:03.744+0800: 0.775: [Tenured: 826K->2569K(14336K), 0.0292213 secs] 7147K->2569K(27264K), [Metaspace: 5939K->5939K(1056768K)], 0.0292829 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 
2018-05-08T19:31:03.811+0800: 0.843: [GC (Allocation Failure) 2018-08-08T19:31:03.811+0800: 0.843: [DefNew: 11519K->4K(12928K), 0.0009580 secs] 14088K->2573K(27264K), 0.0010026 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:31:03.878+0800: 0.909: [GC (Allocation Failure) 2018-08-08T19:31:03.878+0800: 0.909: [DefNew: 11523K->3K(12928K), 0.0003602 secs] 14092K->2572K(27264K), 0.0004109 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:31:03.935+0800: 0.967: [GC (Allocation Failure) 2018-08-08T19:31:03.935+0800: 0.967: [DefNew: 11523K->3K(12928K), 0.0004648 secs] 14092K->2572K(27264K), 0.0005109 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2018-05-08T19:32:31.148+0800: 88.179: [Full GC (System.gc()) 2018-08-08T19:32:31.148+0800: 88.179: [Tenured: 2569K->2540K(14336K), 0.0078915 secs] 13176K->2540K(27264K), [Metaspace: 6017K->6017K(1056768K)], 0.0079582 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
Heap
 def new generation   total 12928K, used 458K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  eden space 11520K,   3% used [0x00000000fe400000, 0x00000000fe472838, 0x00000000fef40000)
  from space 1408K,   0% used [0x00000000fef40000, 0x00000000fef40000, 0x00000000ff0a0000)
  to   space 1408K,   0% used [0x00000000ff0a0000, 0x00000000ff0a0000, 0x00000000ff200000)
 tenured generation   total 14336K, used 2540K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
   the space 14336K,  17% used [0x00000000ff200000, 0x00000000ff47b1e8, 0x00000000ff47b200, 0x0000000100000000)
 Metaspace       used 6029K, capacity 6252K, committed 6400K, reserved 1056768K
  class space    used 691K, capacity 761K, committed 768K, reserved 1048576K

Serial收集器已經很少使用，GC日誌的格式也是大同小異，[GC開頭的是新生代GC，DefNew表示新生代。會列印GC發生時間，GC原因，新生代回收前大小、回收後大小、以及新生代總大小。列印堆的回收前大小、回收後大小、及總大小，列印GC耗時。

[Full GC開頭的是老年代GC，Tenured表示老年代。會列印GC發生時間，GC原因，老年代回收前大小、回收後大小、以及老年代總大小。列印堆的回收前大小、回收後大小、及堆的總大小。列印元空間的回收前、回收後、及總大小，列印GC耗時。

最後打印出整個堆的使用情況。

-XX:+UseParNewGC日誌解析

ParNew收集器+Serilal Old組合（-XX:+UseParNewGC）的日誌如下：

Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8303556k(2874368k free), swap 16215992k(9448728k free)
CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2018-05-09T20:41:34.699+0800: 4.632: [GC (Allocation Failure) 2018-08-09T08:41:34.711+0800: 4.633: [ParNew: 11520K->1408K(12928K), 0.0149096 secs] 11520K->2265K(27264K), 0.0271137 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
2018-05-09T20:41:34.886+0800: 4.808: [Full GC (System.gc()) 2018-08-09T08:41:34.886+0800: 4.808: [Tenured: 857K->2567K(14336K), 0.0091055 secs] 6992K->2567K(27264K), [Metaspace: 5940K->5940K(1056768K)], 0.0091703 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2018-05-09T20:41:34.964+0800: 4.887: [GC (Allocation Failure) 2018-08-09T08:41:34.964+0800: 4.887: [ParNew: 11519K->1214K(12928K), 0.0132311 secs] 14086K->3781K(27264K), 0.0132796 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-09T20:41:35.024+0800: 4.946: [GC (Allocation Failure) 2018-08-09T08:41:35.024+0800: 4.946: [ParNew: 12734K->151K(12928K), 0.0004635 secs] 15301K->2719K(27264K), 0.0005408 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:41:35.057+0800: 4.979: [GC (Allocation Failure) 2018-08-09T08:41:35.057+0800: 4.979: [ParNew: 11671K->38K(12928K), 0.0003371 secs] 14239K->2605K(27264K), 0.0003801 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:42:59.030+0800: 88.953: [Full GC (System.gc()) 2018-08-09T08:42:59.030+0800: 88.953: [Tenured: 2567K->2536K(14336K), 0.0086218 secs] 13341K->2536K(27264K), [Metaspace: 6012K->6012K(1056768K)], 0.0086850 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 12928K, used 227K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  eden space 11520K,   1% used [0x00000000fe400000, 0x00000000fe438f88, 0x00000000fef40000)
  from space 1408K,   0% used [0x00000000fef40000, 0x00000000fef40000, 0x00000000ff0a0000)
  to   space 1408K,   0% used [0x00000000ff0a0000, 0x00000000ff0a0000, 0x00000000ff200000)
 tenured generation   total 14336K, used 2536K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
   the space 14336K,  17% used [0x00000000ff200000, 0x00000000ff47a1e8, 0x00000000ff47a200, 0x0000000100000000)
 Metaspace       used 6023K, capacity 6252K, committed 6400K, reserved 1056768K
  class space    used 691K, capacity 761K, committed 768K, reserved 1048576K

以上是ParNew收集器+Serilal Old組合的GC日誌，格式大同小異。

-XX:+UseParallelOldGC日誌解析

Parallel收集器+Parallel Old收集器組合（-XX:+UseParallelOldGC）的日誌如下：

Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8303556k(2759076k free), swap 16215992k(7616208k free)
CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelOldGC 
2018-05-09T20:44:49.341+0800: 0.618: [GC (Allocation Failure) [PSYoungGen: 11264K->1531K(12800K)] 11264K->2274K(27136K), 0.0043755 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] 
2018-05-09T20:44:49.478+0800: 0.754: [GC (System.gc()) [PSYoungGen: 6544K->1531K(12800K)] 7286K->2626K(27136K), 0.0064927 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-09T20:44:49.484+0800: 0.761: [Full GC (System.gc()) [PSYoungGen: 1531K->0K(12800K)] [ParOldGen: 1094K->1917K(14336K)] 2626K->1917K(27136K), [Metaspace: 5968K->5968K(1056768K)], 0.0125897 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2018-05-09T20:44:49.624+0800: 0.901: [GC (Allocation Failure) [PSYoungGen: 11263K->64K(12800K)] 13181K->1981K(27136K), 0.0227273 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
2018-05-09T20:44:49.690+0800: 0.967: [GC (Allocation Failure) [PSYoungGen: 11327K->64K(12800K)] 13245K->1981K(27136K), 0.0004702 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:44:49.729+0800: 1.007: [GC (Allocation Failure) [PSYoungGen: 11328K->64K(12800K)] 13245K->1981K(27136K), 0.0080092 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-09T20:44:49.774+0800: 1.052: [GC (Allocation Failure) [PSYoungGen: 11327K->64K(9728K)] 13245K->1989K(24064K), 0.0019594 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:46:15.771+0800: 87.048: [GC (System.gc()) [PSYoungGen: 302K->64K(11264K)] 2227K->1989K(25600K), 0.0004195 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:46:15.771+0800: 87.048: [Full GC (System.gc()) [PSYoungGen: 64K->0K(11264K)] [ParOldGen: 1925K->1704K(14336K)] 1989K->1704K(25600K), [Metaspace: 6039K->6033K(1056768K)], 0.0126567 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 11264K, used 324K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 3% used [0x00000000ff200000,0x00000000ff2513a0,0x00000000ffa00000)
  from space 3072K, 0% used [0x00000000ffa00000,0x00000000ffa00000,0x00000000ffd00000)
  to   space 3072K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x0000000100000000)
 ParOldGen       total 14336K, used 1704K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  object space 14336K, 11% used [0x00000000fe400000,0x00000000fe5aa360,0x00000000ff200000)
 Metaspace       used 6044K, capacity 6242K, committed 6400K, reserved 1056768K
  class space    used 688K, capacity 756K, committed 768K, reserved 1048576K

以上是Parallel收集器+Parallel Old收集器組合的GC日誌，格式跟JDK1.8預設的-XX:+UseParallelGC大同小異。

-XX:+UseConcMarkSweepGC日誌解析

-XX:+UseConcMarkSweepGC會指定CMS收集器+ParNew收集器+Serial Old收集器組合，優先使用ParNew收集器+CMS收集器的組合，當出現ConcurrentMode Fail或者Promotion Failed時，則採用ParNew收集器+Serial Old收集器的組合。日誌如下：

Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8303556k(2846816k free), swap 16215992k(7664596k free)
CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2018-05-09T20:53:14.086+0800: 0.590: [GC (Allocation Failure) 2018-08-09T11:53:14.086+0800: 0.590: [ParNew: 11520K->1407K(12928K), 0.0034803 secs] 11520K->2254K(27264K), 0.0039082 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:53:14.247+0800: 0.751: [Full GC (System.gc()) 2018-08-09T11:53:14.247+0800: 0.751: [CMS: 846K->1930K(14336K), 0.0103698 secs] 7165K->1930K(27264K), [Metaspace: 5963K->5963K(1056768K)], 0.0104529 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2018-05-09T20:53:14.292+0800: 0.795: [GC (Allocation Failure) 2018-08-09T11:53:14.292+0800: 0.795: [ParNew: 11519K->1199K(12928K), 0.0085679 secs] 13450K->3129K(27264K), 0.0086244 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-09T20:53:14.333+0800: 0.836: [GC (Allocation Failure) 2018-08-09T11:53:14.333+0800: 0.836: [ParNew: 12719K->300K(12928K), 0.0002620 secs] 14649K->2230K(27264K), 0.0003041 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:53:14.364+0800: 0.867: [GC (Allocation Failure) 2018-08-09T11:53:14.364+0800: 0.867: [ParNew: 11820K->75K(12928K), 0.0002787 secs] 13750K->2005K(27264K), 0.0003223 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
# 併發標記週期開始，根區域掃描
2018-05-09T20:59:47.982+0800: 9.634: [GC concurrent-root-region-scan-start]
2018-05-09T20:59:47.982+0800: 9.652: [GC concurrent-root-region-scan-end, 0.0184308 secs]
# 併發標記
2018-05-09T20:59:47.982+0800: 9.652: [GC concurrent-mark-start]
2018-05-09T20:59:47.982+0800: 9.693: [GC concurrent-mark-end, 0.0406187 secs]
# 重新標記
2018-05-09T20:59:47.982+0800: 9.695: [GC remark 9.695: [Finalize Marking, 0.0005100 secs] 9.695: [GC ref-proc, 0.0003461 secs] 9.696: [Unloading, 0.0069466 secs], 0.0082011 secs]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
# 獨佔清理
2018-05-09T20:59:47.982+0800: 9.703: [GC cleanup 25M->21M(1024M), 0.0027119 secs]
 [Times: user=0.00 sys=0.01, real=0.00 secs] 
# 併發清理
2018-05-09T20:59:47.982+0800: 9.706: [GC concurrent-cleanup-start]
2018-05-09T20:59:47.982+0800: 9.706: [GC concurrent-cleanup-end, 0.0000167 secs]
2018-05-09T20:54:39.299+0800: 85.803: [Full GC (System.gc()) 2018-08-09T11:54:39.299+0800: 85.803: [CMS: 1930K->1832K(14336K), 0.0089015 secs] 12748K->1832K(27264K), [Metaspace: 6035K->6035K(1056768K)], 0.0089724 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

Heap
 par new generation   total 12928K, used 227K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  eden space 11520K,   1% used [0x00000000fe400000, 0x00000000fe438cd8, 0x00000000fef40000)
  from space 1408K,   0% used [0x00000000fef40000, 0x00000000fef40000, 0x00000000ff0a0000)
  to   space 1408K,   0% used [0x00000000ff0a0000, 0x00000000ff0a0000, 0x00000000ff200000)
 concurrent mark-sweep generation total 14336K, used 1832K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 6045K, capacity 6252K, committed 6400K, reserved 1056768K
  class space    used 691K, capacity 761K, committed 768K, reserved 1048576K

第三行把當前使用的JVM引數打印出來，其中，-XX:MaxTenuringThreshold=6是指物件從新生代晉升到老年代需要物件年齡達到6歲，即經過6次GC。

第四行是新生代Young區的GC，首先是GC發生的時間。然後是GC發生的原因GC (Allocation Failure)，物件分配失敗。[ParNew: 11520K->1407K(12928K), 0.0034803 secs]表示新生代回收前是11520K，回收後是1407K，新生代總大小12928K，回收耗時0.0034803 secs。11520K->2254K(27264K), 0.0039082 secs表示回收前堆大小11520K，回收後堆大小2254K，堆的總大小27264K。

第五行是老年代Old區的GC，首先是GC發生的時間。然後是GC發生的原因System.gc()，由於程式碼呼叫。[CMS: 846K->1930K(14336K), 0.0103698 secs]表示回收前老年代是846K，回收後1930K，老年代總大小14336K，回收耗時0.0103698 secs。7165K->1930K(27264K)表示回收前堆大小7165K，回收後堆大小1930K，堆的總大小27264K。

後面有一次併發標記週期，設定引數-XX:InitiatingHeapOccupancyPercent的值，可以指定堆佔有率達到百分之多少時，觸發併發標記，預設值是45%。

最後打印出了堆的整體使用情況，分為新生代、老年代、元空間。

-XX:+UseG1GC日誌解析

G1是JDK1.9中的預設收集器，指定G1收集器併發、並行執行記憶體回收（-XX:+UseG1GC），它的格式差異較大，日誌如下：

Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8303556k(2436164k free), swap 16215992k(7422076k free)
CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation 
# 新生代GC，young區，暫停0.0022375秒
2018-05-09T20:59:47.639+0800: 0.484: [GC pause (G1 Evacuation Pause) (young), 0.0022375 secs]
   # 並行時間1.7ms，4個GC執行緒
   [Parallel Time: 1.7 ms, GC Workers: 4]
      # 開始時刻，相對開始時間點，4個執行緒的最小值、平均值、最大值
      [GC Worker Start (ms): Min: 484.4, Avg: 484.4, Max: 484.5, Diff: 0.0]
      # 根節點掃描耗時
      [Ext Root Scanning (ms): Min: 0.4, Avg: 0.7, Max: 1.6, Diff: 1.2, Sum: 2.7]
      # 更新記憶集（RS, Remembered Set）耗時G1中每塊區域都有一個RS與之對應，RS記錄了該區域被其他區域引用的物件。回收時，就把RS作為根集的一部分，從而加快回收。
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         # Processed Buffers就是記錄引用變化的快取空間
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      # 掃描RS耗時
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      # 根掃描耗時
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      # 物件拷貝（疏散回收的區域）
      [Object Copy (ms): Min: 0.0, Avg: 0.8, Max: 1.1, Diff: 1.1, Sum: 3.3]
      # 執行緒在終止階段的耗時，執行緒在終止前，會檢查其他執行緒的佇列，看是否有未清理完的Reference。如有則幫助其他執行緒清理，之後再嘗試終止
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
         # 嘗試終止次數
         [Termination Attempts: Min: 1, Avg: 1.8, Max: 2, Diff: 1, Sum: 7]
      # GC執行緒花在其他任務中的耗時
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      # GC執行緒耗時
      [GC Worker Total (ms): Min: 1.6, Avg: 1.6, Max: 1.6, Diff: 0.0, Sum: 6.5]
      # 完成時刻
      [GC Worker End (ms): Min: 486.1, Avg: 486.1, Max: 486.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   # 清空CardTable耗時，RS是依賴CardTable記錄區域存活物件的
   [Clear CT: 0.0 ms]
   # 其他任務耗時
   [Other: 0.5 ms]
      # 選取將要被回收的區域的集合耗時
      [Choose CSet: 0.0 ms]
      # 弱引用、軟引用的處理耗時
      [Ref Proc: 0.4 ms]
      # 弱引用、軟引用的入隊耗時
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      # 釋放被回收區域的耗時（包含他們的RS）
      [Free CSet: 0.0 ms]
   # Eden區、Survivor區、堆的回收前大小、回收後大小、以及總大小
   [Eden: 5120.0K(5120.0K)->0.0B(11.0M) Survivors: 0.0B->1024.0K Heap: 5120.0K(28.0M)->1631.5K(28.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
# 併發標記週期開始，根區域掃描
2018-05-09T20:59:47.982+0800: 9.634: [GC concurrent-root-region-scan-start]
2018-05-09T20:59:47.982+0800: 9.652: [GC concurrent-root-region-scan-end, 0.0184308 secs]
# 併發標記
2018-05-09T20:59:47.982+0800: 9.652: [GC concurrent-mark-start]
2018-05-09T20:59:47.982+0800: 9.693: [GC concurrent-mark-end, 0.0406187 secs]
# 重新標記
2018-05-09T20:59:47.982+0800: 9.695: [GC remark 9.695: [Finalize Marking, 0.0005100 secs] 9.695: [GC ref-proc, 0.0003461 secs] 9.696: [Unloading, 0.0069466 secs], 0.0082011 secs]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
# 獨佔清理
2018-05-09T20:59:47.982+0800: 9.703: [GC cleanup 25M->21M(1024M), 0.0027119 secs]
 [Times: user=0.00 sys=0.01, real=0.00 secs] 
# 併發清理
2018-05-09T20:59:47.982+0800: 9.706: [GC concurrent-cleanup-start]
2018-05-09T20:59:47.982+0800: 9.706: [GC concurrent-cleanup-end, 0.0000167 secs]
# 下一輪迴收，FullGC，堆的回收前、回收後、以及總大小。Eden、Survivor、元空間的大小。
2018-05-09T20:59:47.982+0800: 0.828: [Full GC (System.gc())  12M->2223K(28M), 0.0128065 secs]
   [Eden: 11.0M(11.0M)->0.0B(12.0M) Survivors: 1024.0K->0.0B Heap: 12.2M(28.0M)->2223.0K(28.0M)], [Metaspace: 5951K->5951K(1056768K)]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
# 新生代GC
2018-05-09T20:59:48.040+0800: 0.886: [GC pause (G1 Evacuation Pause) (young), 0.0005693 secs]
   [Parallel Time: 0.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 886.1, Avg: 886.1, Max: 886.1, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [Processed Buffers: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 0.3, Avg: 0.3, Max: 0.4, Diff: 0.0, Sum: 1.4]
      [GC Worker End (ms): Min: 886.5, Avg: 886.5, Max: 886.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 12.0M(12.0M)->0.0B(12.0M) Survivors: 0.0B->2048.0K Heap: 14.2M(28.0M)->3460.3K(28.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:59:48.103+0800: 0.949: [GC pause (G1 Evacuation Pause) (young), 0.0004664 secs]
   [Parallel Time: 0.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 949.2, Avg: 949.3, Max: 949.5, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 0.6]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 1.0, Max: 2, Diff: 2, Sum: 4]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.8]
      [GC Worker End (ms): Min: 949.5, Avg: 949.5, Max: 949.5, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 12.0M(12.0M)->0.0B(13.0M) Survivors: 2048.0K->1024.0K Heap: 15.4M(28.0M)->2383.6K(28.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:59:48.146+0800: 0.992: [GC pause (G1 Evacuation Pause) (young), 0.0004067 secs]
   [Parallel Time: 0.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 991.9, Avg: 991.9, Max: 991.9, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 1, Avg: 1.3, Max: 2, Diff: 1, Sum: 5]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Total (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.9]
      [GC Worker End (ms): Min: 992.2, Avg: 992.2, Max: 992.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.0 ms]
   [Other: 0.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 13.0M(13.0M)->0.0B(13.0M) Survivors: 1024.0K->1024.0K Heap: 15.3M(28.0M)->2277.1K(28.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T21:01:18.300+0800: 91.146: [Full GC (System.gc())  9971K->1815K(28M), 0.0099218 secs]
   [Eden: 8192.0K(13.0M)->0.0B(14.0M) Survivors: 1024.0K->0.0B Heap: 9971.7K(28.0M)->1815.8K(28.0M)], [Metaspace: 6026K->6026K(1056768K)]
 [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 garbage-first heap   total 28672K, used 1815K [0x00000000fe400000, 0x00000000fe5000e0, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 6038K, capacity 6252K, committed 6400K, reserved 1056768K
  class space    used 691K, capacity 761K, committed 768K, reserved 1048576K

G1日誌分析詳見上面程式碼中的註釋，G1的垃圾收集比之前的收集器稍微複雜一些。

JVM探祕：GC日誌收集與分析

收集GC日誌

-XX:+UseParallelGC日誌解析

-XX:+UseSerialGC日誌解析

-XX:+UseParNewGC日誌解析

-XX:+UseParallelOldGC日誌解析

-XX:+UseConcMarkSweepGC日誌解析

-XX:+UseG1GC日誌解析

JVM探祕：GC日誌收集與分析

支付寶客戶端架構分析：自動化日誌收集及分析

JVM系列第14講：JVM引數之GC日誌配置

JVM（六）：GC日誌閱讀

JVM（五）：GC垃圾收集器分類

JVM系列：GC引數分析和調優

工資管理系統的需求概述的資料收集與分析：

用Kibana和logstash快速搭建實時日誌查詢、收集與分析系統

JVM gc引數設定與分析

JVM學習筆記3：GC日誌和常用命令工具

JVM探祕：垃圾收集器

用研關鍵三步驟：問題、方法與分析

2017-2018-2 20155233『網絡對抗技術』Exp6：信息收集與漏洞掃描

研究生導師布置的作業！利用Python和API收集與分析網絡數據！

ELK日誌收集與監控

技術分享：OpenStack DVR部署與分析

jvm系列之-gc日誌檢視

法律可行性與經濟可行性的資料收集與分析

JVM讀書筆記之垃圾收集與記憶體分配

大資料篇：Elasticsearch分散式搜尋與分析引擎

JVM探祕：GC日誌收集與分析

收集GC日誌

-XX:+UseParallelGC日誌解析

-XX:+UseSerialGC日誌解析

-XX:+UseParNewGC日誌解析

-XX:+UseParallelOldGC日誌解析

-XX:+UseConcMarkSweepGC日誌解析

-XX:+UseG1GC日誌解析

相關推薦