• verbose命令
• JVM启动参数启用verbose GC
  • JVM启动参数配置
    • log解析
    • 年轻代空间分析
    • 年老代空间分析
    • 方法区空间分析
    • Java堆分解分析

基于JDK7

verbose命令

Java -verbose:gc中参数-verbose:gc表示输出虚拟机中GC的详细情况。
使用后输出如下：[Full GC 168K->97K(1984K)，0.0253873 secs]
解读如下：箭头前后的数据168K和97K分别表示垃圾收集GC前后所有存活对象使用的内存容量，说明有168K-97K=71K的对象容量被回收，括号内的数据1984K为堆内存的总容量，收集所需要的时间是0.0253873秒（这个时间在每次执行的时候会有所不同）。

JVM启动参数启用verbose GC

通过JVM启动参数设置来启用verbose gc，并指定了名字和gc日志文件存储路径。

JVM启动参数配置

1
2
3
4

-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps(GC发生的时间)  
-XX:+PrintGCApplicationStoppedTime(GC消耗了多少时间)  
-XX:+PrintGCApplicationConcurrentTime(GC之间运行了多少时间)

1

-server -Xms1024m -Xmx1024m -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:D:/gc.log

运行程序，控制台打印JVM版本

1

Java 7 HotSpot Verbose GC Test Program v1.0

log文件分析：GC输出分成了3个主要部分。

