java gc日志分析 在线_jvm gc日志分析 - leandison的个人空间 - OSCHINA - 中文开源技术交流社区...

下面是一次gc的日志，例子为spring cloud的一个例子。

vm参数为: -XX:+PrintGCTimeStamps -XX:+PrintGCDetails  -Xloggc:./gc.log

Java HotSpot(TM) 64-Bit Server VM (25.101-b13) for windows-amd64 JRE (1.8.0_101-b13), built on Jun 22 2016 01:21:29 by "java_re" with MS VC++ 10.0 (VS2010)

Memory: 4k page, physical 8272172k(3380068k free), swap 8797204k(2644852k free)

CommandLine flags: -XX:InitialHeapSize=132354752 -XX:MaxHeapSize=2117676032 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC

2.751: [GC (Allocation Failure) [PSYoungGen: 33280K->4773K(38400K)] 33280K->4789K(125952K), 0.0066140 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

3.293: [GC (Allocation Failure) [PSYoungGen: 38053K->5092K(38400K)] 38069K->5949K(125952K), 0.0082336 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

4.025: [GC (Allocation Failure) [PSYoungGen: 38372K->5102K(38400K)] 39229K->7263K(125952K), 0.0072192 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

4.737: [GC (Allocation Failure) [PSYoungGen: 38382K->5112K(38400K)] 40543K->8830K(125952K), 0.0089910 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

4.951: [GC (GCLocker Initiated GC) [PSYoungGen: 16771K->5102K(38400K)] 20489K->9814K(125952K), 0.0105038 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

5.012: [GC (Metadata GC Threshold) [PSYoungGen: 8511K->5454K(74240K)] 13222K->10174K(161792K), 0.0178638 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]

5.030: [Full GC (Metadata GC Threshold) [PSYoungGen: 5454K->0K(74240K)] [ParOldGen: 4719K->5860K(45568K)] 10174K->5860K(119808K), [Metaspace: 21238K->21238K(1069056K)], 0.0532280 secs] [Times: user=0.09 sys=0.02, real=0.05 secs]

7.911: [GC (Allocation Failure) [PSYoungGen: 66560K->4324K(74240K)] 72420K->10192K(119808K), 0.0137975 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

9.539: [GC (Allocation Failure) [PSYoungGen: 70884K->5910K(128000K)] 76752K->11779K(173568K), 0.0349993 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]

12.213: [GC (Allocation Failure) [PSYoungGen: 127766K->7660K(129536K)] 133635K->21046K(175104K), 0.0232323 secs] [Times: user=0.09 sys=0.00, real=0.02 secs]

15.178: [GC (Allocation Failure) [PSYoungGen: 129516K->11252K(188416K)] 142902K->28199K(233984K), 0.0394675 secs] [Times: user=0.16 sys=0.02, real=0.04 secs]

16.501: [GC (Metadata GC Threshold) [PSYoungGen: 55917K->2795K(190976K)] 72864K->27401K(236544K), 0.0207687 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

16.522: [Full GC (Metadata GC Threshold) [PSYoungGen: 2795K->0K(190976K)] [ParOldGen: 24606K->22167K(77824K)] 27401K->22167K(268800K), [Metaspace: 35514K->35514K(1081344K)], 0.1595452 secs] [Times: user=0.44 sys=0.00, real=0.16 secs]

20.103: [GC (Allocation Failure) [PSYoungGen: 177152K->8830K(256512K)] 199319K->31005K(334336K), 0.0269517 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]

gc日志可以看见gc的次数非常频繁，暂时不考虑调优，进行分析.挑选第一条

2.751(时间戳): [GC (Allocation Failure) [PSYoungGen(垃圾回收器默认为Parallel Scavenge): 33280K(回收前年轻代已用堆空间大小)->4773K(gc后年轻代已用堆空间大小)(38400K 当前可使用的堆空间大小)] 33280K(回收前整个堆已用堆空间)->4789K(回收后可用堆空间大小)(125952K(整个堆大小)), 0.0066140 secs] [Times: user=0.00(用户状态cpu时间) sys=0.00(系统cpu), real=0.01(实际消耗) secs]

挑选full gc那一条

16.522: [Full GC (Metadata GC Threshold) [PSYoungGen: 2795K->0K(190976K)] [ParOldGen: 24606K->22167K(77824K)] 27401K->22167K(268800K), [Metaspace: 35514K->35514K(1081344K)], 0.1595452 secs] [Times: user=0.44 sys=0.00, real=0.16 secs]

大同小异，full gc回收了 年轻代、老年代以及元数据区Metaspace(jdk1.8前是永久区)