《JVM故障诊断指南》之6 —— JVM verbose GC 输出日志指南

---

原文是免费电子书，链接：http://www.javacodegeeks.com/whitepaper/jvm-troubleshooting-guide
以下为本人翻译，仅用于交流学习，版权归原作者所有，转载注明出处，请不要用于商业用途 。

---

JVM verbose GC 输出日志指南

这个部分我们会为你提供详细的指导文档，是关于如何启用和阅读Java 7 HotSpot 虚拟机verbose gc输出日志数据。

我建议你也去编译和运行后面的例子程序。

我们最近也做了一个Java verbose GC 指导视频 ，它详细解释了整个分析过程

参数和工具
• OS: Windows 7 - 64-bit
• Java VM: Sun Java 7 HotSpot (build 21.0-b17)
• IDE: Eclipse Java EE IDE for Web Developer v4.1

Step #1 – 编译我们的样例Java程序

我们创建一个Java样例程序，让它加载Java堆并触发显式的GC，以便它能产生一些我们感兴趣的verbose gc输出日志。这个程序轻松的在一个静态的Map数据结构中加载了大约300万个String实例，并触发了一个显式的GC(通过System.gc())。随后移除了200万个实例，并在退出前产生了第二个显式GC。

package org.ph.javaee.tools.jdk7;
import java.util.Map; import java.util.HashMap;
/**
*   JavaHeapVerboseGCTest
*   @author Pierre-Hugues Charbonneau
*
*/
public class JavaHeapVerboseGCTest {

      private static Map<String, String> mapContainer = new HashMap<String, String>();

      /**
*   @param args
      */
      public static void main(String[] args) {

           System.out.println("Java 7 HotSpot Verbose GC Test Program v1.0");
           System.out.println("Author: Pierre-Hugues Charbonneau");
           System.out.println("http://javaeesupportpatterns.blogspot.com/");

           String stringDataPrefix = "stringDataPrefix";

           // Load Java Heap with 3 M java.lang.String instances            for (int i=0; i<3000000; i++) {
                String newStringData = stringDataPrefix + i;                 mapContainer.put(newStringData, newStringData);
           }

           System.out.println("MAP size: "+mapContainer.size());            System.gc(); // Explicit GC!

           // Remove 2 M out of 3 M            for (int i=0; i<2000000; i++) {
                String newStringData = stringDataPrefix + i;                 mapContainer.remove(newStringData);
           }

           System.out.println("MAP size: "+mapContainer.size());            System.gc();
           System.out.println("End of program!");      

      }
}

Step #2 – 通过JVM启动参数启用 verbose GC

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

Step #3 – 执行我们的样例Java程序

此刻正是执行我们的样例程序并产生JVM verbose GC输出的时候了。

• Verbose GC 输出概括分析

现在来回顾生成的GC输出日志。

首先，让我们先看原始数据。从下面可以看到，GC输出分成了3个主要部分：
• 5个Minor 收集 (年轻代收集)被标记为PSYoungGen
• 2 个Major收集(由System.gc()触发)被标记为Full GC (系统)
• 每个内存区域的Java堆分解分析。 

0.437: [GC [PSYoungGen: 262208K->43632K(305856K)] 
 262208K->137900K(1004928K), 0.1396040 secs] 
 [Times: user=0.45 sys=0.01, real=0.14 secs]

0.785: [GC [PSYoungGen: 305840K->43640K(305856K)] 
 400108K->291080K(1004928K), 0.2197630 secs] 
 [Times: user=0.56 sys=0.03, real=0.22 secs]
1.100: [GC [PSYoungGen: 164752K->43632K(305856K)] 
 412192K->340488K(1004928K), 0.0878209 secs] 
 [Times: user=0.37 sys=0.00, real=0.09 secs] 
1.188: [Full GC (System) [PSYoungGen: 43632K->0K(305856K)] 
 [PSOldGen: 296856K->340433K(699072K)] 
 340488K->340433K(1004928K) 
 [PSPermGen: 1554K->1554K(16384K)], 0.4053311 secs]  [Times: user=0.41 sys=0.00, real=0.40 secs] 

1.883: [GC [PSYoungGen: 262208K->16K(305856K)] 
 602641K->340449K(1004928K), 0.0326756 secs] 
 [Times: user=0.09 sys=0.00, real=0.03 secs]
2.004: [GC [PSYoungGen: 92122K->0K(305856K)] 
 432556K->340433K(1004928K), 0.0161477 secs] 
 [Times: user=0.06 sys=0.00, real=0.02 secs] 
2.020: [Full GC (System) [PSYoungGen: 0K->0K(305856K)] 
 [PSOldGen: 340433K->125968K(699072K)] 
 340433K->125968K(1004928K) 
 [PSPermGen: 1555K->1555K(16384K)], 0.2302415 secs]  [Times: user=0.23 sys=0.00, real=0.23 secs] 

Heap
PSYoungGen total 305856K, used 5244K [0x3dac0000, 0x53010000, 0x53010000)  eden space 262208K, 2% used [0x3dac0000,0x3dfdf168,0x4dad0000)  from space 43648K, 0% used [0x4dad0000,0x4dad0000,0x50570000)  to space 43648K, 0% used [0x50570000,0x50570000,0x53010000)
PSOldGen total 699072K, used 125968K [0x13010000, 0x3dac0000, 0x3dac0000)  object space 699072K, 18% used [0x13010000,0x1ab140a8,0x3dac0000) PSPermGen total 16384K, used 1560K [0x0f010000, 0x10010000, 0x13010000)  object space 16384K, 9% used [0x0f010000,0x0f1960b0,0x10010000)

• Verbose GC 数据的解释以及次序

从verbose GC的输出你可以看到，老年代空间在初始加载了300万字符串实例到HashMap后达到了340M。在移除了200万字符串实例后下降到了126M。

现在看下面的说明和图片快照，它是关于如何详细的阅读每个Java堆空间GC输出数据。

年轻代空间分析

年老代空间分析

持久代空间分析

Java 堆分解分析

希望这个样例Java程序和verbose GC输出分析能帮助你了解如何阅读和解释这些关键数据。