为了了解垃圾回收日志的内容,分析从众够得到哪些有用的信息。我们需要添加如下启动参数:
-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的日志:
2015-05-26T14:45:37.987-0200 – GC 事件开始时间。
151.126 – GC 事件开始相对于JVM启动的时间. 单位秒。
GC – 区分Minor & Full GC的标志. 上面的日志表示为 Minor GC。
Allocation Failure – 垃圾回收的原因. 此日志表明新生代(Young Generation)没有任何存放得下该数据结构的空间。
DefNew – 使用的垃圾回收器的名称. 该垃圾回收器是新生代的单线程标记复制算法,该垃圾回收器会导致stop-the-world。
629119K->69888K – 垃圾回收前后新生代的使用量。
(629120K) – 新生代的总量。
1619346K->1273247K – 垃圾回收前后的堆的使用量。
(2027264K) – 堆的总量。
0.0585007 secs – 垃圾回收事件的耗时。
[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