1

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

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错误吗?我错过了什么吗?

更多细节:

  • 挂墙时间:System.currentTimeMillis()方法入口和出口的时间差

  • CPU时间:ManagementFactory.getThreadMXBean().getCurrentThreadCpuTime()方法入口和出口的时间差

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

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

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

4

3 回答 3

2

CPU 时间告诉您线程占用 CPU 的时间,即实际执行代码的时间。如果线程因等待 I/O 或进入监视器而暂停,则阻塞或等待时间会增加。

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

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

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

参考:

于 2013-06-26T13:12:13.477 回答
1

您可能能够提高测量精度的另一种方法是:

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

它并不完美,当然也不严格,但它可能会给你带来更好的数字。

这是我运行的一些测试代码来计算我的平均开销(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
于 2013-06-26T15:12:52.113 回答
0

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

于 2016-06-26T02:09:05.367 回答