理解GC日志

为了了解垃圾回收日志的内容，分析从众够得到哪些有用的信息。我们需要添加如下启动参数：

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

输出的日志结果如下：

第一行：
2015-05-26T14:45:37.987-0200: 151.126:
 [GC (Allocation Failure) 151.126: 
[DefNew: 629119K->69888K(629120K), 0.0584157 secs] 
1619346K->1273247K(2027264K), 0.0585007 secs] 
[Times: user=0.06 sys=0.00, real=0.06 secs]

2015-05-26T14:45:59.690-0200: 172.829: 

第二行：
[GC (Allocation Failure) 172.829: 
[DefNew: 629120K->629120K(629120K), 0.0000372 secs]
172.829: [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs] 
1832479K->755802K(2027264K), 
[Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs]
 [Times: user=0.18 sys=0.00, real=0.18 secs]

从上面的GC日志片段我们可以了解JVM的信息。

从上面的GC日志可以看出，JVM发生了两次GC事件，第一次是回收新生代，第二次是回收整个堆。

我们来分析minor GC的日志：

1. 2015-05-26T14:45:37.987-0200 – GC 事件开始时间。
2. 151.126 – GC 事件开始相对于JVM启动的时间. 单位秒。
3. GC – 区分Minor & Full GC的标志. 上面的日志表示为 Minor GC。
4. Allocation Failure – 垃圾回收的原因. 此日志表明新生代（Young Generation）没有任何存放得下该数据结构的空间。
5. DefNew – 使用的垃圾回收器的名称. 该垃圾回收器是新生代的单线程标记复制算法，该垃圾回收器会导致stop-the-world。
6. 629119K->69888K – 垃圾回收前后新生代的使用量。
7. (629120K) – 新生代的总量。
8. 1619346K->1273247K – 垃圾回收前后的堆的使用量。
9. (2027264K) – 堆的总量。
10. 0.0585007 secs – 垃圾回收事件的耗时。
11. [Times: user=0.06 sys=0.00, real=0.06 secs] – GC事件的耗时的细化指标:

• user –垃圾回收线程回收垃圾的CPU耗时。
• sys – 操作系统调用和等待操作系统操作的耗时。
• real – 你应用停顿的时间。 Serial Garbage Collector 总是使用的单线程, real time 为user 和 system times时间的总和。

通过上面垃圾回收日志片段的介绍，我们了解了GC事件中内存的变化。

垃圾回收前堆的总使用量为1,619,346K。其中新生代使用量为629,119K。通过这些信息我们可以计算出老年代的使用量990,227k。

垃圾回收后新生代减少了 559,231K（629119K-69888K），堆的总使用量减少了346,099K（ 1619346K-1273247K），可以计算出有 213,132K（559,231K-346,099K）的对象从新生代移动到了老年代。

更多详细内容参见：https://plumbr.io/java-garbage-collection-handbook

原文地址：https://plumbr.io/blog/garbage-collection/understanding-garbage-collection-logs