JMX：CPU + 阻塞 + 等待时间 = 挂墙时间？

Question

我正在尝试使用 JMX 来测量方法调用花费了多长时间以及其中有多少是 CPU 时间、线程被阻塞了多少以及等待了多少。理想情况下，我希望 CPU 时间 + 阻塞时间 + 等待时间 = 挂起时间，但我注意到情况并非如此 - 而且不仅仅是计时器稍微不准确。例如：

Wall time:  5657.305 ms
CPU time:   4060.000 ms (71.77%)
User time:  3840.000 ms (67.88%)
Block time: 0.000 ms (0.00%)
Wait time:  0.000 ms (0.00%)

所以，问题是......我的假设是这些时间的总和（不是用户时间，它包含在 CPU 时间中）应该给 Wall time 错误？ 我错过了什么吗？

更多细节：

• Wall time：方法进入和退出时System.currentTimeMillis()的差异

• CPU时间：方法进入和退出时ManagementFactory.getThreadMXBean().getCurrentThreadCpuTime()的差异

• 阻塞和等待时间：类似于 CPU，ManagementFactory.getThreadMXBean().getThreadInfo(Thread.currentThread().getId()).getBlockedTime() 和 getWaitedTime()

• 是的，我确实知道这些方法以不同的单位 (ns/ms) 返回时间，我考虑到了这一点。

• 应用程序是高度超线程的（4000 多个线程），但我存储每个线程的所有信息，因此不应该来自不同线程的调用之间有任何干扰。

Answer 1

CPU 时间告诉您线程使用 CPU 所花费的时间，即实际执行代码。如果线程由于例如原因而被挂起，则阻塞或等待时间会增加等待 I/O 或进入监视器。

但是，由 JVM 和操作系统将 CPU 时间分配给线程和进程。如有必要，他们可以选择暂停一个线程或进程并随时恢复另一个线程或进程。所以线程可能处于既不阻塞也不等待但只是不执行的状态。这将增加挂墙时间，但不会增加阻塞/等待时间。

CPU时间值来自操作系统。我检查了 Linux 系统的 OpenJDK 7，所以它在其他平台上可能会有所不同。调用fast_thread_cpu_time() 或slow_thread_cpu_time() 来计算线程的CPU 时间。这两个函数都位于 OpenJDK 7 源代码的hotspot/src/os/linux/vm/os_linux.cpp。

从OpenJDK uses pthreads on Linux 开始，每个Java 线程都被实现为一个轻量级的OS 线程。现代内核支持的快速方法调用pthread_getcpuclockid 来检索特定线程的clock_id，然后调用clock_gettime 来检索线程的CPU 时间。慢速方法将从/proc/self/task/<tid>/stat 中查找 CPU 时间值。这两种方法都可以告诉您线程在用户和系统/内核空间中消耗 CPU 的时间。

参考资料：

• OpenJDK 7 source
• pthread_getcpuclockid(3) man page
• clock_gettime(3) man page
• proc(5) man page

Answer 2

另一种提高测量精度的方法是：

• 以纳秒为单位进行计算，因此经过的时间（使用 System.nanoTime() 和 CPU 时间本机以纳秒为单位。阻塞时间和等待时间应转换，因为它们以毫秒为单位。
• 实现一个近似值，即简单地捕获经过的时间、cpu、阻塞和等待时间所需的时间。 （称之为 OVERHEAD。）您可以在某个静态块中执行此操作。首先做一个 JVM 预热循环，记住 JIT 在 15000 次方法调用后启动 [默认情况下？取决于您的 JVM ....]，因此至少该大小的预热循环会很好。
• 运行预热后循环，将经过的总时间除以循环计数，您将获得 OVERHEAD 值。
• 从计算的方法运行时间中减去 OVERHEAD，以更好地了解方法的代码执行时间，或者....
• 将 OVERHEAD 添加到您添加的 CPU、Blocked 和 Waited 以更接近实际挂墙时间。
• 可以选择不时重新计算 OVERHEAD。

它并不完美，当然也不苛刻，但它可能会给你带来更好的数字。

这是我运行的一些测试代码来计算我的平均开销（Java 7、Windows 7、64 位）。 我试图确保没有省略任何方法，但您的里程可能会有所不同。

public class Overhead {
    static final ThreadMXBean tmx = ManagementFactory.getThreadMXBean();
    public static void main(String[] args) {

        tmx.setThreadContentionMonitoringEnabled(true);
        tmx.setThreadCpuTimeEnabled(true);
        int loops = 15000;
        long sum = -1;
        long start = System.nanoTime();
        for(int i  = 0; i < loops; i++) {
            sum = measure();
        }
        long elapsed = System.nanoTime()-start;
        log("Warmup completed in [" + elapsed + "] ns. ");
        log("Sum:" + sum);

        start = System.nanoTime();
        loops = loops * 2;
        for(int i  = 0; i < loops; i++) {
            sum = measure();
        }
        elapsed = System.nanoTime()-start;

        long avg = (elapsed/loops);

        log("Test completed in [" + elapsed + "] ns. OVERHEAD: [" + avg + "] ns.");
        log("Sum:" + sum);
    }

    protected static long measure() {
        long s1 = System.nanoTime();
        long bt = tmx.getCurrentThreadCpuTime();
        ThreadInfo ti = tmx.getThreadInfo(Thread.currentThread().getId());
        long blocked = ti.getBlockedTime();
        long waited = ti.getWaitedTime();
        long s2 = System.nanoTime();
        return ((s2 - s1) + blocked + waited + bt);
    }


    public static void log(Object msg) {
        System.out.println(msg);
    }
}

我的输出如下：

Overhead test
Warmup completed in [43176164] ns. 
Sum:109201929
Test completed in [38482368] ns. OVERHEAD: [1282] ns.
Sum:156002228

Answer 3

从代码执行的角度来看，线程可以正在运行、在监视器上阻塞或等待 io。然而，一个正在运行的线程必须与其他正在运行的线程竞争以分配给一个 cpu 来运行 - 在它被分配给一个 cpu 之前，它实际上是空闲的，不是占用 cpu 时间而是占用 wall time。如果您有 1000 个线程和几个 cpu 内核，则空闲可能很重要。如果是这种情况，您可能会看到使用“vmstat”的高用户 cpu 和高上下文切换。