Java GC - 監控回收行爲與日誌分析

時間 2019-11-10

標籤 java 監控回收行爲日誌分析欄目 Java 简体版

原文原文鏈接

1. 簡介html

在上一篇介紹<Java GC - 垃圾回收機制>，本文將介紹如何監控 Javc GC 行爲，同時涉及一些GUI工具的使用(雖然有些已經很老並再也不更新)，監控GC在於判斷JVM是否在良好高效地工做而且是否須要投入性能調優(主要包括應用程序優化與JVM參數優化)，關注的數據大概有：java

1. Mirror GC頻率、持續時間以及回收內存量。瀏覽器

2. Major GC頻率、持續時間、回收內存量以及 stop-the-world 耗時。服務器

3. Heap 對象分配(導出.hprof文件分析，一般比較大)oracle

2. GC LOG 及Collector行爲分析app

LOG分析包含前面文章所介紹的各個GC collector的行爲分析。經過加入 -XX:+PrintGCDetails 參數則能夠打印詳細GC信息至控制檯。參數-verbose:gc也是能夠，但不夠詳細。經過加入-XX:+PrintGCDateStamps則能夠記錄GC發生的詳細時間。jsp

經過加入 -Xloggc:/home/XX/gc/app_gc.log 能夠把GC輸出至文件，這對長時間服務器GC監控頗有幫助。如下列出一些參數大體打印的信息以下：工具

1. -verbose:gc： [GC 72104K->9650K(317952K), 0.0130635 secs]性能

2. -XX:+PrintGCDetails: [GC [PSYoungGen: 142826K->10751K(274944K)] 162800K->54759K(450048K), 0.0609952 secs] [Times: user=0.13 sys=0.02, real=0.06 secs]優化

3. -XX:+PrintGCDetails 加上-XX:+PrintGCDateStamps 參數則打印以下：

2015-12-06T12:32:02.890+0800: [GC [PSYoungGen: 142833K->10728K(142848K)] 166113K->59145K(317952K), 0.0792023 secs] [Times: user=0.22 sys=0.00, real=0.08 secs]

能夠看出，若是是想監控詳細信息與GC發生時間，加上-XX:+PrintGCDateStamps -XX:+PrintGCDetails 參數會是一個比較好的選擇。

首先來講明一段在各個GC中通用的字段含義說明：

一、142826K->10751K(274944K) 分別表明回收前、回收後以及總內存大小。

二、Times: user=0.46 sys=0.05, real=0.07 secs： user表明GC 須要的各個CPU總時間(各個CPU時間相加)，sys表明回收器自身的行爲所佔用CPU時間，real則表明本次GC所耗費的真正耗時(在多核CPU中並行回收，它一般小於user) 。

2.1 Serial GC (-XX:+UseSerialGC)

下面是一段的Serial GC日誌含義依次分解：

---------------------------

[GC[DefNew: 78656K->8704K(78656K), 0.0487492 secs] 135584K->80553K(253440K), 0.0488309 secs] [Times: user=0.05 sys=0.00, real=0.05 secs]

[Full GC[Tenured: 62546K->60809K(174784K), 0.1600120 secs] 85931K->60809K(253440K), [Perm : 38404K->38404K(65536K)], 0.1600814 secs] [Times: user=0.16 sys=0.00, real=0.16 secs]

---------------------------

1. 其中的DefNew表明單線程回收yong generation。

2. 緊跟後面的 78656K->8704K(78656K) 中的 78656K 表明young generation 回收前大小，8704K 表明回收後大小，括號中的78656K 表明young generation總大小(包含2個survivor)。

3. 135584K->80553K(253440K) 則表明整個Heap(young+old)的變化與總量，含義參照前面所述(Perm也同樣)。

4. Full GC 即表明 major GC, Tenured: 62546K->60809K(174784K)則表示 old generation變化及總量

2.2 Parallel GC

Paralle GC 經過加入參數 -XX:+UseParallelGC 來指定(不少服務器默認不須要加這參數就默認使用該GC collector -- 經過判斷配置來決定)，經過再加入 -XX:+UseParallelOldGC 使得 Full GC也啓用並行，但在(http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html)有以下介紹：

-XX:-UseParallelGC：Use parallel garbage collection for scavenges. (Introduced in 1.4.1)
-XX:-UseParallelOldGC：Use parallel garbage collection for the full collections. Enabling this option automatically sets -XX:+UseParallelGC. (Introduced in 5.0 update 6.)

