（轉）Java GC - 監控回收行為與日誌分析
1. 簡介
在上一篇介紹<Java GC - 垃圾回收機制>， 本文將介紹如何監控 Javc GC 行為，同時涉及一些GUI工具的使用(雖然有些已經很老並不再更新)，監控GC在於判斷JVM是否在良好高效地工作並且是否需要投入效能調優(主要包括應用程式優化與JVM引數優化)，關注的資料大概有：
1. Mirror GC頻率、持續時間以及回收記憶體量。
2. Major GC頻率、持續時間、回收記憶體量以及 stop-the-world 耗時。
3. Heap 物件分配(匯出.hprof檔案分析，通常比較大)
2. GC LOG 及Collector行為分析
LOG分析包含前面文章所介紹的各個GC collector的行為分析。通過加入 -XX:+PrintGCDetails 引數則可以列印詳細GC資訊至控制檯。引數-verbose:gc也是可以，但不夠詳細。通過加入-XX:+PrintGCDateStamps則可以記錄GC發生的詳細時間。
通過加入 -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中通用的欄位含義說明：
1、142826K->10751K(274944K) 分別代表回收前、回收後以及總記憶體大小。
2、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，稍等片刻即可連線，如下圖：
注：需要在 TOOLS->PLUGINs 中安裝一些外掛，如visual GC等才能檢視一些更好的資訊，如下圖：
4. jconsole & jps
jconsole大部分功能在jvisualvm中存在，所以使用的概率相對較小。jps 則是列印目前主機中正在啟動的JAVA應用的PID。
5. GCViewer
該工具用於統計加上引數如-XX:+PrintGCDetails -Xloggc:/home/xx.log 形成的LOG檔案，從伺服器上拿到檔案後啟動GCViewer開啟，如下圖:
6. Memory Analyzer
Memory Analyzer 使用者分析 Heap dump 的 .hprof檔案，展示目前Heap中的大物件等資訊，如下圖：
另外還有jProfiler，HPjmeter 等工具不再一一列出。
3. 總結
GC 分析主要點在於：
1. Mirror & Major GC 情況
2. Heap 物件分配