JVM实用参数8：GC日志

本系列的最后一部分是有关垃圾收集（gc）日志的jvm参数。gc日志是一个很重要的工具，它准确记录了每一次的gc的执行时间和执行结果，通过分析gc日志可以优化堆设置和gc设置，或者改进应用程序的对象分配模式。

参数-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将已使用的堆空间从246656k减少到243120k，当前的堆容量（译者注：gc发生时）是376320k，gc持续的时间是0.0929090秒。

每行开始首先是gc的类型（可以是“gc”或者“full gc”），然后是在gc之前和gc之后已使用的堆空间，再然后是当前的堆容量，最后是gc持续的时间（以秒计）。

简单模式的gc日志格式是与gc算法无关的，日志也没有提供太多的信息。在上面的例子中，我们甚至无法从日志中判断是否gc将一些对象从young generation移到了old generation。所以详细模式的gc日志更有用一些。

如果不是使用-xx:+printgc，而是-xx:printgcdetails，就开启了详细gc日志模式。在这种模式下，日志格式和所使用的gc算法有关。我们首先看一下使用throughput垃圾收集器在young generation中生成的日志。为了便于阅读这里将一行日志分为多行并使用缩进。

既然我们已经知道了young generation的大小，所以很容易判定发生了gc，因为young generation无法分配更多的对象空间：已经使用了142848k中的142816k。我们可以进一步得出结论，多数从young generation移除的对象仍然在堆空间中，只是被移到了old generation：通过对比绿色的和蓝色的部分可以发现即使young generation几乎被完全清空（从142816k减少到10752k），但是所占用的堆空间仍然基本相同（从246648k到243136k）。我们可以很容易发现：这是一次在young generation中的gc，它将已使用的堆空间从246648k减少到了243136k，用时0.0935090秒。此外我们还可以得到更多的信息：所使用的垃圾收集器（即psyounggen）、young generation的大小和使用情况（在这个例子中“psyounggen”垃圾收集器将young generation所使用的堆空间从142816k减少到10752k）。

详细日志的“times”部分包含了gc所使用的cpu时间信息，分别为操作系统的用户空间和系统空间所使用的时间。同时，它显示了gc运行的“真实”时间（0.09秒是0.0929090秒的近似值）。如果cpu时间（译者注：0.55秒+0.10秒）明显多于”真实“时间（译者注：0.09秒），我们可以得出结论：gc使用了多线程运行。这样的话cpu时间就是所有gc线程所花费的cpu时间的总和。实际上我们的例子中的垃圾收集器使用了8个线程。

接下来看一下full gc的输出日志

正如我们在第7节中所了解的，即使cms垃圾收集器没有完成一个cms周期，full gc也可能会发生。如果发生了gc，在日志中会包含触发full gc的原因，例如众所周知的”concurrent mode failure“。

对于cms垃圾收集器，young generation的详细日志也和throughput垃圾收集器非常相似，但是old generation的日志却不是这样。对于cms垃圾收集器，在old generation中的gc是在不同的时间片内与应用程序同时运行的。gc日志自然也和full gc的日志不同。而且在不同时间片的日志夹杂着在此期间young generation的gc日志。但是了解了上面介绍的gc日志的基本元素，也不难理解在不同时间片内的日志。只是在解释gc运行时间时要特别注意，由于大多数时间片内的gc都是和应用程序同时运行的，所以和那种独占式的gc相比，gc的持续时间更长一些并不说明一定有问题。

对于serial垃圾收集器，详细的gc日志和throughput垃圾收集器是非常相似的。唯一的区别是不同的generation日志可能使用了不同的gc算法（例如：old generation的日志可能以tenured开头，而不是paroldgen）。使用垃圾收集器作为一行日志的开头可以方便我们从日志就判断出jvm的gc设置。

full gc也可以通过显式的请求而触发，可以是通过应用程序，或者是一个外部的jvm接口。这样触发的gc可以很容易在日志里分辨出来，因为输出的日志是以“full gc(system)”开头的，而不是“full gc”。

对不同generation详细的日志可以让我们分析gc的原因，如果某个generation的日志显示在gc之前，堆空间几乎被占满，那么很有可能就是这个generation触发了gc。但是在上面的例子中，三个generation中的任何一个都不是这样的，在这种情况下是什么原因触发了gc呢。对于throughput垃圾收集器，在某一个generation被过度使用之前，gc ergonomics（参考本系列第6节）决定要启动gc。除了关于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个线程）。

为了避免过于冗长，我这里就不详细说明cms垃圾收集器的日志了。另外，cms垃圾收集器的作者做了详细的说明（在这里），强烈建议阅读。

使用-xx:+printgctimestamps可以将时间和日期也加到gc日志中。表示自jvm启动至今的时间戳会被添加到每一行中。例子如下：

如果指定了-xx:+printgcdatestamps，每一行就添加上了绝对的日期和时间。

缺省的gc日志时输出到终端的，使用-xloggc:也可以输出到指定的文件。需要注意这个参数隐式的设置了参数-xx:+printgc和-xx:+printgctimestamps，但为了以防在新版本的jvm中有任何变化，我仍建议显示的设置这些参数。

-xloggc如果需要也可以同时使用两个参数。推荐同时使用这两个参数，因为这样在关联不同来源的gc日志时很有帮助。

一个常常被讨论的问题是在生产环境中gc日志是否应该开启。因为它所产生的开销通常都非常有限，因此我的答案是需要开启。但并不一定在启动jvm时就必须指定gc日志参数。

hotspot jvm有一类特别的参数叫做可管理的参数。对于这些参数，可以在运行时修改他们的值。我们这里所讨论的所有参数以及以“printgc”开头的参数都是可管理的参数。这样在任何时候我们都可以开启或是关闭gc日志。比如我们可以使用jdk自带的jinfo工具来设置这些参数，或者是通过jmx客户端调用hotspotdiagnostic mxbean的setvmoption方法来设置这些参数。

以上就是本期内容，更多请关注下期持续更新！