JVM实用参数（八）GC日志
作者：PATRICK PESCHLOW
本系列的最后一部分是有关垃圾收集（GC）日志的JVM参数。GC日志是一个很重要的工具，它准确记录了每一次的GC的执行时间和执行结果，通过分析GC日志可以优化堆设置和GC设置，或者改进应用程序的对象分配模式。
-XX:+PrintGC
参数-XX:+PrintGC（或者-verbose:gc）开启了简单GC日志模式，为每一次新生代（young generation）的GC和每一次的Full GC打印一行信息。下面举例说明：
[GC 246656K->243120K(376320K), 0.0929090 secs]
[Full GC 243120K->241951K(629760K), 1.5589690 secs]
每行开始首先是GC的类型（可以是“GC”或者“Full GC”），然后是在GC之前和GC之后已使用的堆空间，再然后是当前的堆容量，最后是GC持续的时间（以秒计）。
第一行的意思就是GC将已使用的堆空间从246656K减少到243120K，当前的堆容量（译者注：GC发生时）是376320K，GC持续的时间是0.0929090秒。
简单模式的GC日志格式是与GC算法无关的，日志也没有提供太多的信息。在上面的例子中，我们甚至无法从日志中判断是否GC将一些对象从young generation移到了old generation。所以详细模式的GC日志更有用一些。
-XX:PrintGCDetails
如果不是使用-XX:+PrintGC，而是-XX:PrintGCDetails，就开启了详细GC日志模式。在这种模式下，日志格式和所使用的GC算法有关。我们首先看一下使用Throughput垃圾收集器在young generation中生成的日志。为了便于阅读这里将一行日志分为多行并使用缩进。
| |
| |
| |
| |
我们可以很容易发现：这是一次在young generation中的GC，它将已使用的堆空间从246648K减少到了243136K，用时0.0935090秒。此外我们还可以得到更多的信息：所使用的垃圾收集器（即PSYoungGen）、young generation的大小和使用情况（在这个例子中“PSYoungGen”垃圾收集器将young generation所使用的堆空间从142816K减少到10752K）。
既然我们已经知道了young generation的大小，所以很容易判定发生了GC，因为young generation无法分配更多的对象空间：已经使用了142848K中的142816K。我们可以进一步得出结论，多数从young generation移除的对象仍然在堆空间中，只是被移到了old generation：通过对比绿色的和蓝色的部分可以发现即使young generation几乎被完全清空（从142816K减少到10752K），但是所占用的堆空间仍然基本相同（从246648K到243136K）。
详细日志的“Times”部分包含了GC所使用的CPU时间信息，分别为操作系统的用户空间和系统空间所使用的时间。同时，它显示了GC运行的“真实”时间（0.09秒是0.0929090秒的近似值）。如果CPU时间（译者注：0.55秒+0.10秒）明显多于”真实“时间（译者注：0.09秒），我们可以得出结论：GC使用了多线程运行。这样的话CPU时间就是所有GC线程所花费的CPU时间的总和。实际上我们的例子中的垃圾收集器使用了8个线程。
接下来看一下Full GC的输出日志
1
[Full GC
2
[PSYoungGen: 10752K->9707K(142848K)]
3
[ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K)
4
[PSPermGen: 3162K->3161K(21504K)], 1.5265450 secs
5
]
除了关于young generation的详细信息，日志也提供了old generation和permanent generation的详细信息。对于这三个generations，一样也可以看到所使用的垃圾收集器、堆空间的大小、GC前后的堆使用情况。需要注意的是显示堆空间的大小等于young generation和old generation各自堆空间的和。以上面为例，堆空间总共占用了241951K，其中9707K在young generation，232244K在old generation。Full GC持续了大约1.53秒，用户空间的CPU执行时间为10.96秒，说明GC使用了多线程（和之前一样8个线程）。
对不同generation详细的日志可以让我们分析GC的原因，如果某个generation的日志显示在GC之前，堆空间几乎被占满，那么很有可能就是这个generation触发了GC。但是在上面的例子中，三个generation中的任何一个都不是这样的，在这种情况下是什么原因触发了GC呢。对于Throughput垃圾收集器，在某一个generation被过度使用之前，GC ergonomics（参考本系列第6节）决定要启动GC。
Full GC也可以通过显式的请求而触发，可以是通过应用程序，或者是一个外部的JVM接口。这样触发的GC可以很容易在日志里分辨出来，因为输出的日志是以“Full GC(System)”开头的，而不是“Full GC”。
对于Serial垃圾收集器，详细的GC日志和Throughput垃圾收集器是非常相似的。唯一的区别是不同的generation日志可能使用了不同的GC算法（例如：old generation的日志可能以Tenured开头，而不是ParOldGen）。使用垃圾收集器作为一行日志的开头可以方便我们从日志就判断出JVM的GC设置。
对于CMS垃圾收集器，young generation的详细日志也和Throughput垃圾收集器非常相似，但是old generation的日志却不是这样。对于CMS垃圾收集器，在old generation中的GC是在不同的时间片内与应用程序同时运行的。GC日志自然也和Full GC的日志不同。而且在不同时间片的日志夹杂着在此期间young generation的GC日志。但是了解了上面介绍的GC日志的基本元素，也不难理解在不同时间片内的日志。只是在解释GC运行时间时要特别注意，由于大多数时间片内的GC都是和应用程序同时运行的，所以和那种独占式的GC相比，GC的持续时间更长一些并不说明一定有问题。
正如我们在第7节中所了解的，即使CMS垃圾收集器没有完成一个CMS周期，Full GC也可能会发生。如果发生了GC，在日志中会包含触发Full GC的原因，例如众所周知的”concurrent mode failure“。
为了避免过于冗长，我这里就不详细说明CMS垃圾收集器的日志了。另外，CMS垃圾收集器的作者做了详细的说明（在这里），强烈建议阅读。
-XX:+PrintGCTimeStamps和-XX:+PrintGCDateStamps
使用-XX:+PrintGCTimeStamps可以将时间和日期也加到GC日志中。表示自JVM启动至今的时间戳会被添加到每一行中。例子如下：
1
0.185: [GC 66048K->53077K(251392K), 0.0977580 secs]
2
0.323: [GC 119125K->114661K(317440K), 0.1448850 secs]
3
0.603: [GC 246757K->243133K(375296K), 0.2860800 secs]
如果指定了-XX:+PrintGCDateStamps，每一行就添加上了绝对的日期和时间。
1
2014-01-03T12:08:38.102-0100: [GC 66048K->53077K(251392K), 0.0959470 secs]
2
2014-01-03T12:08:38.239-0100: [GC 119125K->114661K(317440K), 0.1421720 secs]
3
2014-01-03T12:08:38.513-0100: [GC 246757K->243133K(375296K), 0.2761000 secs]
如果需要也可以同时使用两个参数。推荐同时使用这两个参数，因为这样在关联不同来源的GC日志时很有帮助。
-Xloggc
缺省的GC日志时输出到终端的，使用-Xloggc:也可以输出到指定的文件。需要注意这个参数隐式的设置了参数-XX:+PrintGC和-XX:+PrintGCTimeStamps，但为了以防在新版本的JVM中有任何变化，我仍建议显示的设置这些参数。
可管理的JVM参数
一个常常被讨论的问题是在生产环境中GC日志是否应该开启。因为它所产生的开销通常都非常有限，因此我的答案是需要开启。但并不一定在启动JVM时就必须指定GC日志参数。
jinfo工具来设置这些参数，或者是通过JMX客户端调用HotSpotDiagnostic MXBean的setVMOption方法来设置这些参数。
00:13:44 java -cp .:/zrjapp/java/jdk1.7.0_75/lib/dt.jar:/zrjapp/java/jdk1.7.0_75/lib/tools.jar::lib/aopalliance-1.0.jar:lib/aspectjrt-1.7.0.jar:lib/aspectjweaver-1.7.0.jar:lib/bank-api-1.0-SNAPSHOT.jar:lib/c3p0-0.9.5.1.jar:lib/commons-codec-1.9.jar:lib/commons-lang3-3.3.2.jar:lib/commons-logging-1.1.3.jar:lib/curator-client-2.5.0.jar:lib/curator-framework-2.5.0.jar:lib/druid-1.0.12.jar:lib/dubbo-little-2.8.3.jar:lib/fastjson-1.2.3.jar:lib/guava-16.0.1.jar:lib/hamcrest-core-1.3.jar:lib/jackson-annotations-2.3.0.jar:lib/jackson-core-2.3.3.jar:lib/jackson-databind-2.3.3.jar:lib/javassist-3.15.0-GA.jar:lib/jconsole-1.8.0.jar:lib/jline-0.9.94.jar:lib/junit-4.11.jar:lib/kryo-2.24.0.jar:lib/kryo-serializers-0.26.jar:lib/log4j-1.2.16.jar:lib/log4j-1.2-api-2.2.jar:lib/log4j-api-2.2.jar:lib/log4j-core-2.2.jar:lib/log4j-jcl-2.2.jar:lib/log4j-slf4j-impl-2.2.jar:lib/mchange-commons-java-0.2.10.jar:lib/minlog-1.2.jar:lib/mybatis-3.2.8.jar:lib/mybatis-spring-1.2.2.jar:lib/mysql-connector-java-5.1.34.jar:lib/netty-3.2.5.Final.jar:lib/objenesis-2.1.jar:lib/slf4j-api-1.6.2.jar:lib/spring-aop-3.2.9.RELEASE.jar:lib/spring-beans-3.2.9.RELEASE.jar:lib/spring-context-3.2.9.RELEASE.jar:lib/spring-core-3.2.9.RELEASE.jar:lib/spring-expression-3.2.9.RELEASE.jar:lib/spring-jdbc-3.2.9.RELEASE.jar:lib/springmore-core-1.0.0.jar:lib/spring-test-3.2.9.RELEASE.jar:lib/spring-tx-3.2.9.RELEASE.jar:lib/tools-1.8.0.jar:lib/zkclient-0.1.jar:lib/zookeeper-3.3.3.jar:lib/zrj-base-api-1.1-SNAPSHOT.jar:bank-account-service-1.0.jar:conf -Xms256m -Xmx256m -XX:PermSize=64m -server -XX:ParallelGCThreads=4 -XX:SurvivorRatio=1 -XX:-UseAdaptiveSizePolicy -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -verbose:gc -XX:+PrintGCTimeStamps-XX:+PrintGCDetails -Xloggc:logs/gc.log com.zrj.bank.depository.account.main.MainServer
[serv@datanode1 logs]$ tail -100 gc.log
1.007: [GC1.008: [ParNew: 29120K->4578K(58240K), 0.0093640 secs] 29120K->4578K(233024K), 0.0095270 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
1.615: [GC1.615: [ParNew: 33698K->6215K(58240K), 0.0062520 secs] 33698K->6215K(233024K), 0.0063380 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
2.505: [GC2.505: [ParNew: 35335K->10090K(58240K), 0.0177400 secs] 35335K->10090K(233024K), 0.0179030 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
3.576: [GC3.576: [ParNew: 39210K->13361K(58240K), 0.0148680 secs] 39210K->13361K(233024K), 0.0150110 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
3.945: [GC3.945: [ParNew: 42481K->10674K(58240K), 0.0130810 secs] 42481K->10674K(233024K), 0.0132150 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
4.968: [GC4.968: [ParNew: 39794K->14813K(58240K), 0.0187760 secs] 39794K->14813K(233024K), 0.0189180 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
5.675: [GC5.675: [ParNew: 43933K->15449K(58240K), 0.0161270 secs] 43933K->15449K(233024K), 0.0162580 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
23526.485: [GC23526.485: [ParNew: 44569K->13413K(58240K), 0.0447940 secs] 44569K->13413K(233024K), 0.0453090 secs] [Times: user=0.17 sys=0.00, real=0.05 secs]
55917.499: [GC55917.499: [ParNew: 42533K->11440K(58240K), 0.0262140 secs] 42533K->11440K(233024K), 0.0264160 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]
89316.384: [GC89316.384: [ParNew: 40560K->11993K(58240K), 0.0278290 secs] 40560K->11993K(233024K), 0.0580460 secs] [Times: user=0.11 sys=0.00, real=0.06 secs]
122988.652: [GC122988.652: [ParNew: 41113K->13488K(58240K), 0.0448210 secs] 41113K->13488K(233024K), 0.0451820 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
156817.481: [GC156817.481: [ParNew: 42608K->9562K(58240K), 0.0328410 secs] 42608K->9562K(233024K), 0.0330640 secs] [Times: user=0.14 sys=0.00, real=0.03 secs]
181409.050: [GC181409.050: [ParNew: 38682K->11135K(58240K), 0.0210350 secs] 38682K->11135K(233024K), 0.0214670 secs] [Times: user=0.09 sys=0.00, real=0.02 secs]
210401.966: [GC210401.968: [ParNew: 40255K->11923K(58240K), 0.0439190 secs] 40255K->11923K(233024K), 0.0461530 secs] [Times: user=0.18 sys=0.00, real=0.04 secs]
244027.788: [GC244027.788: [ParNew: 41043K->9870K(58240K), 0.0409900 secs] 41043K->9870K(233024K), 0.0413360 secs] [Times: user=0.18 sys=0.00, real=0.04 secs]
277657.647: [GC277657.647: [ParNew: 38990K->9851K(58240K), 0.0338950 secs] 38990K->11637K(233024K), 0.0340900 secs] [Times: user=0.15 sys=0.00, real=0.04 secs]
310060.645: [GC310060.645: [ParNew: 38971K->8378K(58240K), 0.0458020 secs] 40757K->10756K(233024K), 0.0461910 secs] [Times: user=0.18 sys=0.00, real=0.04 secs]
343388.809: [GC343388.809: [ParNew: 37498K->5972K(58240K), 0.0316740 secs] 39876K->10634K(233024K), 0.0320120 secs] [Times: user=0.14 sys=0.00, real=0.03 secs]
serv 45149 1 0 10:16 ? 00:00:44 /home/jdk1.7.0_75/bin/java -Djava.util.logging.config.file=/zrjapp/apps/bank-admin-tomcat-https/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -server -Xms512M -Xmx512M -Xss256K -Djava.awt.headless=true -Dfile.encoding=utf-8 -XX:PermSize=256M -XX:MaxPermSize=512m -Djava.endorsed.dirs=/zrjapp/apps/bank-admin-tomcat-https/endorsed -classpath /zrjapp/apps/bank-admin-tomcat-https/bin/bootstrap.jar:/zrjapp/apps/bank-admin-tomcat-https/bin/tomcat-juli.jar -Dcatalina.base=/zrjapp/apps/bank-admin-tomcat-https -Dcatalina.home=/zrjapp/apps/bank-admin-tomcat-https -Djava.io.tmpdir=/zrjapp/apps/bank-admin-tomcat-https/temp org.apache.catalina.startup.Bootstrap start
