java虚拟机--GC日志分析

Posted 2022-04-15 huigelaile

打印日志相关参数：

-XX:+PrintGCDetails

-XX:PrintGCTimestamps

-XX:PrintGCDateStamps

-Xloggc:$CATALINA_HOME/logs/gc.log

-XX:+PrintHeapAtGC

-XX:+PrintTenuringDistriution：发生GC的时候，把Young区中对象的年龄打印出来

其余的参数应该能直接看懂的，就不解释了。

Parallel日志：

默认情况下，都是使用Parallel收集器

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

打开gc.log文件：

#虚拟机版本、jdk版本、Linux内核
Java HotSpot(TM) 64-Bit Server VM (25.102-b14) for linux-amd64 JRE (1.8.0_102-b14), built on Jun 22 2016 18:43:17 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 3880412k(1678252k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=62086592 -XX:MaxHeapSize=993385472 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2019-07-15T10:38:52.441+0800: 0.654: [GC (Allocation Failure) [PSYoungGen: 15360K->2544K(17920K)] 15360K->4022K(58880K), 0.0074512 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-07-15T10:38:52.942+0800: 1.155: [GC (Allocation Failure) [PSYoungGen: 17904K->2554K(33280K)] 19382K->7383K(74240K), 0.0171215 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2019-07-15T10:38:53.359+0800: 1.572: [GC (Allocation Failure) [PSYoungGen: 33274K->2554K(33280K)] 38103K->11504K(74240K), 0.0143284 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-07-15T10:38:53.500+0800: 1.713: [GC (Allocation Failure) [PSYoungGen: 33274K->2554K(64000K)] 42224K->14443K(104960K), 0.0129043 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-07-15T10:38:53.788+0800: 2.000: [GC (Allocation Failure) [PSYoungGen: 63994K->2554K(64000K)] 75883K->23497K(104960K), 0.0179449 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 
2019-07-15T10:38:54.041+0800: 2.253: [GC (Allocation Failure) [PSYoungGen: 63994K->11256K(131584K)] 84937K->33580K(172544K), 0.0177155 secs] [Times: user=0.02 sys=0.01, real=0.02 secs] 
2019-07-15T10:38:54.500+0800: 2.713: [GC (Allocation Failure) [PSYoungGen: 131576K->13815K(134144K)] 153900K->43739K(175104K), 0.0276207 secs] [Times: user=0.03 sys=0.02, real=0.03 secs] 
2019-07-15T10:38:55.513+0800: 3.726: [GC (Metadata GC Threshold) [PSYoungGen: 115110K->10443K(258560K)] 145034K->40823K(299520K), 0.0227380 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2019-07-15T10:38:55.536+0800: 3.748: [Full GC (Metadata GC Threshold) [PSYoungGen: 10443K->0K(258560K)] [ParOldGen: 30380K->28896K(59392K)] 40823K->28896K(317952K), [Metaspace: 20720K->20720K(1069056K)], 0.0819349 secs] [Times: user=0.14 sys=0.00, real=0.09 secs] 
2019-07-15T10:38:58.060+0800: 6.272: [GC (Allocation Failure) [PSYoungGen: 240640K->15826K(259584K)] 269536K->44730K(318976K), 0.0444735 secs] [Times: user=0.08 sys=0.01, real=0.04 secs] 
2019-07-15T10:38:58.842+0800: 7.054: [GC (Metadata GC Threshold) [PSYoungGen: 113863K->8488K(303616K)] 142768K->37401K(363008K), 0.0197353 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2019-07-15T10:38:58.861+0800: 7.074: [Full GC (Metadata GC Threshold) [PSYoungGen: 8488K->0K(303616K)] [ParOldGen: 28912K->15427K(55296K)] 37401K->15427K(358912K), [Metaspace: 33955K->33955K(1081344K)], 0.1084317 secs] [Times: user=0.19 sys=0.00, real=0.11 secs] 
　

　　

　

GC日志：

DefNew：default new generation

PSYoungGen：Parallel Scavenge generation

ParNew：Parallel New Generation

老年代和永久带同理，名称也是由收集器决定

 

说明：

最前面的数字代表GC发生的时间，jvm启动经过的秒数

Full GC 证明这次GC发生了GC停顿，如果是调用了system.gc()，就会显示Full GC(system)

[PSYoungGen: 33280K->2415K(38400K)] 33280K->2423K(125952K), 0.0109733 secs]

33280K->2415K(38400K)：GC前该内存区域已使用容量->GC后。。。。(该内存区域总容量)

33280K->2423K(125952K)：堆的容量

0.0109733 secs：GC时间

[Times: user=0.02 sys=0.00, real=0.01 secs] ：分别代表用户态消耗的CPU时间、内核态消耗的CPU时间、操作从开始到结束经过的墙钟事件

CPU时间和墙钟时间区别：

墙钟时间包含多种非运算的等待耗时，例如等待磁盘IO、等待线程阻塞

CPU时间不包含这些耗时，多CPU或多核，会叠加这些CPU时间

 

Minor GC 对年轻代进行回收，

Major GC 是清理老年代。

Full GC 是清理整个堆空间—包括年轻代和老年代。

Minor GC触发条件：当Eden区满时，触发Minor GC。