理解GC的输出（不包括G1）

垃圾收集器很大程度上会影响应用的吞吐量和延迟。在调优之前，首先要监控，继而进行分析。那我们先看一下如何获取GC数据，并理解这些数据。

获取GC数据

可以在命令行中指定下面一种选项：

• -verbose:gc或-verbosegc
• -XX:+PrintGCDetails——获取的信息比-verbose:gc更多

如果要获取GC执行的时间，计算GC的持续时间和频率，可以在命令行中指定任一选项：

• -XX:+PrintGCTimeStamps——显示从JVM启动到执行GC时流逝的时间，单位是秒
• -XX:+PrintGCDateStamps——显示执行GC时的本地时间（Java 6 update 4才开始支持）

要想观察GC的开销，或者看应用的延迟是应用本身的延迟，还是JVM GC的stop-the-world阶段的开销，可以指定-XX:+PrintGCApplicationConcurrentTime和-XX:+PrintGCApplicationStoppedTime选项。

另外还可以使用-Xloggc:<fileName>选项将GC数据直接输出到文件中，以便进行离线分析。

输出示例

常规输出

下面是Java 7 update 71（不同版本的输出可能会略有不同）上使用-XX:+PrintGCDetails获取的输出示例：

command 写道

java -Xms64m -Xmx128m -XX:+UseParallelGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gclog2.txt -jar E:\Java\jdk1.7.0_71\demo\jfc\Java2D\Java2demo.jar

 

log 写道

22.431: [GC [PSYoungGen: 1151K->638K(36352K)] 9659K->9146K(80384K), 0.0032716 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
22.435: [Full GC [PSYoungGen: 638K->0K(36352K)] [ParOldGen: 8507K->9082K(44032K)] 9146K->9082K(80384K) [PSPermGen: 14392K->14392K(21504K)], 0.0547773 secs] [Times: user=0.08 sys=0.00, real=0.06 secs]

第一条信息：

GC说明是minor GC（年轻代GC）。

PSYoungGen表示收集使用的收集器是多线程垃圾收集器Parallel Scavenge。

1151K->638K(36352K)中，1151K表示收集前年轻代占用的内存，638K表示收集后年轻代占用的内存。由于年轻代分为Eden和两个Suvivor，minor收集后Eden为空，所以该值也是Survivor的占用量。括号中的36352K是年轻代的大小。

9659K->9146K(80384K)中，9659K表示收集前整个堆占用的内存，9146K表示收集后整个堆占用的内存。括号里的80384K是Java堆的总量，可以算出老年代的大小是44032K（80384K-36352K）。

0.0032716是整次GC的暂停时间。

[Times: user=0.03 sys=0.00, real=0.00 secs]里，user是垃圾收集器执行非操作系统调用指令所耗费的CPU时间，sys是垃圾收集器执行操作系统调用所耗费的CPU时间, real表示完成GC的实际时间。

GC之后，年轻代减少了513K（1151K-638K），老年代占用的空间则没有变化（(9146K-638K)-(9659K-1151K)），这说明年轻代里的对象都被回收了，没有晋升到老年代中。

第二条信息：

Full GC说明是full GC，是对整个堆进行GC，包括年轻代、老年代和永久代。

PSYoungGen: 638K->0K(36352K)的含义和第一条信息里的PSYoungGen: 1151K->638K(36352K)一样。

ParOldGen: 8507K->9082K(44032K)表示老年代收集使用的是多线程垃圾收集器Parallel Old，收集前老年代占用8507K，收集后占用9082K，老年代的大小是44032K。

PSPermGen: 14392K->14392K(21504K)说明GC前永久代的占用量是14392K，GC后永久代的占用量是14392K，而永久代的大小是21504K。

带延迟信息的输出

下面是Java 7 update 71上使用-XX:+PrintGCDetails和-XX:+PrintGCApplicationConcurrentTime、-XX:+PrintGCApplicationStoppedTime选项获取的输出示例：

log 写道

21.719: Application time: 1.8299992 seconds
21.719: [GC [PSYoungGen: 1815K->64K(15360K)] 10319K->8567K(49664K), 0.0035923 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
21.723: [Full GC [PSYoungGen: 64K->0K(15360K)] [ParOldGen: 8503K->8523K(34304K)] 8567K->8523K(49664K) [PSPermGen: 14392K->14392K(22016K)], 0.0500793 secs] [Times: user=0.12 sys=0.00, real=0.05 secs] 
21.773: Total time for which application threads were stopped: 0.0542506 seconds

在这个片段中，应用运行了1.83秒，GC用了0.054秒，此次GC大约有3%的开销。

显式GC

如果GC输出信息中包含(System)，那说明这次GC是应用显式调用System.gc()所引起的。Java通常不建议应用进行显式的垃圾收集，要是在GC输出中发现该信息，就需要调查代码显式GC的原因了。

[Full GC (System) [PSYoungGen: ......

小结

通常来说，如果minor GC时，年轻代里的对象大部分被晋升到了老年代，被GC的并不多，那可以说明年轻代太小了。但在minor GC前后，老年代的大小要是没有发生变化，那意味着没有对象从年轻代提升到老年代。这是个好现象，说明minor GC回收了较多的垃圾对象，可以减少full GC的频率（full GC的持续时间很长）。

如果日志里只有full GC，每次full GC后，老年代几乎没回收什么空间，而且年轻代总有很大的占用量，那很可能是老年代空间不够大。

 

GC调优就基于对数据的分析，以及应用追求的性能指标（吞吐量、延迟、抑或内存占用），然后调整相应的设置，再进行新一轮的“监控——分析——调优”，……，直到满足应用的性能指标。

评论

1 楼 nuo9021 2014-12-22  

王女士，您好：
我是一名24岁的互联网创业者。有一些疑惑想向前辈请教。不知您是否有空？