在 Java 内获得可靠的单调时钟

Question

我正在使用ThreadMXBean来获取每个方法的CPU时间，但问题是它不是单调的（对于稍后实际执行的方法，时钟值可能会降低） .在 Java 中访问单调增加 CPU 时间的最佳方法是什么？请注意，我已检查System.nanoTime()，但据我了解，它还包括等待时间。

更新： 问题代码如下：

public class HelloThread extends Thread {
    public static void main(String args[]) throws Exception {
        HelloThread ht = new HelloThread();
        ht.a(1);
        System.out.println("Hello");
    }
    int a(int x) {
        for (int i = 0; i < 100; i++) {
            x = x * 5;
        }
        return x;
    }
}

我已经使用面向方面的编程 (AOP) 来获取线程 ID 和 CPU 时间（我希望它是单调递增的）。这是（方法名称、线程 ID、以毫秒为单位的时间）格式的输出：

public static void main(String[]) 1 647.971834
int HelloThread.a(int) 1 1318.913474
void java.io.PrintStream.println(String) 1 1339.034116
End 1 670.156696

AOP代码：

aspect Profiler {
  pointcut mainStarting(): execution(public static void main(..));
  pointcut mainEnding(): execution(public static void main(..));
  pointcut methodCallBegin(): call(* * (..));
  pointcut methodCallEnd(): call(* * (..));

  static ThreadMXBean threadBean = ManagementFactory.getThreadMXBean();
  double getTime() {
       return (threadBean.getCurrentThreadCpuTime() / 1000000.0);
  }
  before(): mainStarting() {
       System.out.println(Thread.currentThread().getId() + " " + getTime());
  }

  after(): mainEnding() {
       System.out.println(Thread.currentThread().getId() + " " + getTime());
  }

   before(): methodCallBegin() {
      System.out.println(Thread.currentThread().getId() + " " + getTime());
   }
   after(): methodCallEnd() {
      System.out.println(Thread.currentThread().getId() + " " + getTime());
   }
}

我运行在 Intel(R) Xeon(R) CPU E5-2630（6 核）上使用 OpenJDK (java 1.7.0_55)处理器）。

Answer 1

似乎发布的方面没有按预期工作。可能是因为拦截每个调用太多了（我不是 AOP 专家）。我稍微改变了它以仅拦截 HelloThread.a 和 System.out.println 调用：

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;

aspect Profiler {
  pointcut mainStarting(): execution(public static void main(..));
  pointcut mainEnding(): execution(public static void main(..));
  pointcut methodCallBegin(): (call(* *.a (..)) || call(* *.println (..)));
  pointcut methodCallEnd(): (call(* *.a (..)) || call(* *.println (..)));

  static ThreadMXBean threadBean = ManagementFactory.getThreadMXBean();
  double getTime() {
       return (threadBean.getCurrentThreadCpuTime() / 1000000.0);
  }
  before(): mainStarting() {
       System.out.print("mainStarting: "+Thread.currentThread().getId() 
             + " " + getTime()+"\n");
  }

  after(): mainEnding() {
       System.out.print("mainEnding: "+Thread.currentThread().getId() 
             + " " + getTime()+"\n");
  }

  before(): methodCallBegin() {
      System.out.print("methodCallBegin: "+Thread.currentThread().getId() 
             + " " + getTime()+"\n");
  }

  after(): methodCallEnd() {
      System.out.print("methodCallEnd: "+Thread.currentThread().getId() 
             + " " + getTime()+"\n");
  }
}

现在典型的结果如下所示：

mainStarting: 1 93.6006
methodCallBegin: 1 93.6006
methodCallEnd: 1 93.6006
methodCallBegin: 1 93.6006
Hello
methodCallEnd: 1 93.6006
mainEnding: 1 93.6006

结果是预期的：如此简单的代码运行得如此之快，以至于 CPU 时间计数器可能根本不会增加（至少在 Windows 平台上，分辨率可能低于 Linux).然而，此类代码不能像您的示例输出中显示的那样花费 500 毫秒。速度非常快。

我可以让 a 方法变慢：

public static void main(String args[]) throws Exception {
    HelloThread ht = new HelloThread();
    int b = ht.a(1);
    System.out.println("Hello");
}

int a(int x) {
    for (int i = 0; i < 1000000; i++) {
        x = x * 5;
    }
    return x;
}

在这种情况下，结果如下：

mainStarting: 1 93.6006
methodCallBegin: 1 93.6006
methodCallEnd: 1 109.2007
methodCallBegin: 1 109.2007
Hello
methodCallEnd: 1 109.2007
mainEnding: 1 109.2007

因此 a 调用正确地增加了 CPU 时间。没有观察到减少。一般来说 getCurrentThreadCpuTime() 应该不会产生明显的下降。您的原始代码似乎与发布的代码不同。

在 Java 内获得可靠的单调时钟

Get reliable monotonic clock in Java

java

time