GC日志格式

两款GC工具

在线工具：https://gceasy.io/

GCViewer

评价垃圾回收期重要指标

吞吐量

响应时间

打印日志相关参数

##打印GC详细信息

-XX:+PrintGCDetails

##打印CG发生的时间戳

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps     

##日志文件的输出路径

-Xloggc:../logs/gc.log

##在进行GC的前后打印出堆的信息

-XX:+PrintHeapAtGC

##对象年龄

-XX:+PrintTenuringDistribution

日志格式

ParallelGC

##设置catalina.sh

JAVA_OPTS="$JAVA_OPTS -XX:+UseParallelGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:/opt/gc.log"

##内存信息

Memory: 4k page, physical 1918128k(410384k free), swap 2064380k(2064312k free)

##命令行参数（堆分配的大小是自适应，根据内存情况分配）

CommandLine flags: -XX:InitialHeapSize=16777216 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseParallelGC

#young GC

2019-09-17T01:04:35.719-0700: 0.254: [GC (Allocation Failure) [PSYoungGen: 4352K->504K(4864K)] 4352K->1446K(15872K), 0.0048177 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

--日期时间格式

--[PSYoungGen: 4352K->504K(4864K)] ：young区的gc

----4352K：垃圾回收前young区的大小

----504K：垃圾回收后young区的大小

----(4864K)：young区的总大小

--4352K->1446K(15872K)

----4352K：垃圾回收前堆的大小

----1446k：垃圾回收后堆的大小

----(15872K)：整个堆的总大小

--0.0048177 secs：垃圾回收所用到的时间

有1446K-504K=941k的对象晋升到old区

# Full GC

2019-09-17T01:05:01.620-0700: 26.156: [Full GC (Ergonomics) [PSYoungGen: 504K->0K(17920K)] [ParOldGen: 11733K->10548K(20736K)] 12237K->10548K(38656K), [Metaspace: 9151K->9151K(9520K)], 0.0408441 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

ConcMarkSweepGC

##设置catalina.sh

JAVA_OPTS="$JAVA_OPTS -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:/opt/gc.log"

##内存信息

Memory: 4k page, physical 1918128k(412044k free), swap 2064380k(2064312k free)

##命令行参数

-XX:InitialHeapSize=16777216 -XX:MaxHeapSize=268435456 -XX:MaxNewSize=67108864 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseConcMarkSweepGC -XX:+UseParNewGC

-- MaxTenuringThreshold：从young晋升到old，需要达到年龄是6

#young gc

2019-09-17T02:01:46.255-0700: 0.241: [GC (Allocation Failure) 0.241: [ParNew: 4416K->511K(4928K), 0.0084491 secs] 4416K->1487K(15872K), 0.0085234 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

#old gc

2019-09-17T02:01:46.964-0700: 0.951: [GC (CMS Initial Mark) [1 CMS-initial-mark: 9452K(10944K)] 10676K(15872K), 0.0010510 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

--9452K(10944K):CMS在标记时old区占9452k,最大是10944K

--10676K(15872K):整个堆是15872K，现在占用10676K

G1GC

##设置catalina.sh

JAVA_OPTS="$JAVA_OPTS -XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:/opt/gc.log"

##内存信息

Memory: 4k page, physical 1918128k(408276k free), swap 2064380k(2064312k free)

##命令行参数

-XX:InitialHeapSize=16777216 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseG1GC

#young gc

2019-09-17T18:31:31.618-0700: 0.415:

[GC pause (G1 Evacuation Pause) (young), 0.0052778 secs]

   [Parallel Time: 4.8 ms, GC Workers: 1]//启动一个worker并发线程

      [GC Worker Start (ms):  415.4] //开始的时间点

      [Ext Root Scanning (ms):  1.2] //根节点扫描

      [Update RS (ms):  0.2]

      [Processed Buffers:  5]

      [Scan RS (ms):  0.0]

      [Code Root Scanning (ms):  0.1]

      [Object Copy (ms):  3.3]

      [Termination (ms):  0.0]

      [GC Worker Other (ms):  0.0]

      [GC Worker Total (ms):  4.8]

      [GC Worker End (ms):  420.2]

   [Code Root Fixup: 0.0 ms]

   [Code Root Migration: 0.1 ms]

   [Clear CT: 0.0 ms]

   [Other: 0.3 ms]

      [Choose CSet: 0.0 ms]

      [Ref Proc: 0.3 ms]

      [Ref Enq: 0.0 ms]

      [Free CSet: 0.0 ms]

   [Eden: 5120.0K(5120.0K)->0.0B(8192.0K) Survivors: 1024.0K->1024.0K Heap: 7000.5K(16.0M)->2929.8K(16.0M)]

……

   [Eden: 8192.0K(8192.0K)->0.0B(6144.0K) Survivors: 1024.0K->2048.0K Heap: 10.9M(16.0M)->5632.0K(16.0M)]

 [Times: user=0.01 sys=0.00, real=0.01 secs]

--Eden区从5120.0K变成了0(全部回收），Eden区下一步准备扩展到8192.0K，再次触发回收

-- Survivors区从1024.0K->1024.0K

-- Heap区的占用从7000.5K->2929.8K,整个堆的大小是16.0M

##global concurrent marking（全局并发标志）

--查看InitiatingHeapOccupancyPercent

[root@storm-nimbus-a ~]# jinfo -flag InitiatingHeapOccupancyPercent 11617

-XX:InitiatingHeapOccupancyPercent=45

[Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 1024.0K->1024.0K Heap: 11.5M(16.0M)->8704.0K(16.0M)]

--8704.0K(16.0M)已经超过了45%

2019-09-17T18:31:32.026-0700: 0.824: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0063935 secs]

……

2019-09-17T18:32:06.585-0700: 35.383: [GC concurrent-root-region-scan-start]

2019-09-17T18:32:06.586-0700: 35.384: [GC concurrent-root-region-scan-end, 0.0013367 secs]

2019-09-17T18:32:06.586-0700: 35.384: [GC concurrent-mark-start]

2019-09-17T18:32:06.614-0700: 35.411: [GC concurrent-mark-end, 0.0271411 secs]

2019-09-17T18:32:06.617-0700: 35.415: [GC remark 35.415: [GC ref-proc, 0.0001415 secs], 0.0018118 secs]

 [Times: user=0.00 sys=0.00, real=0.00 secs]

2019-09-17T18:32:06.619-0700: 35.417: [GC cleanup 32M->26M(52M), 0.0002043 secs]

 [Times: user=0.00 sys=0.00, real=0.00 secs]

2019-09-17T18:32:06.619-0700: 35.417: [GC concurrent-cleanup-start]

2019-09-17T18:32:06.619-0700: 35.417: [GC concurrent-cleanup-end, 0.0000142 secs]

##MixedGC[G1HeapWastePercent]

在global concurrent marking结束之后，可以知道区有多少空间要被回收，在每次YGC之后和再次发生MixedGC之前，会检查垃圾占比是否达到此参数，只有达到了，下次才会发生Mixed GC

2019-09-17T18:32:08.948-0700: 37.746: [GC pause (G1 Evacuation Pause) (mixed), 0.0076251 secs]