JVM虚拟机GC日志样例解读

Posted 2020-11-16 clarino

近期查看产品日志，看到如下GC日志，收集整理如下

Tomcat垃圾回收日志（tomcat-gc*.log）

2019-09-29T06:01:00.041+0800: 1310458.865: [GC (Allocation Failure) 2019-09-29T06:01:00.041+0800: 1310458.866: [ParNew: 366307K->2255K(386880K), 0.0214515 secs] 1016409K->652361K(1369920K), 0.0227310 secs] [Times: user=0.15 sys=0.00, real=0.02 secs] 
Heap after GC invocations=4674 (full 3):
 par new generation   total 386880K, used 2255K [0x00000000ab000000, 0x00000000c4000000, 0x00000000c4000000)
  eden space 364160K,   0% used [0x00000000ab000000, 0x00000000ab000000, 0x00000000c13a0000)
  from space 22720K,   9% used [0x00000000c13a0000, 0x00000000c15d3c00, 0x00000000c29d0000)
  to   space 22720K,   0% used [0x00000000c29d0000, 0x00000000c29d0000, 0x00000000c4000000)
 concurrent mark-sweep generation total 983040K, used 650106K [0x00000000c4000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 386387K, capacity 391928K, committed 392064K, reserved 1390592K
  class space    used 49137K, capacity 50188K, committed 50304K, reserved 1048576K
}
{Heap before GC invocations=4674 (full 3):
 par new generation   total 386880K, used 366415K [0x00000000ab000000, 0x00000000c4000000, 0x00000000c4000000)
  eden space 364160K, 100% used [0x00000000ab000000, 0x00000000c13a0000, 0x00000000c13a0000)
  from space 22720K,   9% used [0x00000000c13a0000, 0x00000000c15d3c00, 0x00000000c29d0000)
  to   space 22720K,   0% used [0x00000000c29d0000, 0x00000000c29d0000, 0x00000000c4000000)
 concurrent mark-sweep generation total 983040K, used 650106K [0x00000000c4000000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 386387K, capacity 391928K, committed 392064K, reserved 1390592K
  class space    used 49137K, capacity 50188K, committed 50304K, reserved 1048576K

TODO:结合如下内容对上述日志进行解读

参考外网的解读
[GC (Allocation Failure) [ParNew: 367523K->1293K(410432K), 0.0023988 secs] 522739K->156516K(1322496K), 0.0025301 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

字段	说明
GC	表明进行了一次垃圾回收，前面没有Full修饰，表明这是一次Minor GC,注意它不表示只GC新生代，并且现有的不管是新生代还是老年代都会STW（Stop the World。
Allocation Failure：	表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。
ParNew	表明本次GC发生在年轻代并且使用的是ParNew垃圾收集器。ParNew是一个Serial收集器的多线程版本，会使用多个CPU和线程完成垃圾收集工作（默认使用的线程数和CPU数相同，可以使用-XX：ParallelGCThreads参数限制）。该收集器采用复制算法回收内存，期间会停止其他工作线程，即Stop The World。
367523K->1293K(410432K)	GC前该内存区域(这里是年轻代)使用容量，GC后该内存区域使用容量，该内存区域总容量。
0.0023988 secs	该内存区域GC耗时，单位是秒
522739K->156516K(1322496K)	三个参数分别为：堆区垃圾回收前的大小，堆区垃圾回收后的大小，堆区总大小。
0.0025301 secs	该内存区域GC耗时，单位是秒
[Times: user=0.04 sys=0.00, real=0.01 secs]	分别表示用户态耗时，内核态耗时和总耗时

• 分析下可以得出结论：
  该次GC新生代减少了367523-1293=366239K
  Heap区总共减少了522739-156516=366223K
  366239 – 366223 =16K，说明该次共有16K内存从年轻代移到了老年代，可以看出来数量并不多，说明都是生 命周期短的对象，只是这种对象有很多。