JVM实用参数 GC日志

原文章地址：http://blog.panaihua.com/archives/151

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中生成的日志。为了便于阅读这里将一行日志分为多行并使用缩进。

[GC
     [PSYoungGen: 142816K->10752K(142848K)] 246648K->243136K(375296K), 0.0935090 secs
]
[Times: user=0.55 sys=0.10, real=0.09 secs]

咱们能够很容易发现：这是一次在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的输出日志

[Full GC
     [PSYoungGen: 10752K->9707K(142848K)]
     [ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K)
     [PSPermGen: 3162K->3161K(21504K)], 1.5265450 secs
]

除了关于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启动至今的时间戳会被添加到每一行中。例子以下：

0.185: [GC 66048K->53077K(251392K), 0.0977580 secs]0.323: [GC 119125K->114661K(317440K), 0.1448850 secs]0.603: [GC 246757K->243133K(375296K), 0.2860800 secs]

若是指定了-XX:+PrintGCDateStamps，每一行就添加上了绝对的日期和时间。

2014-01-03T12:08:38.102-0100: [GC 66048K->53077K(251392K), 0.0959470 secs]2014-01-03T12:08:38.239-0100: [GC 119125K->114661K(317440K), 0.1421720 secs]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日志参数。

HotSpot JVM有一类特别的参数叫作可管理的参数。对于这些参数，能够在运行时修改他们的值。咱们这里所讨论的全部参数以及以“PrintGC”开头的参数都是可管理的参数。这样在任什么时候候咱们均可以开启或是关闭GC日志。好比咱们可使用JDK自带的jinfo工具来设置这些参数，或者是经过JMX客户端调用HotSpotDiagnostic MXBean的setVMOption方法来设置这些参数。

原文章地址：http://blog.panaihua.com/archives/151