GC 日志分析 - Serial GC（串行 GC）

[bingoogolapple]

• java -jar -Xms2g -Xmx2g -Xss256k -XX:+UseSerialGC -Xloggc:./log/SerialGC.log -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails build/libs/tuning-1.0.jar

Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for bsd-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:32:22 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 8388608k(212688k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ThreadStackSize=256 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseSerialGC

2017-07-27T13:50:34.741-0800: 2.379: [GC (Allocation Failure)
  2017-07-27T13:50:34.741-0800: 2.379: [DefNew: 559232K->69888K(629120K), 1.4259384 secs]
  559232K->527812K(2027264K),
1.4261279 secs]
[Times: user=0.21 sys=0.64, real=1.42 secs]

2017-07-27T13:50:36.830-0800: 4.467: [GC (Allocation Failure)
 2017-07-27T13:50:36.830-0800: 4.467: [DefNew: 629120K->69862K(629120K), 1.0482919 secs]
 1087044K->1075373K(2027264K),
1.0484195 secs]
[Times: user=0.24 sys=0.47, real=1.04 secs]

2017-07-27T13:50:39.020-0800: 6.658: [GC (Allocation Failure)
  2017-07-27T13:50:39.020-0800: 6.658: [DefNew: 629094K->629094K(629120K), 0.0000261 secs]
  2017-07-27T13:50:39.020-0800: 6.658: [Tenured: 1005511K->1352301K(1398144K), 2.9364904 secs]
  1634605K->1352301K(2027264K),
  [Metaspace: 3143K->3143K(1056768K)],
2.9381694 secs]
[Times: user=0.54 sys=1.19, real=2.93 secs]

2017-07-27T13:50:42.085-0800: 9.722: [GC (Allocation Failure)
  2017-07-27T13:50:42.085-0800: 9.722: [DefNew: 559232K->559232K(629120K), 0.0000406 secs]
  2017-07-27T13:50:42.085-0800: 9.722: [Tenured: 1352301K->1398042K(1398144K), 1.5665746 secs]
  1911533K->1505982K(2027264K),
  [Metaspace: 3144K->3144K(1056768K)],
1.5667670 secs]
[Times: user=0.66 sys=0.06, real=1.57 secs]

2017-07-27T13:50:43.887-0800: 11.524: [Full GC (Allocation Failure)
  2017-07-27T13:50:43.887-0800: 11.525: [Tenured: 1398042K->1397963K(1398144K), 0.8454010 secs]
  2026966K->1598176K(2027264K),
  [Metaspace: 3145K->3145K(1056768K)],
0.8455380 secs]
[Times: user=0.59 sys=0.01, real=0.85 secs]

2017-07-27T13:50:44.824-0800: 12.462: [Full GC (Allocation Failure)
  2017-07-27T13:50:44.825-0800: 12.462: [Tenured: 1397963K->1398079K(1398144K), 0.6756190 secs]
  2027040K->1649395K(2027264K),
  [Metaspace: 3145K->3145K(1056768K)],
0.6757408 secs]
[Times: user=0.55 sys=0.02, real=0.68 secs]

2017-07-27T13:50:46.323-0800: 13.960: [Full GC (Allocation Failure)
  2017-07-27T13:50:46.323-0800: 13.960: [Tenured: 1398079K->1398138K(1398144K), 0.5022550 secs]
  2027056K->1729295K(2027264K),
  [Metaspace: 3158K->3158K(1056768K)],
0.5024000 secs]
[Times: user=0.47 sys=0.01, real=0.50 secs]

2017-07-27T13:50:47.519-0800: 15.156: [Full GC (Allocation Failure)
  2017-07-27T13:50:47.519-0800: 15.156: [Tenured: 1398138K->1397989K(1398144K), 0.6711842 secs]
  2027166K->1852817K(2027264K),
  [Metaspace: 3158K->3158K(1056768K)],
0.6713084 secs]
[Times: user=0.49 sys=0.01, real=0.68 secs]

Heap
 def new generation   total 629120K, used 495211K [0x0000000740000000, 0x000000076aaa0000, 0x000000076aaa0000)
  eden space 559232K,  88% used [0x0000000740000000, 0x000000075e39af20, 0x0000000762220000)
  from space 69888K,   0% used [0x0000000762220000, 0x0000000762220000, 0x0000000766660000)
  to   space 69888K,   0% used [0x0000000766660000, 0x0000000766660000, 0x000000076aaa0000)
 tenured generation   total 1398144K, used 1397989K [0x000000076aaa0000, 0x00000007c0000000, 0x00000007c0000000)
   the space 1398144K,  99% used [0x000000076aaa0000, 0x00000007bffd96d0, 0x00000007bffd9800, 0x00000007c0000000)
 Metaspace       used 3174K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 354K, capacity 386K, committed 512K, reserved 1048576K

[bingoogolapple]

取正数第二条来分析

2017-07-27T13:50:36.830-0800: 4.467: [GC (Allocation Failure)
 2017-07-27T13:50:36.830-0800: 4.467: [DefNew: 629120K->69862K(629120K), 1.0482919 secs]
 1087044K->1075373K(2027264K),
1.0484195 secs]
[Times: user=0.24 sys=0.47, real=1.04 secs]

2017-07-27T13:50:36.830-0800（开始垃圾收集时的当前时间戳）: 4.467（JVM 启动后经过的时间，单位为秒）: [GC (Allocation Failure（导致 GC 的原因，这里是分配内存失败导致的）)
 2017-07-27T13:50:36.830-0800: 4.467: [DefNew（Serial GC 年轻代内存区域名称，串行，单线程，标记-复制 Mark-Copy，STW）: 629120K（GC 前年轻代的使用量）->69862K（GC 后年轻代的使用量）(629120K（年轻代总大小）), 1.0482919（年轻代 GC 所占用的时间） secs]
 1087044K（GC 前整个堆的使用量）->1075373K（GC 后整个堆的使用量）(2027264K（整个堆的总大小）),
1.0484195（本次 GC 的总时间） secs]
[Times: user=0.24（用户消耗的 CPU 时间） sys=0.47（系统消耗的 CPU 时间）, real=1.04（操作从开始到结束所经过的墙钟时间） secs]

• 单线程，real 约等于 user 与 sys 的和
• 此次 GC 之前，堆内存总的使用量为 1,087,044K。其中年轻代使用了 629,120K。可以算出老年代使用量为 457,924K
• 此次 GC 之后，年轻代的使用量减少了 559,258K，但整个堆内存的使用量只下降了 11,671K。从中可以算出有 547,587K 的对象从年轻代提升到了老年代

[bingoogolapple]

取正数第四条来分析

2017-07-27T13:50:42.085-0800: 9.722: [GC (Allocation Failure)
  2017-07-27T13:50:42.085-0800: 9.722: [DefNew: 559232K->559232K(629120K), 0.0000406 secs]
  2017-07-27T13:50:42.085-0800: 9.722: [Tenured: 1352301K->1398042K(1398144K), 1.5665746 secs]
  1911533K->1505982K(2027264K),
  [Metaspace: 3144K->3144K(1056768K)],
1.5667670 secs]
[Times: user=0.66 sys=0.06, real=1.57 secs]

2017-07-27T13:50:42.085-0800（开始垃圾收集时的当前时间戳）: 9.722（JVM 启动后经过的时间，单位为秒）: [GC (Allocation Failure（导致 GC 的原因，这里是分配内存失败导致的）)
  2017-07-27T13:50:42.085-0800: 9.722: [DefNew（Serial GC 年轻代内存区域名称，串行，单线程，标记-复制 Mark-Copy，STW）: 559232K（GC 前年轻代的使用量）->559232K（GC 后年轻代的使用量）(629120K（年轻代总大小）), 0.0000406（年轻代 GC 所占用的时间） secs]
  2017-07-27T13:50:42.085-0800: 9.722: [Tenured（Serial GC 老年代内存区域名称，串行，单线程，标记-清除-整理 Mark-Sweep-Compact，STW）: 1352301K（GC 前老年代的使用量）->1398042K（GC 后老年代的使用量）(1398144K（老年代代总大小）), 1.5665746（老年代 GC 所占用的时间） secs]
  1911533K（GC 前整个堆的使用量）->1505982K（GC 后整个堆的使用量）(2027264K（整个堆的总大小）),
  [Metaspace: 3144K->3144K(1056768K)],
1.5667670（本次 GC 的总时间） secs]
[Times: user=0.66 sys=0.06, real=1.57 secs]