JVM GC 日誌詳解

時間  2019-11-07
標籤 jvm 日誌 詳解 欄目 Java 简体版
原文   原文鏈接

本文采用的JDK版本：html

java version "1.8.0_144"
Java(TM) SE Runtime Environment (build 1.8.0_144-b01)
Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode)
複製代碼

1、GC 日誌參數

設置JVM GC格式日誌的主要參數包括以下8個：java

-XX:+PrintGC 輸出簡要GC日誌 
-XX:+PrintGCDetails 輸出詳細GC日誌 
-Xloggc:gc.log  輸出GC日誌到文件
-XX:+PrintGCTimeStamps 輸出GC的時間戳（以JVM啓動到當期的總時長的時間戳形式） 
-XX:+PrintGCDateStamps 輸出GC的時間戳（以日期的形式，如 2013-05-04T21:53:59.234+0800） 
-XX:+PrintHeapAtGC 在進行GC的先後打印出堆的信息
-verbose:gc
-XX:+PrintReferenceGC 打印年輕代各個引用的數量以及時長
複製代碼

本文假設讀者已經熟悉JVM 內存結構。linux

1.1 -XX:+PrintGC與-verbose:gc

若是想開啓GC日誌的信息，能夠經過設置以下的參數任一參數：git

-XX:+PrintGC
-XX:+PrintGCDetails 
-Xloggc:gc.log 
複製代碼

若是隻設置-XX:+PrintGC那麼打印的日誌以下所示：github

[GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]
複製代碼

一、GC 表示是一次YGC（Young GC）bash

二、Allocation Failure 表示是失敗的類型數據結構

三、68896K->5080K 表示年輕代從68896K降爲5080K併發

四、256000K表示整個堆的大小性能

五、0.0041139 secs表示此次GC總計所用的時間學習

在JDK 8中，-verbose:gc是-XX:+PrintGC一個別稱，日誌格式等價與：-XX:+PrintGC，。

不過在JDK 9中 -XX:+PrintGC被標記爲deprecated。

-verbose:gc是一個標準的選項， -XX:+PrintGC是一個實驗的選項，建議使用-verbose:gc替代-XX:+PrintGC

參考：Difference between -XX:+PrintGC and -verbose:gc

1.2 -XX:+PrintGCDetails

[GC (Allocation Failure) [PSYoungGen: 53248K->2176K(59392K)] 58161K->7161K(256000K), 0.0039189 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]
複製代碼

一、GC 表示是一次YGC（Young GC）

二、Allocation Failure 表示是失敗的類型

三、PSYoungGen 表示年輕代大小

四、53248K->2176K 表示年輕代佔用從53248K降爲2176K

五、59392K表示年輕帶的大小

六、58161K->7161K 表示整個堆佔用從53248K降爲2176K

七、256000K表示整個堆的大小

八、 0.0039189 secs 表示此次GC總計所用的時間

九、[Times: user=0.02 sys=0.01, real=0.00 secs] 分別表示，用戶態佔用時長，內核用時，真實用時。

時間保留兩位小數，四捨五入。

1.3 -XX:+PrintGCTimeStamps

1.963: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]
複製代碼

若是加上-XX:+PrintGCTimeStamps那麼日誌僅僅比1.1介紹的最前面多了一個時間戳： 1.963， 表示從JVM啓動到打印GC時刻用了1.963秒。

1.4 -XX:+PrintGCDateStamps

2019-03-05T16:56:15.108+0800: [GC (Allocation Failure)  61805K->9849K(256000K), 0.0041139 secs]
複製代碼

若是加上-XX:+PrintGCDateStamps那麼日誌僅僅比1.1介紹的最前面多了一個日期時間： 2019-03-05T16:56:15.108+0800， 表示打印GC的時刻的時間是2019-03-05T16:56:15.108+0800。+0800表示是東8區。

1.5 -XX:+PrintHeapAtGC

這個參數開啓後，

使用以下參數-verbose:gc -XX:+PrintHeapAtGC -Xmn64M -Xms256M -Xmx256M

打印日誌以下：

{Heap before GC invocations=1 (full 0):
 PSYoungGen      total 57344K, used 49152K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
  eden space 49152K, 100% used [0x00000000fc000000,0x00000000ff000000,0x00000000ff000000)
  from space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
  to   space 8192K, 0% used [0x00000000ff000000,0x00000000ff000000,0x00000000ff800000)
 ParOldGen       total 196608K, used 0K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
  object space 196608K, 0% used [0x00000000f0000000,0x00000000f0000000,0x00000000fc000000)
 Metaspace       used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
  class space    used 888K, capacity 986K, committed 1024K, reserved 1048576K
[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]
Heap after GC invocations=1 (full 0):
 PSYoungGen      total 57344K, used 2400K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
  eden space 49152K, 0% used [0x00000000fc000000,0x00000000fc000000,0x00000000ff000000)
  from space 8192K, 29% used [0x00000000ff000000,0x00000000ff258020,0x00000000ff800000)
  to   space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
 ParOldGen       total 196608K, used 16K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
  object space 196608K, 0% used [0x00000000f0000000,0x00000000f0004000,0x00000000fc000000)
 Metaspace       used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
  class space    used 888K, capacity 986K, committed 1024K, reserved 1048576K
}
複製代碼