如想詳細查詢是否真正自動啓用(仍是不加入-XX:+UseParallelOldGC有什麼細微區別) 則可查看 Open JDK 參考實現來肯定，本文不作詳細分析，因此加上-XX:+UseParallelGC -XX:+UseParallelOldGC 會是個保險的選擇。下面附上一段Open JDK 7的路徑爲：

hotspot/src/share/vm/runtime/arguments.cpp 部分源碼，估計會有些幫助:

void Arguments::set_parallel_gc_flags() {
　　assert(UseParallelGC || UseParallelOldGC, "Error");
　　// If parallel old was requested, automatically enable parallel scavenge.
　　if (UseParallelOldGC && !UseParallelGC && FLAG_IS_DEFAULT(UseParallelGC)) {
　　　　FLAG_SET_DEFAULT(UseParallelGC, true);
　　}

　　// If no heap maximum was requested explicitly, use some reasonable fraction
　　// of the physical memory, up to a maximum of 1GB.
　　if (UseParallelGC) {
　　　　FLAG_SET_ERGO(uintx, ParallelGCThreads,
　　　　Abstract_VM_Version::parallel_worker_threads());

　　　　// If InitialSurvivorRatio or MinSurvivorRatio were not specified, but the
　　　　// SurvivorRatio has been set, reset their default values to SurvivorRatio +
　　　　// 2. By doing this we make SurvivorRatio also work for Parallel Scavenger.
　　　　// See CR 6362902 for details.
　　　　if (!FLAG_IS_DEFAULT(SurvivorRatio)) {
　　　　　　if (FLAG_IS_DEFAULT(InitialSurvivorRatio)) {
　　　　　　　　FLAG_SET_DEFAULT(InitialSurvivorRatio, SurvivorRatio + 2);
　　　　　　}
　　　　　　if (FLAG_IS_DEFAULT(MinSurvivorRatio)) {
　　　　　　　　FLAG_SET_DEFAULT(MinSurvivorRatio, SurvivorRatio + 2);
　　　　　　}
　　　　}

　　　　if (UseParallelOldGC) {
　　　　　　// Par compact uses lower default values since they are treated as
　　　　　　// minimums. These are different defaults because of the different
　　　　　　// interpretation and are not ergonomically set.
　　　　　　if (FLAG_IS_DEFAULT(MarkSweepDeadRatio)) {
　　　　　　　　FLAG_SET_DEFAULT(MarkSweepDeadRatio, 1);
　　　　　　}
　　　　　　if (FLAG_IS_DEFAULT(PermMarkSweepDeadRatio)) {
　　　　　　　　FLAG_SET_DEFAULT(PermMarkSweepDeadRatio, 5);
　　　　　　}
　　　　}
　　}
　　if (UseNUMA) {
　　　　if (FLAG_IS_DEFAULT(MinHeapDeltaBytes)) {
　　　　　　FLAG_SET_DEFAULT(MinHeapDeltaBytes, 64*M);
　　　　}
　　}
}

--------------------------

