java - 在 JVM 中分析 block 的正确方法？

Question

我看到很多帖子建议使用类似于下面的代码来分析 Scala 中的方法:

  def timer[A](block: => A): A = {
    val startTime = System.currentTimeMillis()
    val ret = block
    println(s"${System.currentTimeMillis() - startTime}ms")
    ret
  }

基本原理是通过名称传递来实现阻止。但是，当我尝试代码片段时，我发现结果不可信。

object Euler006 extends App {
  def f1(n: Int): Long = {
    val numbers = 1 to n
    def square(n: Int) = n.toLong * n
    square(numbers.sum) - numbers.map(square).sum
  }

  def f2(n: Int): Long = (n.toLong - 1) * n / 2 * (n + 1) / 3 * (3 * n + 2) / 2

  {
    val r2 = timer(f2(10000))
    val r1 = timer(f1(10000))
    println(s"$r1 $r2")
  }

  System.gc()
  System.runFinalization()

  {
    val r1 = timer(f1(10000))
    val r2 = timer(f2(10000))
    println(s"$r1 $r2")
  }

}

输出:

57ms // line 1
19ms // line 2
2500166641665000 2500166641665000
7ms  // line 4
0ms  // line 5
2500166641665000 2500166641665000

显然，f2 应该花费很少的时间来执行，但是第 1 行输出 57ms。我想这可能是因为 JVM 初始化的原因。 OTOH，尽管我尝试了垃圾收集，但第 2 行和第 4 行也不同(我们不能保证，因为 JVM 有一些不确定性，但这就是我能想到的)。

这个例子非常简单，我应该多次运行结果来实际分析它们(就像Python中的timeit模块)。但是，我不确定如何编写正确的计时器来消除/减轻输出中所示的潜在影响。

更新:

应该包括 JVM 初始化，因为如果我在开始之前添加类似 timer({}) 的内容，第 1 行时间成本很快就会变成0ms (表示花费的时间很少)。

Answer 1

Obviously f2 should take little time to execute,

这可能需要一些时间，但不一定要花一毫秒。您的计算可能只有几分之一毫秒。事实上，由于未使用结果，因此可以丢弃该代码。

我建议您使用System.nanoTime()并确保使用结果。

guess perhaps it's because of the JVM initialization.

第一次调用代码时，必须加载它，并且很可能这就是您正在计时的时间

line 2 and line 4 are also different although I tried garbage collection

代码现已加载。注意:如果您复制代码并运行另一个执行相同操作的方法，您可能会得到类似的计时。

I should run the results for many times to actually profile them

我会忽略运行的前 2 秒以确保代码已预热，或者使用像 JMH http://openjdk.java.net/projects/code-tools/jmh/ 这样的微基准框架。

static int n = 10000;

public static void main(String[] args) throws RunnerException, IOException {
    long time = 2;
    Options opt = new OptionsBuilder()
            .include(CalcBenchmark.class.getSimpleName())
            .warmupIterations(6)
            .forks(1)
            .measurementTime(TimeValue.seconds(time))
            .timeUnit(TimeUnit.NANOSECONDS)
            .build();

    new Runner(opt).run();
}
@Benchmark
public long calc() {
    return (n - 1L) * n / 2 * (n + 1) / 3 * (3 * n + 2) / 2;
}

打印

# JMH 1.11.2 (released 164 days ago, please consider updating!)
# VM version: JDK 1.8.0_45, VM 25.45-b02
# VM invoker: /mnt/opt/jdk1.8.0_45/jre/bin/java
# VM options: -Didea.launcher.port=7534 -Didea.launcher.bin.path=/mnt/opt/idea-IC-143.1821.5/bin -Dfile.encoding=UTF-8
# Warmup: 6 iterations, 1 s each
# Measurement: 20 iterations, 2 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: vanilla.java.jmh.CalcBenchmark.calc

# Run progress: 0.00% complete, ETA 00:00:46
# Fork: 1 of 1
# Warmup Iteration   1: 0.105 ops/ns
# Warmup Iteration   2: 0.156 ops/ns
# Warmup Iteration   3: 0.169 ops/ns
# Warmup Iteration   4: 0.167 ops/ns
# Warmup Iteration   5: 0.166 ops/ns
# Warmup Iteration   6: 0.165 ops/ns
Iteration   1: 0.169 ops/ns
Iteration   2: 0.166 ops/ns
Iteration   3: 0.165 ops/ns
Iteration   4: 0.168 ops/ns
Iteration   5: 0.163 ops/ns
Iteration   6: 0.159 ops/ns
Iteration   7: 0.162 ops/ns
Iteration   8: 0.166 ops/ns
Iteration   9: 0.169 ops/ns
Iteration  10: 0.166 ops/ns
Iteration  11: 0.169 ops/ns
Iteration  12: 0.162 ops/ns
Iteration  13: 0.166 ops/ns
Iteration  14: 0.167 ops/ns
Iteration  15: 0.166 ops/ns
Iteration  16: 0.169 ops/ns
Iteration  17: 0.166 ops/ns
Iteration  18: 0.165 ops/ns
Iteration  19: 0.170 ops/ns
Iteration  20: 0.164 ops/ns


Result "calc":
  0.166 ±(99.9%) 0.002 ops/ns [Average]
  (min, avg, max) = (0.159, 0.166, 0.170), stdev = 0.003
  CI (99.9%): [0.163, 0.168] (assumes normal distribution)


# Run complete. Total time: 00:00:47

Benchmark            Mode  Cnt  Score   Error   Units
CalcBenchmark.calc  thrpt   20  0.166 ± 0.002  ops/ns

简而言之，一旦预热，您的操作应该需要大约 6 ns 或 0.000006 ms

<小时/>

没有 JMH 的更简单的基准测试可能如下所示。注意:我更相信 JMH 的数字。

public class SimpleCalcBenchmark {
    static int n = 10000;
    static final AtomicLong blackHole = new AtomicLong();

    public static void main(String[] args) throws RunnerException, IOException {
        for (int i = 0; i < 5; i++) {
            long start = System.nanoTime();
            long counter = 0;
            while (System.nanoTime() - start < 2e9) {
                for (int j = 0; j < 100; j++) {
                    blackHole.lazySet(calc());
                }
                counter += 100;
            }
            long time = System.nanoTime() - start;
            System.out.printf("Took an average of %.1f ns%n", (double) time/counter);
        }
    }

    public static long calc() {
        return (n - 1L) * n / 2 * (n + 1) / 3 * (3 * n + 2) / 2;
    }
}

打印

Took an average of 10.2 ns
Took an average of 6.7 ns
Took an average of 4.7 ns
Took an average of 4.7 ns
Took an average of 4.6 ns