• 5个Minor收集(年轻代收集)被标记为PSYoungGen。
• 2个Major收集(由System.gc()触发)被标记为Full GC。
• 每个内存区域的Java堆分解分析。 

  1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23

  Java HotSpot(TM) 64-Bit Server VM (24.76-b04) for windows-amd64 JRE (1.7.0_76-b13), built on Dec 18 2014 16:31:25 by "java_re" with unknown MS VC++:1600 Memory: 4k page, physical 8286452k(3023144k free), swap 22905152k(11317276k free) CommandLine flags: -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=1073741824 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 0.413: [GC [PSYoungGen: 262656K->43496K(306176K)] 262656K->137856K(1005568K), 0.1518709 secs] [Times: user=0.45 sys=0.06, real=0.15 secs] 0.787: [GC [PSYoungGen: 306152K->43496K(306176K)] 400512K->277096K(1005568K), 0.2234163 secs] [Times: user=0.59 sys=0.06, real=0.22 secs] 1.143: [GC [PSYoungGen: 219344K->43496K(306176K)] 452944K->369728K(1005568K), 0.1305207 secs] [Times: user=0.39 sys=0.03, real=0.13 secs] 1.274: [Full GC [PSYoungGen: 43496K->0K(306176K)] [ParOldGen: 326232K->368338K(699392K)] 369728K->368338K(1005568K) [PSPermGen: 2576K->2575K(21504K)], 2.7245170 secs] [Times: user=6.93 sys=0.00, real=2.72 secs] 4.309: [GC [PSYoungGen: 262656K->32K(306176K)] 630994K->368370K(1005568K), 0.0343405 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 4.453: [GC [PSYoungGen: 113899K->0K(306176K)] 482237K->368338K(1005568K), 0.0239018 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 4.477: [Full GC [PSYoungGen: 0K->0K(306176K)] [ParOldGen: 368338K->134041K(699392K)] 368338K->134041K(1005568K) [PSPermGen: 2576K->2576K(21504K)], 0.3736071 secs] [Times: user=1.01 sys=0.00, real=0.37 secs] Heap PSYoungGen total 306176K, used 5253K [0x00000000eaa80000, 0x0000000100000000, 0x0000000100000000) eden space 262656K, 2% used [0x00000000eaa80000,0x00000000eafa1540,0x00000000fab00000) from space 43520K, 0% used [0x00000000fab00000,0x00000000fab00000,0x00000000fd580000) to space 43520K, 0% used [0x00000000fd580000,0x00000000fd580000,0x0000000100000000) ParOldGen total 699392K, used 134041K [0x00000000bff80000, 0x00000000eaa80000, 0x00000000eaa80000) object space 699392K, 19% used [0x00000000bff80000,0x00000000c82665f0,0x00000000eaa80000) PSPermGen total 21504K, used 2583K [0x00000000bad80000, 0x00000000bc280000, 0x00000000bff80000) object space 21504K, 12% used [0x00000000bad80000,0x00000000bb005f20,0x00000000bc280000)

从verbose GC的第1次Full GC输出你可以看到，ParOldGen（老年代）空间在初始加载了320万字符串实例到HashMap后达到了360M。在移除了200万字符串实例后下降到了134M。说明ParOldGen（老年代）在执行GC操作。

log解析

1

0.413（0）：[GC（1） [PSYoungGen（2）: 262656K（3）->43496K(306176K)（4）] 262656K（5）->137856K(1005568K)（6）, 0.1518709（7） secs] [Times: user=0.45（8） sys=0.06（9）, real=0.15 secs（10）]

（Allocation Failure）：引起垃圾回收的原因。本次GC是因为年轻代中没有任何合适的区域能够存放需要分配的数据结构而触发的。

1. GC时间的开始时间，相对于JVM的启动时间，单位是秒(Measured in seconds)。
2. 用来区分(distinguish)是Minor GC还是Full GC的标志Flag。这里的GC表明本次发生的是Minor GC。
3. 使用的垃圾收集器的名字。这里采用并行垃圾收集器（Throughput Collector）。
4. 年轻代垃圾收集前占用内存。
5. 年轻代垃圾收集后占用内存。
6. 年轻代的总大小。
7. 堆内存垃圾收集前占用内存。
8. 堆内存垃圾收集后占用内存。
9. 此次垃圾回收, 垃圾收集线程消耗的所有CPU时间(Total CPU time)。
10. 操作系统调用(OS call) 以及等待系统事件的时间(waiting for system event)。
11. 应用程序暂停的时间(Clock time)，由于串行垃圾收集器(Serial Garbage Collector)只会使用单个线程，所以Rreal Time等于user以及System Time的总和。

    年轻代空间分析

    1	0.413: [GC [PSYoungGen: 262656K->43496K(306176K)] 262656K->137856K(1005568K), 0.1518709 secs] [Times: user=0.45 sys=0.06, real=0.15 secs]

• 0.413：收集时间
• PSYoungGen：收集类型
• 262656K：垃圾收集GC前存活对象使用的内存容量
• 43496K：垃圾收集GC后存活对象使用的内存容量

• 306176K：年轻代堆内存的总容量

  年老代空间分析

  1	1.274: [Full GC [PSYoungGen: 43496K->0K(306176K)] [ParOldGen: 326232K->368338K(699392K)] 369728K->368338K(1005568K) [PSPermGen: 2576K->2575K(21504K)], 2.7245170 secs] [Times: user=6.93 sys=0.00, real=2.72 secs]

• 1.274：收集时间

• ParOldGen：收集类型
• 326232K：垃圾收集GC前存活对象使用的内存容量
• 368338K：垃圾收集GC后存活对象使用的内存容量

• 699392K：老年代堆内存的总容量

  方法区空间分析

  1	1.274: [Full GC [PSYoungGen: 43496K->0K(306176K)] [ParOldGen: 326232K->368338K(699392K)] 369728K->368338K(1005568K) [PSPermGen: 2576K->2575K(21504K)], 2.7245170 secs] [Times: user=6.93 sys=0.00, real=2.72 secs]

• 1.274：收集时间

• PSPermGen：收集类型
• 2576K：垃圾收集GC前存活对象使用的内存容量
• 2575K：垃圾收集GC后存活对象使用的内存容量
• 21504K：方法区堆内存的总容量

  Java堆分解分析

  1 2 3 4 5 6 7 8 9

  Heap PSYoungGen total 306176K, used 5253K [0x00000000eaa80000, 0x0000000100000000, 0x0000000100000000) eden space 262656K, 2% used [0x00000000eaa80000,0x00000000eafa1540,0x00000000fab00000) from space 43520K, 0% used [0x00000000fab00000,0x00000000fab00000,0x00000000fd580000) to space 43520K, 0% used [0x00000000fd580000,0x00000000fd580000,0x0000000100000000) ParOldGen total 699392K, used 134041K [0x00000000bff80000, 0x00000000eaa80000, 0x00000000eaa80000) object space 699392K, 19% used [0x00000000bff80000,0x00000000c82665f0,0x00000000eaa80000) PSPermGen total 21504K, used 2583K [0x00000000bad80000, 0x00000000bc280000, 0x00000000bff80000) object space 21504K, 12% used [0x00000000bad80000,0x00000000bb005f20,0x00000000bc280000)

年轻代：eden，survive0，survive1
老年代
方法区