[GC [PSYoungGen: 88524K->10728K(274944K)] 133505K->61187K(450048K), 0.0374438 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
[Full GC [PSYoungGen: 10728K->0K(274944K)] [ParOldGen: 50459K->50210K(175104K)] 61187K->50210K(450048K) [PSPermGen: 38656K->38643K(77312K)], 0.3787131 secs] [Times: user=0.98 sys=0.02, real=0.38 secs]

--------------------------

1. PSYoungGen 表明並行回收 young generation

2. ParOldGen 表明並行回收 old generation.

3. PSPermGen 表明並行回收 Permanent generation. 其餘的參數與前面解釋的相似。

2.3 CMS GC

CMS GC相對來講比較複雜，經過使用 -XX:+UseConcMarkSweepGC 參數在指定，可是通常狀況須要更多的其餘參數來保證它能比較好地達到咱們的低延時目的，下面就部分經常使用參數作介紹：

-XX:+CMSIncrementalMode 採用增量式的標記方式，減小標記時應用停頓時間
-XX:+CMSParallelRemarkEnabled 啓用並行標記
-XX:CMSInitiatingOccupancyFraction=70 Old generation消耗比例達到多少時進行回收，一般配置60-80之間
-XX:CMSFullGCsBeforeCompaction=1 多少次Full GC 後壓縮old generation一次
-XX:+UseCMSInitiatingOccupancyOnly
-XX:+ScavengeBeforeFullGC Old generation GC前對young generation GC一次，默認開啓。
-XX:+CMSScavengeBeforeRemark CMS remark以前進行一次young generation GC

關於CMSFullGCsBeforeCompaction 的參數影響在Open JDK中以下判斷：

*should_compact =
UseCMSCompactAtFullCollection &&
((_full_gcs_since_conc_gc >= CMSFullGCsBeforeCompaction) ||
GCCause::is_user_requested_gc(gch->gc_cause()) ||
gch->incremental_collection_will_fail(true /* consult_young */));

關於UseCMSInitiatingOccupancyOnly 參數的詳細解釋以下:

-XX:+UseCMSInitiatingOccupancyOnly instructs the HotSpot VM to always use the -XX:CMSInitiatingOccupancyFraction as the occupancy of the old generation space to initiate a CMS cycle.

If -XX:+UseCMSInitiatingOccupancyOnly is not used, the HotSpot VM uses the -XX:CMSInitiatingOccupancyFraction as the occupancy percentage to start only the first CMS cycle. It then attempts to adaptively adjust when to start the CMS cycle for subsequent CMS cycles, that is, it no longer uses the specified -XX:CMSInitiatingOccupancyFraction after the first CMS cycle

下面爲一個可參考的CMS GC配置，根據應用的不一樣用途作相應修改(下面打印了GC LOG)：

------------------------------------------------------

JAVA_OPTS="
-DappName=XXX
-server
-Xms10g -Xmx10g
-XX:NewSize=4g -XX:MaxNewSize=4g
-XX:PermSize=256m -XX:MaxPermSize=256m

-XX:+UseConcMarkSweepGC
-XX:+CMSIncrementalMode -XX:+CMSParallelRemarkEnabled
-XX:CMSInitiatingOccupancyFraction=70 -XX:CMSFullGCsBeforeCompaction=1
-XX:+UseCMSInitiatingOccupancyOnly
-XX:+ScavengeBeforeFullGC -XX:+CMSScavengeBeforeRemark

-XX:+PrintGCDateStamps -verbose:gc -XX:+PrintGCDetails -Xloggc:/home/XX/gc/XX_gc.log
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=10M

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/XX/dump_OOME.hprof

-XX:+DisableExplicitGC

-----------------------------------------------------

下面使用一段LOG 做爲 CMS GC行爲：

--------------------------------

[GC [ParNew: 5033216K->629120K(5662336K), 19.9680140 secs] 5033216K->2091720K(11953792K), 19.9682480 secs] [Times: user=119.82 sys=14.07, real=19.97 secs]

[GC [1 CMS-initial-mark: 1462600K(6291456K)] 4404491K(11953792K), 3.6824630 secs] [Times: user=3.67 sys=0.01, real=3.69 secs]
[CMS-concurrent-mark-start]
[[ParNew: 5662336K->629120K(5662336K), 6.8885140 secs] 7124936K->4366353K(11953792K), 6.8886670 secs] [Times: user=136.94 sys=0.92, real=6.89 secs]
[CMS-concurrent-mark: 2.053/75.039 secs] [Times: user=192.12 sys=3.19, real=75.04 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 6.159/6.274 secs] [Times: user=7.53 sys=0.30, real=6.28 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 10.680/10.681 secs] [Times: user=12.77 sys=0.43, real=10.68 secs]
[GC[YG occupancy: 3043648 K (5662336 K)] [GC [ParNew: 3043648K->629120K(5662336K), 1.5345480 secs] 6780882K->4985422K(11953792K), 1.5346490 secs] [Times: user=30.72 sys=0.27, real=1.53 secs]
[Rescan (parallel) , 0.1900960 secs] [weak refs processing, 0.0000460 secs] [scrub string table, 0.0008680 secs] [1 CMS-remark: 4356302K(6291456K)] 4985422K(11953792K), 1.7259240 secs] [Times: user=34.88 sys=0.27, real=1.72 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 3.379/3.380 secs] [Times: user=4.05 sys=0.13, real=3.38 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.030/0.030 secs] [Times: user=0.02 sys=0.01, real=0.03 secs]

---------------------------------

默認狀況下Full GC以前會進行一次 Mirror GC，日誌中的第一行則是，含義和前面的描述同樣，再也不贅述。

其餘的則是CMS GC 的各個週期(在前一篇文章中有描述)，其中只在 CMS-remark階段應用暫停時間最長，但相對Parallel GC來講它相對會短些。

3. GC監控工具

GC 監控工具備JDK自帶的工具和第三方分析工具，同時包含命令行與GUI工具

附： jstack 命令能夠查詢當前應用線程狀態，可用於判斷是否存在死鎖、線程等待緣由等問題。

3.1 jmap

jmap 有幾項參數，直接執行jmap命令可打印這些選項，下面列出 -heap 參數打印狀況(關鍵點粗體字標出)：

--------------------------------

Server compiler detected.
JVM version is 24.79-b02

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
MinHeapFreeRatio = 40
MaxHeapFreeRatio = 70
MaxHeapSize = 2147483648 (2048.0MB)
NewSize = 1310720 (1.25MB)
MaxNewSize = 348913664 (332.75MB)
OldSize = 5439488 (5.1875MB)
NewRatio = 2
SurvivorRatio = 8
PermSize = 67108864 (64.0MB)
MaxPermSize = 268435456 (256.0MB)
G1HeapRegionSize = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
capacity = 80543744 (76.8125MB)
used = 13761040 (13.123550415039062MB)
free = 66782704 (63.68894958496094MB)
17.08517547930228% used
Eden Space:
capacity = 71630848 (68.3125MB)
used = 4848144 (4.6235504150390625MB)
free = 66782704 (63.68894958496094MB)
6.768234825308783% used
From Space:
capacity = 8912896 (8.5MB)
used = 8912896 (8.5MB)
free = 0 (0.0MB)
100.0% used
To Space:
capacity = 8912896 (8.5MB)
used = 0 (0.0MB)
free = 8912896 (8.5MB)
0.0% used
concurrent mark-sweep generation:
capacity = 178978816 (170.6875MB)
used = 54910688 (52.366912841796875MB)
free = 124068128 (118.32058715820312MB)
30.679992876922373% used
Perm Generation:
capacity = 67108864 (64.0MB)
used = 37996544 (36.236328125MB)
free = 29112320 (27.763671875MB)
56.6192626953125% used

17968 interned Strings occupying 2174744 bytes.

--------------------------------

下面dump一份heap分配狀況：

jmap -dump:format=b,file=d:/test.hprof 7880

其中 7880爲 PID，導出的文件可以使用Memory Analyzer, jvisualvm, jprofile等工具打開

3.2 jhat

若是你導出的 hprof 文件很大不方便下載本地分析，可使用 jhat 啓動HTTP Server的後可使用瀏覽器訪問,

例如：執行 jhat d:/test.hprof 後開啓 7000 端口提供HTTP服務，使用瀏覽器便可訪問:

---------------------------

Snapshot read, resolving...
Resolving 2049558 objects...
Chasing references, expect 409 dots
...................................
Eliminating duplicate references...
...................................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

---------------------------

注：若是導出的文件很大，則須要開啓更多的內存空間，使用 -J-Xmx5g 命令則開啓最大5G。

3.3 jstat (jstatd) & jvisualvm

jstat用於實時監測 GC狀況，如PID爲7880的應用監測，每 1000毫秒打印一次：

---------------------------

jstat -gc 7880 1000
S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT
8704.0 8704.0 8704.0 0.0 69952.0 14761.0 277100.0 181950.8 65536.0 37705.5 60 2.946 35 1.285 4.231
8704.0 8704.0 8704.0 0.0 69952.0 14763.0 277100.0 181950.8 65536.0 37705.5 60 2.946 35 1.285 4.231

---------------------------

若是開啓 jstatd 則可遠程使用 jvisualvm 的圖形化監控.

1. 首先須要配置一個policy文件，內容以下( 假設名稱爲 tools.policy，根據安裝路徑不一進行相應修改 )：

grant codebase "file:/usr/java/jdk1.7.0_79/lib/tools.jar" {
permission java.security.AllPermission;
};

2. 而後啓動jstatd服務，後面的IP地址爲該服務綁定的地址：

jstatd -J-Djava.security.policy=/home/XXX/tools.policy -J-Djava.rmi.server.hostname=192.168.X.X

3. 在jvisualvm中添加 Remote，輸入IP新建主機後右鍵添加 jstatd connection，稍等片刻便可鏈接，以下圖：