GC Log Analyzing - tenji/ks GitHub Wiki
GC日志分析
始终在生产环境开启GC日志是一个很好的实践，因为它不会对Weblogic服务器或其他应用程序服务器的性能造成任何资源开销或任何副作用。GC日志有助于我们排查现网问题，除此之外，它还有助于我们根据垃圾收集的统计信息来确定是否有优化的空间。
一、Minor GC vs Major GC vs Full GC
1.1 Minor GC
从 Young space（包括 Eden 和 Survivor spaces）收集垃圾称为 Minor GC。
1.2 Major GC vs Full GC
- Major GC 只清理 Tenured space.
- Full GC 清理整个堆内存 – 包括 Young 和 Tenured spaces.
二、GC日志输出配置
-Xloggc:D:/gcLogs/GCLogs.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
三、GC日志解析
4.636: [GC [PSYoungGen: 230400K->19135K(268800K)] 230400K->19135K(2058752K), 0.0635710 secs] [Times: user=0.08 sys=0.01, real=0.06 secs]
7.302: [GC [PSYoungGen: 249535K->38396K(268800K)] 249535K->51158K(2058752K), 0.0777300 secs] [Times: user=0.21 sys=0.04, real=0.07 secs]
7.521: [GC [PSYoungGen: 49735K->38388K(268800K)] 62496K->51933K(2058752K), 0.0741680 secs] [Times: user=0.15 sys=0.04, real=0.07 secs]
7.595: [Full GC (System) [PSYoungGen: 38388K->0K(268800K)] [PSOldGen: 13545K->51794K(1789952K)] 51933K->51794K(2058752K) [PSPermGen: 19868K->19868K(39936K)], 0.3066610 secs] [Times: user=0.28 sys=0.02, real=0.31 secs]
9.752: [GC [PSYoungGen: 230400K->26206K(268800K)] 282194K->78000K(2058752K), 0.0728380 secs] [Times: user=0.15 sys=0.00, real=0.08 secs]
11.906: [GC [PSYoungGen: 256606K->38393K(268800K)] 308400K->94759K(2058752K), 0.1058920 secs] [Times: user=0.19 sys=0.00, real=0.10 secs]
13.480: [GC [PSYoungGen: 268793K->38394K(268800K)] 325159K->109054K(2058752K), 0.0762360 secs] [Times: user=0.20 sys=0.03, real=0.08 secs]
18.115: [GC [PSYoungGen: 268794K->38384K(268800K)] 339454K->179238K(2058752K), 0.1351350 secs] [Times: user=0.42 sys=0.10, real=0.14 secs]
20.860: [GC [PSYoungGen: 268784K->38394K(268800K)] 409638K->200343K(2058752K), 0.1063430 secs] [Times: user=0.29 sys=0.03, real=0.11 secs]
22.148: [GC [PSYoungGen: 268794K->38399K(268800K)] 430743K->221395K(2058752K), 0.1173980 secs] [Times: user=0.24 sys=0.02, real=0.12 secs]
23.357: [GC [PSYoungGen: 268799K->26775K(268800K)] 451795K->231618K(2058752K), 0.0714130 secs] [Times: user=0.15 sys=0.03, real=0.08 secs]
24.449: [GC [PSYoungGen: 257175K->29170K(268800K)] 462018K->239909K(2058752K), 0.0312400 secs] [Times: user=0.06 sys=0.01, real=0.04 secs]
Point-1). [Full GC (System) [PSYoungGen: 38388K->0K(268800K)] It means a Full GC is happening on the complete Heap Area including all the Areas of the Java Heap Space.
Point-2). [GC [PSYoungGen: 230400K->19135K(268800K)] Indicates some small GCs which keep on happening in the young generation very frequently,This garbage collection cleans the Young Generation short living Objects.
Point-3). Meaning of the [GC [PSYoungGen: 230400K->19135K(268800K)] line is around 256MB (268800K) is the Young Generation Size, Before Garbage Collection in young generation the heap utilization in Young Generation area was around 255MB (230400K) and after garbage collection it reduced up to 18MB (19135K)
Point-4). Same thing we can see for Full Garbage collection as well….How effective the Garbage collection was…[Full GC (System) [PSYoungGen: 38388K->0K(268800K)] [PSOldGen: 13545K->51794K(1789952K)] Here it says that around [(old)1789952K + young (268800K) ] memory space means OldGeneration is consuming 1.75GB space and Young Generation is consuming around 255 MB space So it means total Heap size is around 2GB.
四、garbagecat工具分析
-
下载garbagecat-1.0.0.jar文件，下载链接
-
执行以下命令，生成日志分析结果
$ java -jar garbagecat-1.0.0.jar GCLog.log -
生成的文件列表
garbagecat-1.0.0.jar GCLog.log gcdb.lck gcdb.log gcdb.properties report.txt -
打开report.txt结果文件，可以看到以下内容：
======================================== SUMMARY: ======================================== # GC Events: 12 GC Event Types: PARALLEL_SCAVENGE, PARALLEL_SERIAL_OLD Max Heap Space: 2058752K Max Heap Occupancy: 462018K Max Perm Space: 39936K Max Perm Occupancy: 19868K Throughput: 95% Max Pause: 306 ms Total Pause: 1233 ms First Timestamp: 4636 ms Last Timestamp: 24449 ms ========================================如果看到GC的Max Pause时间非常高，比如对于2 GB堆，超过5-7秒，那么就需要引起关注了。