使用Java测量短时间运行的线程执行时间

Question

我目前正在开发某种数据库基准测试应用程序。基本上，我试图使用线程模拟一定数量的客户端，在一定时间内反复执行相同的操作（例如：读取操作）并针对数据库进行测试。
在这段时间内，我想要在每个线程中测量从数据库获取答案的平均延迟。

我的第一个选择是依靠ThreadMXBean的getThreadCpuTime()方法 (http://docs.oracle.com/javase/7/docs/api/java/lang/management/ThreadMXBean.html)，但问题在于该操作速度太快，无法测量（操作之前和之后的getThreadCpuTime()值相等）。

我进行了小实验来理解和说明这个问题：

public class ExampleClass {
class LongRunningThread extends Thread {
    private int n;
    public LongRunningThread(int n) {
        this.n = n;
    }
    public void run() {
        ArrayList l = new ArrayList();
        for (int i = 0; i < n; i++) {
            l.add(new Object());
        }
        long time = ManagementFactory.getThreadMXBean().getThreadCpuTime(this.getId());
        System.out.println("Long running thread " + this.getId() + " execution time: " + time);
    }
}

class MyThread extends Thread {
    int n;
    public MyThread(int n) {
        this.n = n;
    }
    public void run() {
        ArrayList l = new ArrayList();
        for (int i = 0; i < n; i++) {
            l.add(new Object());
        }
        long time = ManagementFactory.getThreadMXBean().getThreadCpuTime(this.getId());
        System.out.println("My thread " + this.getId() + " execution time: " + time);
    }
}

public static void main(String [] args) {
        System.out.println("Cpu time supported? " + ManagementFactory.getThreadMXBean().isThreadCpuTimeSupported());
    System.out.println("Cpu time enabled? " + ManagementFactory.getThreadMXBean().isThreadCpuTimeEnabled());
    for (int i = 1; i < 10; ++i) {
        new LongRunningThread(i*1000000).start();
    }

    for (int i = 1; i < 10; ++i) {
        new MyThread(i*100).start();
    }
}


Output:
Cpu time supported? true
Cpu time enabled? true
My thread 18 execution time: 0
My thread 26 execution time: 0
My thread 20 execution time: 0
My thread 22 execution time: 0
My thread 24 execution time: 0
My thread 21 execution time: 0
My thread 25 execution time: 0
My thread 19 execution time: 0
My thread 23 execution time: 0
Long running thread 9 execution time: 15600100
Long running thread 10 execution time: 15600100
Long running thread 11 execution time: 46800300
Long running thread 12 execution time: 31200200
Long running thread 14 execution time: 78000500
Long running thread 13 execution time: 78000500
Long running thread 17 execution time: 124800800
Long running thread 15 execution time: 140400900
Long running thread 16 execution time: 109200700

我无法获取所有MyThread实例的执行时间，但对于LongRunningThread实例没有问题。正如我所说，我的假设是第一个线程完成的操作发生得太快，无法实际测量。有没有办法实现我想要做的事情？是否可以测量这种短时间运行线程的执行时间？

谢谢您的帮助 :)

- Morro

---

你能把isThreadCpuTimeSupported()和isThreadCpuTimeEnabled()添加到日志中吗？请参考http://docs.oracle.com/javase/7/docs/api/java/lang/management/ThreadMXBean.html。Java虚拟机默认情况下可能会禁用CPU时间测量。 - iMysak

还有一个问题 - 您需要CpuTime还是每个线程的工作时间？ - iMysak

我实际上需要每个线程的工作时间。然而，如果我将getThreadCpuTime()更改为getThreadUserTime()，结果是相同的（即完成MyThread操作的时间为零）。 - Morro

Answer 1

你考虑过这个框架吗 http://metrics.codahale.com/。它非常好，内置支持通过JMX公开指标。

- imrichardcole

Answer 2

在不使用纳秒时钟测量墙上时间的情况下，对于这种短时间运行的线程是否可以测量执行时间可能是否定的。对于小循环，测量的CPU时间可能小于该方法的精度。ThreadMXBean.getThreadCpuTime(...)的Javadocs表明：

返回指定ID的线程的总CPU时间（以纳秒为单位）。返回的值具有纳秒精度，但不一定是纳秒精度。

需要考虑的一个问题是，如果CPU时间> 0，则取CPU时间；如果CPU时间== 0，则取墙上时间。

- Gray

---

谢谢。这看起来肯定不是一件简单的事，我可能不得不找到一个解决方法 :/ - Morro

Answer 3

作为更简单的解决方案，您可以使用下面的内容:

class MyThread extends Thread {
    int n;
    public MyThread(int n) {
        this.n = n;
    }
    public void run() {
        long startTime = System.nanoTime();
        ArrayList l = new ArrayList(n);
        for (int i = 0; i < n; i++) {
            l.add(new Object());
        }
        long time = System.nanoTime() - startTime;
        System.out.println("My thread " + this.getId() + " execution time: " + time + " ns");
    }
}

如果您不需要纳秒级精度，可以使用System.currentTimeMillis()代替。

- iMysak

---

在这种情况下，如果第一个线程被调度程序中断以便执行另一个第二个线程，那么第二个线程的执行时间将包含在第一个线程的区间[startTime，time]中。如果我错了，请纠正我。 - Morro