测量垃圾回收所花费的时间

Question

假设我正在测试一款Java服务器应用程序，我知道测试需要多长时间。现在我想知道在测试期间花费了多少时间进行垃圾回收。我该如何做？

- Michael

---

我会计算测试的从头到尾的运行时间，包括垃圾回收时间，并且只有在想要进行性能调优时才会对其进行分解，例如使用内存分析器。 - Peter Lawrey

Answer 1

我猜测当垃圾回收器（Garbage Collector）在工作时，应用程序会停止，并在垃圾回收完成后恢复。

我不认为这是一个安全的假设。你确定垃圾回收器没有与你的应用程序代码并行工作吗？

要测量垃圾回收所花费的时间，可以查询垃圾回收器 MXBean。

试试这个：

public static void main(String[] args)  {
    System.out.println("collectionTime = " + getGarbageCollectionTime());
}

private static long getGarbageCollectionTime() {
    long collectionTime = 0;
    for (GarbageCollectorMXBean garbageCollectorMXBean : ManagementFactory.getGarbageCollectorMXBeans()) {
        collectionTime += garbageCollectorMXBean.getCollectionTime();
    }
    return collectionTime;
}

- Steve McLeod

---

这个答案非常棒。我一直在对垃圾收集进行各种测试，GarbageCollectorMXBean 提供的值与 JVM args 写入的日志完全相同。 - Pedro Dusso

getGarbageCollectorMXBeans() 什么时候会返回多个 MX Bean？ - cdalxndr

Answer 2

最简单的方法是在启动JVM时使用-Xloggc和-XX:-PrintGCTimeStamps选项。我认为它会打印垃圾回收所需的时间。更多信息请参考：http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html。

- hvgotcodes

Answer 3

另一个方便的解决方案是在测试完成后对进程运行jstat -gc（文档）。这将为您提供有关JVM生命周期中已经在GC中花费了多少时间的良好汇总输出。

- K Erlandsson

Answer 4

这个性能指标是由JVM记录的，并通过JMX进行访问。要进行交互式监视，请使用JConsole连接到运行中的JVM，在“VM Summary”选项卡中，它会显示类似以下内容：

垃圾回收器：名称=“Copy”，集合次数= 26，总耗时= 0.183秒 垃圾回收器：名称=“MarkSweepCompact”，集合次数= 2，总耗时= 0.168秒

您也可以以编程方式查询JMX。

- meriton

Answer 5

类似于 @Steve McLeod 的答案，使用 ManagementFactory，自 Java 8 开始，也可以使用 Java streams 在一行代码中实现：

long collectionTime = ManagementFactory.getGarbageCollectorMXBeans().stream().mapToLong(mxBean -> mxBean.getCollectionTime()).sum();

- Markus Weninger

---

getGarbageCollectorMXBeans() 什么时候会返回多个 MX Bean？ - cdalxndr

我目前无法测试，但我非常确定如果分别为小型和大型收集使用两个不同的收集器，则会发生这种情况。 - Markus Weninger

Answer 6

启用垃圾回收日志。如文档所述，您可以使用-verbose:gc、-XX:+PrintGCDetails和-XX:+PrintGCTimeStamps标志。-Xloggc标志可用于将这些指向文件。

生成的日志是人类可读的，但为了获得最大的效益，您可能希望将它们通过分析器运行。此类工具列在此线程中。

- eis

Answer 7

有不同的GC算法，它们的行为也不同。最近我读了一篇好文章，如果您想了解更多信息，我可以推荐给您。

您可以使用以下命令行选项启动应用程序-verbose:gc -XX:+PrintGCDateStamps -XX:+PrintGCDetails并获取有关GC的信息。

以下是日志消息的示例：

2012-12-17T03:02:15.590-0500: [GC [PSYoungGen: 40934K->2670K(29440K)] 48211K->14511K(73152K), 0.5745260 secs] [Times: user=0.08 sys=0.01, real=0.58 secs]

- Andrew Logvinov