测量垃圾收集时间的阻塞部分答案

【问题标题】：Measuring the blocking part of Garbage Collection time测量垃圾收集时间的阻塞部分
【发布时间】：2017-07-08 23:07:36
【问题描述】：

Java 的垃圾收集器 (GC) 并不总是停止主线程。它可能会阻塞所有线程，或者只是并行运行而不暂停其他线程。

我可以通过使用来测量总垃圾收集时间 garbageCollectorMXBean.getCollectionTime(); 在程序结束时，或通过使用 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -verbose:gc 运行 VM。

但是，我想测量主线程被阻塞（即暂停）的 GC 部分，以便我可以测量主线程运行的确切时间。可以测量吗？

【问题讨论】：

请编辑问题以阐明您是要测量 GC 暂停还是主线程的运行时间。这是两个完全不同的指标，一个不是从另一个派生而来的。
时间 1) 主线程未被 GC 停止，或 2) 不在 VM 安全点中，或 3) 实际在 CPU 上运行 - 这些都是不同的时间。跨度>

标签： java multithreading performance garbage-collection performance-testing

【解决方案1】：

我猜你的问题归结为测量“主线程运行的确切时间”。为了了解这一点，您无需测量垃圾收集器的阻塞时间。

线程运行的时间与其 CPU 时间相对应。如果您还想考虑等待 I/O 的时间，那么这种方法对您不起作用，但是垃圾收集器暂停您的线程的时间应该可以忽略不计。

我为你整理了一个简单的概念证明：

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;
import java.util.concurrent.TimeUnit;

public class CpuTime
{
    public static void main(String[] args) {

        // We obtain the thread mx bean and check if it support CPU time measuring.
        final ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
        if (!threadMxBean.isThreadCpuTimeSupported())
            throw new IllegalStateException("CPU time not supported on this platform");

        // This is important because the default value is platform-dependent.
        threadMxBean.setThreadCpuTimeEnabled(true);

        // Now we start the measurement ...
        final long threadId = Thread.currentThread().getId();
        final long wallTimeStart = System.nanoTime();
        final long cpuTimeStart = threadMxBean.getThreadCpuTime(Thread.currentThread().getId());

        // ... and do stupid things to give the garbage collector some work.
        for (int i = 0; i < 1_000_000_000; i++) {
            Long l = new Long(i);
        }

        // Finally we measure the cpu and wall time.
        final long wallTime = System.nanoTime() - wallTimeStart;
        final long cpuTime = threadMxBean.getThreadCpuTime(threadId) - cpuTimeStart;

        System.out.println("CPU time:  " + TimeUnit.NANOSECONDS.toMillis(cpuTime));
        System.out.println("Wall time: " + TimeUnit.NANOSECONDS.toMillis(wallTime));
    }
}

请注意，这种方法需要一些调整才能获得绝对精确的结果。但是，它应该可以帮助您入门。

【讨论】：

谢谢，印象深刻。尽管如此，我的程序是一个具有大量 CPU 和 IO 的数据管理算法。问题是从 IO 中读取了大量数据，导致 GC 非常活跃，而且计算量很大，这使得测量确切时间变得复杂:-(
看看github.com/aragozin/jvm-tools，它是这个sn-p 的“生产化”版本，实时显示每个线程的CPU 和分配率。它也跟踪 GC。

【解决方案2】：

使用-XX:+PrintGCApplicationStoppedTime 和/或-XX:+PrintGCApplicationConcurrentTime

【讨论】：

不幸的是，-XX:+PrintGCApplicationStoppedTime 并不完全符合其名称的含义。参见例如stackoverflow.com/questions/29666057/analysis-on-gc-logs/…。这也不适用于每个线程，是吗？
@BjörnZurmaar 是的，我知道（至少，因为我已经写了你所指的答案:) Java 开发人员通常对暂停时间感兴趣，无论是 GC 暂停还是不是。但尚不清楚原始问题中的含义 - 我要求澄清。
链接到此答案的原因之一是您是作者。我只是提到它是为了让这个问题的作者意识到这一点。 =)

【解决方案3】：

除了 GC 日志和 MBean，还有 JVM 的 perf counter 暴露相关信息。

jcmd.exe PID PerfCounter.print | grep "sun.rt.safepointTime" 命令将显示 JVM 自启动以来处于 Stop-the-World 状态的累计经过时间。

【讨论】：

【解决方案4】：

您可能想查看 jHiccup，https://www.azul.com/jhiccup/（免费和开源）。这衡量了除您的应用程序之外的所有内容对您的应用程序性能的影响。您可以使用此数据来计算由于 JVM 等影响（如 GC）而导致主线程未运行的聚合时间。但是，这不会测量主线程因被其他应用程序线程阻塞而导致的暂停。

【讨论】：