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 對象分配