两款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]