由此能夠看出在，打印以下日誌先後

[GC (Allocation Failure)  49152K->2416K(253952K), 0.0030218 secs]
複製代碼

詳細打印出了日誌信息

invocations 表示GC的次數，每次GC增長一次，每次GC先後的invocations相等

一、Heap before GC invocations=1 表示是第1次GC調用以前的堆內存情況

二、{Heap before GC invocations=1 (full 0): 表示是第1次GC調用以後的堆內存情況

1.6 -Xloggc:gc.log

若是使用該參數-Xloggc則默認開啓以下兩個參數

-XX:+PrintGC -XX:+PrintGCTimeStamps 
複製代碼

若是啓動參數以下：-Xloggc:gc.log -Xmn64M -Xms256M -Xmx256M則日誌格式以下所示

0.318: [GC (Allocation Failure)  49152K->2384K(253952K), 0.0038675 secs]
複製代碼

gc.log也能夠指定絕對的路徑。

在gc.log最前面還會默認打印系統的JDK版本與啓動的參數

Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 16287104k(1657700k free), swap 16636924k(15826632k free)
CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=268435456 -XX:MaxNewSize=67108864 -XX:NewSize=67108864 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
複製代碼

1.7 -XX:+PrintReferenceGC

此設置 -XX:+PrintReferenceGC能夠打印出SoftReference，WeakReference，FinalReference，PhantomReference，JNI Weak Reference幾種引用的數量，以及清理所用的時長，該參數在進行YGC調優時能夠排上用場。

[GC (Allocation Failure) [SoftReference, 0 refs, 0.0000119 secs][WeakReference, 499 refs, 0.0000370 secs][FinalReference, 1045 refs, 0.0002313 secs][PhantomReference, 0 refs, 0 refs, 0.0000039 secs][JNI Weak Reference, 0.0000290 secs][PSYoungGen: 53456K->4880K(57344K)] 53496K->4928K(253952K), 0.0037199 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
複製代碼

具體能夠參考佔小狼的一篇實戰：一次 Young GC 的優化實踐（FinalReference 相關）

2、CMS GC日誌詳細分析

[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs] [Times: user=0.57 sys=0.00, real=5.09 secs] 
[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
複製代碼

CMS日誌分爲兩個STW(stop the world)

分別是init remark（1） 與 remark（7）兩個階段。通常耗時比YGC長約10倍（我的經驗）。

（1）、[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: user=0.01 sys=0.00, real=0.01 secs]

會STO(Stop The World)，這時候的老年代容量爲 32768K， 在使用到 19498K 時開始初始化標記。耗時短。

（2）、[CMS-concurrent-mark-start]

併發標記階段開始

（3）、[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

併發標記階段花費時間。

（4）、[CMS-concurrent-preclean-start]

併發預清理階段，也是與用戶線程併發執行。虛擬機查找在執行併發標記階段新進入老年代的對象(可能會有一些對象從新生代晉升到老年代， 或者有一些對象被分配到老年代)。經過從新掃描，減小下一個階段」從新標記」的工做，由於下一個階段會Stop The World。

（5）、[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

併發預清理階段花費時間。

（6）、[CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs][Times: user=0.57 sys=0.00, real=5.09 secs]

併發可停止預清理階段，運行在並行預清理和從新標記之間，直到得到所指望的eden空間佔用率。增長這個階段是爲了不在從新標記階段後緊跟着發生一次垃圾清除

（7）、[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

會STW(Stop The World)，收集階段，這個階段會標記老年代所有的存活對象，包括那些在併發標記階段更改的或者新建立的引用對象

（8）、[CMS-concurrent-sweep-start]

併發清理階段開始，與用戶線程併發執行。

（9）、[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

併發清理階段結束，所用的時間。

（10）、[CMS-concurrent-reset-start]

開始併發重置。在這個階段，與CMS相關數據結構被從新初始化，這樣下一個週期能夠正常進行。

（11）、[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

併發重置所用結束，所用的時間。

參考：

Geek-Yan: JVM 學習筆記(四) CMS GC日誌詳解

3、G1垃圾收集器

建議在堆內存大於6G以上來使用，這個是官網的推薦。

4、GC調優

設置JVM GC 性能的有以下參數

4.1 -Xmn

新生代大小官網推薦的大小是3/8, 若是設置過小，好比1/10會致使Minor GC 與Major GC次數增多。

4.2 -XX:MaxTenuringThreshold=n

其中n的大小爲區間爲[0,15],若是高於15，JDK7 會默認15，JDK 8會啓動報錯

5、常見問題

1 .併發模式失敗（concurrent mode failure）

發生在CMS GC運行期間，詳情參考：

JVM 調優 —— GC 長時間停頓問題及解決方法

GC的悲觀策略

2. 提高失敗（promotion failed）

發生在Minor GC期間

參考資料

  1. 鐵錨:快速解讀GC日誌
  2. Geek-Yan: JVM 學習筆記(四) CMS GC日誌詳解
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程