一步步优化JVM三：GC优化基础

命令行选项和GC日志

   从垃圾回收器获取监控信息，是优化JVM的重要操作。收集垃圾回收器信息的最好办法就是收集日志。这个意味着通过HotSpot VM的命令行选项可以收集垃圾回收器的统计信息。开启垃圾回收器日志（即使在生产环境）是很好的主意，其实开启垃圾回收器的开销很小而且可以提供丰富的信息，这些信息和垃圾回收器应用事件或者JVM事件有关系，比如说：一个应用在运行过程中出现了一个比较长的暂停，如果有垃圾回收信息，就可以判断出是垃圾回收器引起的暂停还是应用进行的其他操作引起的暂停。

   有很多的HotSpot VM命令行选项可以用在垃圾回收的日志上面，下面列举几个推荐使用的命令行选项：

[html] view plaincopy

1. <span style="font-size:14px;">   -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:<filename></span>  

   -XX:+PrintGCTimeStamps打印出垃圾回收发生的时间是距离HotSpot VM启动时间的秒数。-XX:+PrintGCDetails提供了垃圾回收特有的统计信息而且具体信息依赖于使用的垃圾回收器类型。-Xloggc:<filename>表示垃圾回收器的信息输出到叫<filename>的文件。

   下面是通过使用-XX:+UseParallelOldGC或者-XX:+UseParallelGC选项来打印出来的垃圾回收信息,而且使用了前面列出的3个选项。

[html] view plaincopy

1. <span style="font-size:14px;">   45.152: [GC [PSYoungGen: 295648K->32968K(306432K)] 296198K->33518K(1006848K), 0.1083183 secs][Times: user=1.83 sys=0.01, real=0.11 secs]</span>  

   45.152是表明距离JVM启动到垃圾回收的秒数，GC标签表明是Minor GC或者young代垃圾回收。

   [PSYoungGen: 295648K->32968K(306432K)]提供了young代的空间信息,PSYoungGen表示young代的垃圾回收是使用throughput垃圾回收器。其他可能的young代垃圾回收有ParNew（使用CMS垃圾回收器多线程回收young代空间）、DefNew（使用serial垃圾回收器单线程回收young代空间）。

   在“->”左边的数字（295648K）表示垃圾回收前young代的空间大小，右边数字（32968K）表示垃圾回收后的young代空间大小。young代被分为eden区域和survivor区域。由于在垃圾回收之后，eden区域是空的，右边的数字其实就是survivor区域的空间。在括号里面的数字（306432K）表示young代的总空间。

   296198K->33518K(1006848K)提供了Java堆在垃圾回收前后的使用情况。另外，他提供Java堆的总大小，是young代和old代的和。在->左边的数字（296198K）表示，在垃圾回收前Java堆占用的空间，->右边的数字（33518K）表示垃圾回收后Java堆占用空间。括号里面的数字（1006848K）表示Java堆总共的空间。

   通过young代的占用空间和Java堆占用的空间，可以快速的计算出old代占用的空间。比如：Java堆的大小是1006848K，young代的空间大小是306432K，因此可以计算出old代的空间大小是1006848K-306432K=700416K。在垃圾回收之前，296198K-295648K=550K是old代使用了的空间。在垃圾回收后33518K-32968K=550K。在这个例子中，在垃圾回收前后没有对象从young代移动到old代。这是一个重要的观察说明了Minor GC回收原则。如果有对象被移动到old代，然后变成不可读取的，就不是最大量的对象被回收，会违反Minor GC回收原则。

   0.1083183 secs表明垃圾回收执行的时间。

   [Times: user=1.83 sys=0.01, real=0.11 secs]提供了CPU和占用时间。user表明垃圾回收在用户模式下执行消耗的CPU时间，即：在JVM里面运行的时间，在这个例子中，垃圾回收器在用户模式下消耗1.83秒的CPU时间。sys表示操作系统代表垃圾回收器消耗的时间，在这里例子中，垃圾回收器使用0.01秒的操作系统CPU时间。real表示垃圾回收执行的时间的。这几个数字精确到0.01秒。

   如果你对垃圾回收的实际时间感兴趣，可以设置-XX:+PrintGCDateStamps选项。-XX:+PrintGCDateStamps显示垃圾回收发生的年，月，日和时间。这个选项是在Java 6 Update 4引入的。下面的例子是同时使用-XX:+PrintGCDateStamps和-XX:+PrintGCDetails选项的结果：

[html] view plaincopy

1. <span style="font-size:14px;">2012-06-21T09:57:10.518-0500: [GC[PSYoungGen: 295648K->32968K(306432K)]296198K->33518K(1006848K), 0.1083183 secs][Times: user=1.83 sys=0.01, real=0.11 secs]</span>  

   2012-06-21T09:57:10.518-0500字段是使用了ISO 8601日期和时间戳。格式是YYYY-MM-DDTHH-MM-SS.mmm-TZ,分别的意思是：

YYYY表示4位数的年

MM表示2位数月，如果只有一位数，前面加0

DD表示2位数的天，如果只有一位数，前面加0

T是一个字符用来隔开日期和时间

HH表示2位数小时，如果只有一位数，前面加0

MM表示2位数分钟，如果只有一位数，前面加0

SS表示2位数秒，如果只有一位数，前面加0

mmm表示3位数毫秒，如果不足三位，前面加0或者00

TZ表示格林尼治时间的时区

   尽管时区已经包含在输出里面了，但是输出日期和时间不是GMT时间，而是本地化过的时间。

   当为了低延迟而优化HotSpot VM的时候，下面的两个选项是非常有用的，这两个选项会报告应用由于虚拟机的安全点（Safepoint）操作而阻塞的时间以及应用程序在安全点（Safepoint）执行了多长的时间。

[html] view plaincopy

1. <span style="font-size:14px;">   -XX:+PrintGCApplicationStoppedTime  
2.    -XX:+PrintGCApplicationConcurrentTime</span>  

   安全点（Safepoint）操作会让JVM进入一种所有应用程序的线程都被阻塞以及阻止任何正在执行的本地程序把结果返回给Java代码的状态。当需要进行优化虚拟机内部操作的时候，安全点（Safepoint操作会被执行以使得所有线程都进入阻塞状态避免影响Java堆（垃圾回收是一种安全点（Safepoint操作）。

   由于安全点（Safepoint)操作阻塞了所有Java程序的执行，所以知道程序的响应时间延迟是否和安全点（Safepoint)操作有关系就显得非常重要了。因此，能够观察程序什么时候被阻塞（ 通过设置-XX:+PrintGCApplicationStoppedTime选项）通过应用的日志信息能够帮组你识别出，当应用的响应时间超过预期的时候，是安全点（Safepoint)操作引起的还是应用或者操作系统的其他操作引起的。-XX:+PrintSafepointStatistics可以帮助区别垃圾回收的安全点（Safepoint)以及其他的安全点（Safepoint)。

   在发现应用的响应时间超过预期的预期的时候，-XX:+PrintGCApplicationConcurrentTime选项可以用来判断程序是否被执行以及执行了多长时间。

   下图总结了前面提到的垃圾回收器的选项以及给出了使用它们的合适情况。