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中通用的字段含义说明：

一、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，稍等片刻便可链接，以下图：

注：须要在 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 对象分配