1、GC日志采集
在服务器上我们需要配置一些参数才能采集到历史的GC日志信息,这些参数通常在项目启动的时候就需要指定,
如果你项目是jar包,可以按照下面方式指定这些GC参数即可。
下面这些参数意思是把GC日志记录到/opt/app/abc-user/ard-user-gc-%t.log 这个文件里,每个文件大小为20M,一共生成5个文件,超过的话则覆盖。
java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:+PrintHeapAtGC -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=20M -Xloggc:/opt/ard-user-gc-%t.log -jar abg-user-1.0-SNAPSHOT.jar
-Xloggc:/opt/app/ard-user/ard-user-gc-%t.log 设置日志目录和日志名称
-XX:+UseGCLogFileRotation 开启滚动生成日志
-XX:NumberOfGCLogFiles=5 滚动GC日志文件数,默认0,不滚动
-XX:GCLogFileSize=20M
GC文件滚动大小,需开启UseGCLogFileRotation
-XX:+PrintGCDetails
开启记录GC日志详细信息(包括GC类型、各个操作使用的时间),并且在程序运行结束打印出JVM的内存占用情况
-XX:+PrintGCDateStamps 记录系统的GC时间
-XX:+PrintGCCause 产生GC的原因(默认开启)
2、Ps+Po日志解析
ParallelScavenge + Parallel Old日志主要会包括下面几类信息:
1、GC类型: 这里会告诉我们产生的是YGC (YGC 代表新生代的GC只会收集Eden区和Survivor )、 还是Full GC(Full GC是针对于整个堆进行搜集)
2、GC产生的原因:这里一般都会告诉我们是因为什么原因导致产生GC,一般通过这里可以分析出具体是因为哪个区域空间不够了导致的GC。
3、回收的情况:这里主要体现出回收的成果,通过数据告诉我们 回收之前的区域对象占用空间大小、回收之后区域对象占用空间的大小 、当前区域的空间大小、回收使用的时长。
下面是一段ParallelScavenge + Parallel Old 组合的 Full GC 日志信息:
下面我们针对一段Full GC日志来逐一对说明对应的内容所表示的信息进行说明。
3、CMS日志解析
如果老年代采用的CMS收集器,那么JVM默认会选择ParNew作为新生代收集器与CMS配合。所以使用CMS后主要是有两种日志类型,一种是ParNew的新生代收集日志,一种是CMS的老年代收集日志。
新生代GC日志(PaNew)
老年代的GC日志(CMS)
CMS日志和之前PS+PO的日志有很大区别,主要是CMS收集机制与之前的收集器不一样,CMS根据阶段来记录GC日志的,GC日志主要分为6个阶段。
//第一阶段 初始标记,CMS的第一个STW阶段,这个阶段会所有的GC Roots进行标记。
2020-10-20T17:04:45.424+0800: 10.756: [GC (CMS Initial Mark) [1 CMS-initial-mark: 68287K(68288K)] 69551K(99008K), 0.0019516 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
解析:CMS Initial Mark 说明该阶段为初始标记阶段,68287K(68288K)当前老年代空间的用量和总量,69551K(99008K)当前堆空间的用量和总量,0.0019516 secs初始化标记所耗费的时间。
//第二阶段并发标记
2020-10-20T17:04:45.426+0800: 10.758: [CMS-concurrent-mark-start]
2020-10-20T17:04:45.519+0800: 10.850: [CMS-concurrent-mark: 0.092/0.092 secs] [Times: user=0.56 sys=0.01, real=0.09 secs]
解析:CMS-concurrent-mark: 0.092/0.092 secs] 并发标记所所耗费的时间
//第三阶段 并发预清理阶段,并发执行的阶段。在本阶段,会查找前一阶段执行过程中,从新生代晋升或新分配或被更新的对象。通过并发地重新扫描这些对象,预清理阶段可以减少重新标记阶段的工作量。
2020-10-20T17:04:45.519+0800: 10.850: [CMS-concurrent-preclean-start]
2020-10-20T17:04:45.598+0800: 10.930: [CMS-concu解析rrent-preclean: 0.080/0.080 secs] [Times: user=0.46 sys=0.00, real=0.08 secs]
解析: [CMS-concurrent-preclean: 0.080/0.080 secs] 预清阶段所使用功能的时间。
//第四阶段 并发可中止的预清理阶段。这个阶段工作和上一个阶段差不多。增加这一阶段是为了让我们可以控制这个阶段的结束时机,比如扫描多长时间(默认5秒)或者Eden区使用占比达到期望比例(默认50%)就结束本阶段。
2020-10-20T17:04:45.599+0800: 10.930: [CMS-concurrent-abortable-preclean-start]
2020-10-20T17:04:45.599+0800: 10.930: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
//第五阶段 重新标记阶段,需要STW,从GC Root开始重新扫描整堆,标记存活的对象。需要注意的是,虽然CMS只回收老年代的垃圾对象,但是这个阶段依然需要扫描新生代,因为很多GC Root都在新生代。
2020-10-20T17:04:45.608+0800: 10.939: [GC (CMS Final Remark) [YG occupancy: 25310 K (30720 K)]2020-10-20T17:04:45.608+0800: 10.939: [Rescan (parallel) , 0.0117481 secs]2020-10-20T17:04:45.620+0800: 10.951: [weak refs processing, 0.0000354 secs]2020-10-20T17:04:45.620+0800: 10.951: [class unloading, 0.0268352 secs]2020-10-20T17:04:45.647+0800: 10.978: [scrub symbol table, 0.0053781 secs]2020-10-20T17:04:45.652+0800: 10.983: [scrub string table, 0.0006005 secs][1 CMS-remark: 68287K(68288K)] 93598K(99008K), 0.0447563 secs] [Times: user=0.18 sys=0.00, real=0.04 secs]
解析:
[YG occupancy: 25310 K (30720 K)] =》 新生代空间占用大小,新生代总大小。
[Rescan (parallel) , 0.0117481 secs] =》 暂停用户线程的情况下完成对所有存活对象的标记,此阶段所花费的时间。
[weak refs processing, 0.0000354 secs] =》第一步 标记处理弱引用;
[class unloading, 0.0033120 secs] =》 第二步,标记那些已卸载未使用的类;
[scrub symbol table, 0.0053781 secs][scrub string table, 0.0004780 secs =》 最后标记未被引用的常量池对象。
[1 CMS-remark: 68287K(68288K)] 93598K(99008K), 0.0447563 secs] =》 重新标记完成后 老年代使用量与总量,堆空间使用量与总量。
[Times: user=0.18 sys=0.00, real=0.04 secs] =》 各个维度的时间消耗。
//第六阶段 并发清理阶段, 对前面标记的所有可回收对象进行回收
2020-10-20T17:04:45.653+0800: 10.984: [CMS-concurrent-sweep-start]
2020-10-20T17:04:45.689+0800: 11.020: [CMS-concurrent-sweep: 0.036/0.036 secs] [Times: user=0.20 sys=0.01, real=0.04 secs]
2020-10-20T17:04:45.689+0800: 11.020: [CMS-concurrent-reset-start]
2020-10-20T17:04:45.689+0800: 11.021: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
解析:
[CMS-concurrent-sweep: 0.036/0.036 secs] 开并发清理所耗费的时间。
[CMS-concurrent-reset: 0.000/0.000 secs] 重置数据和结构信息。
3、G1日志解析
G1会有3种类型的GC,YGC(只会对新生代空间进行GC)、Miexd GC(混合GC,对新生代和部分老年代进行GC)、FGC(Full FC ,对整堆进行GC)。
Young GC日志对新生代内存空间进行回收。
2020-10-20T20:06:24.845+0800: 3.927: [GC pause (G1 Evacuation Pause) (young), 0.0142232 secs] //GC发生的系统时间,GC发生在程序启动后的多少秒后产生的GC。
//该GC产生STW(由对象复制空间不足造成的STW)(发生在young区),整个阶段的耗时。
//下面是整个GC细节过程的耗时情况
[Parallel Time: 12.9 ms, GC Workers: 8] // 开启了8个GC线程
[GC Worker Start (ms): Min: 3926.9, Avg: 3934.2, Max: 3939.7, Diff: 12.8] // 工作线程启动时间
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 2.5, Diff: 2.5, Sum: 2.6] //扫描root的耗时
[Update RS (ms): Min: 0.0, Avg: 0.3, Max: 2.1, Diff: 2.1, Sum: 2.1] //更新RS的耗时
[Processed Buffers: Min: 0, Avg: 1.9, Max: 15, Diff: 15, Sum: 15]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1] //扫描RS的耗时
[Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.6, Diff: 0.6, Sum: 0.6] //
[Object Copy (ms): Min: 0.0, Avg: 4.5, Max: 7.1, Diff: 7.1, Sum: 35.9] //对象拷贝耗时
[Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.5, Diff: 0.5, Sum: 2.9]
[Termination Attempts: Min: 1, Avg: 74.2, Max: 133, Diff: 132, Sum: 594]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 0.0, Avg: 5.5, Max: 12.8, Diff: 12.8, Sum: 44.3]
[GC Worker End (ms): Min: 3939.7, Avg: 3939.7, Max: 3939.8, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 1.1 ms] //其它任务的耗时
[Choose CSet: 0.0 ms] //CSet选择Region的时间
[Ref Proc: 0.7 ms] //处理对象引用的时间
[Ref Enq: 0.0 ms] //引用入ReferenceQueues队列的时间
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms] //释放CSet时间
[Eden: 52.0M(52.0M)->0.0B(52.0M) Survivors: 8192.0K->8192.0K Heap: 74.2M(100.0M)->25.6M(100.0M)]
Eden 回收前用量(总容量)->回收后用量(总容量),Survivors区回收前用量-回收后用量, 堆内存回收前用量(总容量)->回收后用量(总容量)
Miexd GC日志
Miexd GC回收整个新生代和部分老年代。
2020-10-20T20:06:25.068+0800: 4.151: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0076494 secs]
//GC产生STW(Metadata空间不足引起的GC)(initial-mark 说明整个GC属于混合GC,YGC和初始化标记阶段同时进行)。
//下面和YGC一样,是整个GC细节过程的耗时情况,
[Parallel Time: 6.1 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 4150.8, Avg: 4150.9, Max: 4151.0, Diff: 0.1]
[Ext Root Scanning (ms): Min: 0.6, Avg: 2.3, Max: 5.8, Diff: 5.2, Sum: 18.3]
[Update RS (ms): Min: 0.0, Avg: 0.5, Max: 0.8, Diff: 0.8, Sum: 4.2]
[Processed Buffers: Min: 0, Avg: 2.2, Max: 7, Diff: 7, Sum: 18]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3]
[Object Copy (ms): Min: 0.0, Avg: 2.7, Max: 4.2, Diff: 4.2, Sum: 21.8]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 1.3]
[Termination Attempts: Min: 1, Avg: 4.6, Max: 11, Diff: 10, Sum: 37]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 5.8, Avg: 5.8, Max: 5.9, Diff: 0.1, Sum: 46.6]
[GC Worker End (ms): Min: 4156.7, Avg: 4156.7, Max: 4156.7, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 1.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.0 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 50.0M(52.0M)->0.0B(53.0M) Survivors: 8192.0K->7168.0K Heap: 75.1M(100.0M)->28.6M(100.0M)]
Heap after GC invocations=6 (full 0):
garbage-first heap total 102400K, used 29326K [0xdf000000, 0xdf100190, 0xe5400000)
region size 1024K, 7 young (7168K), 7 survivors (7168K)
Metaspace used 16139K, capacity 16346K, committed 16384K, reserved 16688K
}
[Times: user=0.03 sys=0.00, real=0.01 secs]
//初始标记阶段STW
2020-10-20T20:06:25.076+0800: 4.159: [GC concurrent-root-region-scan-start]
2020-10-20T20:06:25.080+0800: 4.162: [GC concurrent-root-region-scan-end, 0.0039639 secs]
//并发标记阶段
2020-10-20T20:06:25.080+0800: 4.163: [GC concurrent-mark-start]
2020-10-20T20:06:25.097+0800: 4.180: [GC concurrent-mark-end, 0.0170679 secs]
//最终标记阶段STW
2020-10-20T20:06:25.098+0800: 4.180: [GC remark 2020-10-20T20:06:25.098+0800: 4.180: [Finalize Marking, 0.0005518 secs] 2020-10-20T20:06:25.098+0800: 4.180: [GC ref-proc, 0.0003269 secs] 2020-10-20T20:06:25.098+0800: 4.181: [Unloading, 0.0040534 secs], 0.0052224 secs]
[Times: user=0.02 sys=0.00, real=0.00 secs]
//筛选回收阶段STW
2020-10-20T20:06:25.103+0800: 4.185: [GC cleanup 32M->30M(100M), 0.0008868 secs]
[Times: user=0.00 sys=0.00, real=0.01 secs]
2020-10-20T20:06:25.104+0800: 4.186: [GC concurrent-cleanup-start]
2020-10-20T20:06:25.104+0800: 4.186: [GC concurrent-cleanup-end, 0.0000233 secs]
字段解析:
[GC cleanup 32M->30M(100M), 0.0008868 secs] 回收前用量->回收之后用量(总容量)
Full GC日志 回收整个堆,包括新生代、老年代、元空间等 。
//回收前内存占情况
Heap before GC invocations=297 (full 0):
garbage-first heap total 102400K, used 102278K [0xdf000000, 0xdf100190, 0xe5400000)
region size 1024K, 0 young (0K), 0 survivors (0K)
Metaspace used 33404K, capacity 33769K, committed 33920K, reserved 34096K]
字段解析:
heap total 102400K used 102278K [0xdf000000, 0xdf100190, 0xe5400000) => 堆空间总大小 已使用大小
内存空间开始位置、已使用空间位置,结束位置。
region size 1024K, 0 young (0K), 0 survivors (0K) => 单个region 大小,
Metaspace used 33404K, capacity 33769K, committed 33920K, reserved 34096K]
//FGC 详情
2020-10-20T20:06:34.447+0800: 13.529: [Full GC (Allocation Failure) 99M->74M(100M), 0.3039405 secs]
[Eden: 0.0B(5120.0K)->0.0B(13.0M) Survivors: 0.0B->0.0B Heap: 99.9M(100.0M)->74.0M(100.0M)], [Metaspace: 33404K->33307K(34096K)]
字段解析:
[Full GC (Allocation Failure) =》 GC类型为Full GC, 原因是分配内存失败导致的Full GC。
99M->74M(100M), 0.3039405 secs] =》 回收前堆内空间占用量,回收后堆内存占用量(堆内存总量),耗费时间。
[Eden: 0.0B(5120.0K)->0.0B(13.0M) =》 回收前eden区空间用量(总量),回收后Eden区空间用量(总量)。
Survivors: 0.0B->0.0B =》 回收前Survivorsn区空间用量),回收后Survivors区空间用量)。
Heap: 99.9M(100.0M)->74.0M(100.0M)] =》 回收前堆空间用量(总量),回收后堆空间用量(总量)
[Metaspace: 33404K->33307K(34096K)] =》 回收前元数据空间用量,回收后元数据空间用量(总量)
//回收后内存占用情况
Heap after GC invocations=298 (full 1):
garbage-first heap total 102400K, used 75785K [0xdf000000, 0xdf100190, 0xe5400000)
region size 1024K, 0 young (0K), 0 survivors (0K)
Metaspace used 33307K, capacity 33649K, committed 33920K, reserved 34096K
}