5.3 垃圾回收工具

由于垃圾回收对 Java 的性能影响至关重要,业界提供了大量的工具用于监控它的性能。

观察垃圾回收对应用程序的性能影响最好的方法就是尽量熟悉垃圾回收的日志,垃圾回收日志中包含了程序运行过程中的每一次垃圾回收操作。

垃圾回收日志的细节依据使用的垃圾回收算法各有不同,不过垃圾回收日志的基本结构(management)是一致的。这一节我们会介绍这些结构,与具体垃圾回收算法相关的更多日志细节会在下一章中介绍。

多种方法都能开启 GC 的日志功能,其中包括:使用 -verbose:gc-XX:+PrintGC 这两个标志中的任意一个能创建基本的 GC 日志(这两个日志标志实际上互为别名,默认情况下的 GC 日志功能是关闭的)。使用 -XX:+PrintGCDetails 标志会创建更详细的 GC 日志。我们推荐使用 -XX:+PrintGCDetails 标志(这个标志默认情况下也是关闭的);通常情况下使用基本的 GC 日志很难诊断垃圾回收时发生的问题。除了使用详细的 GC 日志,我们还推荐使用 -XX:+PrintGCTimeStamps 或者 -XX:+PrintGCDateStamps,便于我们更精确地判断几次 GC 操作之间的时间。这两个参数之间的差别在于时间戳是相对于 0(依据 JVM 启动的时间)的值,而日期戳(date stamp)是实际的日期字符串。由于日期戳需要进行格式化,所以它的效率可能会受轻微的影响,不过这种操作并不频繁,它造成的影响也很难被我们感知。

默认情况下 GC 日志直接输出到标准输出,不过使用 -Xloggc:filename 标志也能修改输出到某个文件。除非显式地使用 -PrintGCDetails 标志,否则使用 -Xloggc 会自动地开启基本日志模式。使用日志循环(Log rotation)标志可以限制保存在 GC 日志中的数据量;对于需要长时间运行的服务器而言,这是一个非常有用的标志,否则累积几个月的数据很可能会耗尽服务器的磁盘。通过 -XX:+UseGCLogfileRotation -XX:NumberOfGCLogfiles=N -XX:GCLogfileSize=N 标志可以控制日志文件的循环。默认情况下,UseGCLogfileRotation 标志是关闭的。开启 UseGCLogfileRotation 标志后,默认的文件数目是 0(意味着不作任何限制),默认的日志文件大小是 0(同样也是不作任何限制)。因此,为了让日志循环功能真正生效,我们必须为所有这些标志设定值。需要注意的是,如果设定的数值不足 8 KB 的话,日志文件的大小会以 8 KB 为单位规整。

根据需要,你可以手工地解析、研读垃圾回收日志,也可以利用一些工具来完成这部分工作。GC Histogram(http://java.net/projects/gchisto)就是这些工具中的一员。GC Histogram 能够读入 GC 日志,根据日志文件中的数据生成对应的图表和表格。图 5-4 是由 GC Histogram 生成的 GC 开销的概略表。

{%}

图 5-4:GC Histogram 的停顿状态选项卡

在这个例子中,JVM 消耗了 41% 的时间进行垃圾回收,完成一次 Full GC 的时间长达 7 秒钟。很明显,这个应用程序需要调优它的内存使用。

使用 jconsole 可以实时监控堆的使用情况。jconsole 的内存面板可以实时查看堆的使用状况,如图 5-5 所示。

{%}

图 5-5:查看堆的实时状况

从这幅视图我们能看到整个堆的使用情况,它在介于 100 MB 到 160 MB 的区间内周期性地循环。使用 jconsole 一次只能看到一个分区的使用情况:要么是 Eden 空间,要么是 Survivor 空间,要么是老年代,或者是永久代。如果选择 Eden 空间作为绘制图表的区域,能看到 Eden 空间以相似的模式在 0 MB 到 60 MB 之间波动(并且,跟你的猜测一样,如果依据老年代的数据作图,那它基本将是一条横在 100 MB 的水平线)。

如果你希望使用脚本的方式获取数据,jstat 是理想的工具。jstat 提供了 9 个选项,提供堆的各种数据;使用 jstat -options 选项能够列出所有这些选项。这其中最常用的一个选项是 -gcutil,它能够输出消耗在 GC 上的时间,以及每个 GC 区域使用的百分比。其他的选项能够以 KB 为单位输出各 GC 空间的大小。

注意,jstat 接受一个可选的参数,指定每隔多少毫秒重复执行这个命令,这个选项帮助我们长时间地监控应用程序的垃圾回收过程。下面是一个示例的输出,它以每隔一秒钟的频率运行。

  1. % jstat -gcutil process_id 1000
  2. S0 S1 E O P YGC YGCT FGC FGCT GCT
  3. 51.71 0.00 99.12 60.00 99.93 98 1.985 8 2.397 4.382
  4. 0.00 42.08 5.55 60.98 99.93 99 2.016 8 2.397 4.413
  5. 0.00 42.08 6.32 60.98 99.93 99 2.016 8 2.397 4.413
  6. 0.00 42.08 68.06 60.98 99.93 99 2.016 8 2.397 4.413
  7. 0.00 42.08 82.27 60.98 99.93 99 2.016 8 2.397 4.413
  8. 0.00 42.08 96.67 60.98 99.93 99 2.016 8 2.397 4.413
  9. 0.00 42.08 99.30 60.98 99.93 99 2.016 8 2.397 4.413
  10. 44.54 0.00 1.38 60.98 99.93 100 2.042 8 2.397 4.439
  11. 44.54 0.00 1.91 60.98 99.93 100 2.042 8 2.397 4.439

在这个例子中,监控开始时,程序已经在新生代(YGC)中进行了 99 次垃圾回收操作,这总共消耗了大约 1.985 秒的时间(YGCT)。于此同时,它还完成了 8 次 Full GC(FGC),消耗了 2.397 秒的时间(FGCT);因此 GC 消耗的总时长(GCT)为 4.382 秒。

新生代中三个区间的数据都在这里列出:两个 Survivor 空间(分别是 S0S1)以及 1 个 Eden 空间(标记为 E)。监控开始时,Eden 空间几乎要被填满了(已经占用了 99.12% 的空间),因此下一秒就有一次新生代的垃圾回收:这之后 Eden 空间的使用率回落到 5.55%,Survivor 空间发生了交换,一部分内存对象被晋升到了老年代空间(标记为 O),老年代的空间使用率增长到 60.98%。跟典型的场景一样,我们没有在永久代(标记为 P)发现大幅度的变化,因为几乎所有需要的类都已经在程序启动时载入内存。

如果你不记得如何开启 GC 日志,这是一个很好的替代方法,它能帮助我们观察垃圾回收是如何在较长的时间跨度内工作的。

5.3 垃圾回收工具 - 图3 快速小结

1. GC 日志是分析 GC 相关问题的重要线索;我们应该开启 GC 日志标志(即使是在生产服务器上)。

2. 使用 PrintGCDetails 标志能获得更详尽的 GC 日志信息。

3. 使用工具能很有效地帮助我们解析和理解 GC 日志的内容,尤其是在对 GC 日志中的数据进行归纳汇总时,它们非常有帮助。

4. 使用 jstat 能动态地观察运行程序的垃圾回收操作。