CLOVER🍀

That was when it all began.

マイクロベンチマークツール、JMHを試す

去年、こんな記事が出ていて、個人的にはけっこう興味を引きました。

Javaのマイクロベンチマークツール「JMH」
http://acro-engineer.hatenablog.com/entry/2013/11/07/120606

以前、Javaのキャッシュのベンチマークを取るのにGoogle Caliperの0.5を使って遊んだことがあるのですが、1.0になってどうも変な動きになっていて諦めていたところに出てきた記事だったので、大変参考になりました。

で、試そう試そうと思っているうちに、気付けば年が変わっていましたがー。

ま、今からでも、やってみましょう。

Code Tools: jmh
http://openjdk.java.net/projects/code-tools/jmh/

準備

元記事にはJMH自体をビルドする方法から紹介されていますが、今はMaven Centralに0.2までアップされているので、こちらを使用することにします。

Maven依存関係は、以下のように定義します。

    <dependency>
      <groupId>org.openjdk.jmh</groupId>
      <artifactId>jmh-core</artifactId>
      <version>0.2</version>
    </dependency>

また、ビルドしてJARを生成するのですが、この時JMH自体をJARに含める必要があるため、build/plugins配下に以下の設定を加えます。

      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-shade-plugin</artifactId>
        <version>2.2</version>
        <executions>
          <execution>
            <phase>package</phase>
            <goals>
              <goal>shade</goal>
            </goals>
            <configuration>
              <finalName>microbenchmarks</finalName>
              <transformers>
                <transformer implementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer">
                  <mainClass>org.openjdk.jmh.Main</mainClass>
                </transformer>
              </transformers>
            </configuration>
          </execution>
        </executions>
      </plugin>

あとは、マイクロベンチマークを行うためのコードを用意します。

この設定で、ソースコードを書いた後に以下のコマンドを実行すると

$ mvn package

targetディレクトリ配下に「microbenchmarks.jar」が生成されるので、こちらを使用します。

実行コマンドは、こんな感じです。

$ java -jar target/microbenchmarks.jar [オプション]

では、いくつかサンプルを紹介すると共に、実行例を載せていきましょう。

なお、JMH自体のサンプルコードは、こちらで確認することができます。

http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-samples/src/main/java/org/openjdk/jmh/samples/

もしくは、リポジトリ自体をMercurialでチェックアウトしましょう。

$ hg clone http://hg.openjdk.java.net/code-tools/jmh/ jmh

HelloWorld的な

では、まずは単純な処理を書いてみます。
src/main/java/org/littlewings/jmh/example/HelloJmh.java

package org.littlewings.jmh.example;

import java.util.concurrent.TimeUnit;

import org.openjdk.jmh.annotations.GenerateMicroBenchmark;

public class HelloJmh {
    @GenerateMicroBenchmark
    public void simpleBench() throws InterruptedException {
        TimeUnit.MILLISECONDS.sleep(500);
    }
}

ベンチマーク対象のメソッドには、@GenerateMicroBenchmarkアノテーションを付与します。ひとつのクラスに、複数の@GenerateMicroBenchmarkアノテーションを付与したメソッドを設けて大丈夫です。

今回は、1回の呼び出しで500msecスリープする処理を用意しました。

それでは、ビルドして実行してみます。

$ java -jar target/microbenchmarks.jar -wi 3 -i 3 -f 1 -r 1s -bm thrpt -tu s

実行途中にはこのような進捗状態が表示され、

# Fork: 1 of 1
# Warmup: 3 iterations, 1 s each
# Measurement: 3 iterations, 1 s each
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Running: org.littlewings.jmh.example.HelloJmh.simpleBench
# Warmup Iteration   1: 2.000 ops/s
# Warmup Iteration   2: 2.000 ops/s
# Warmup Iteration   3: 2.000 ops/s
Iteration   1: 2.000 ops/s
Iteration   2: 2.000 ops/s
Iteration   3: 2.000 ops/s

Result : 2.000 ±(99.9%) 0.000 ops/s
  Statistics: (min, avg, max) = (2.000, 2.000, 2.000), stdev = 0.000
  Confidence interval (99.9%): [2.000, 2.000]

最終的に、こんな結果が表示されます。

Benchmark                        Mode Thr     Count  Sec         Mean   Mean error    Units
o.l.j.e.HelloJmh.simpleBench    thrpt   1         3    1        2.000        0.000    ops/s

今回は表示を秒単位にしてあるので、1秒で2回の呼び出し…まあ、そうですね。

起動時にいろいろオプションを指定していますが、実際には指定しなくてもデフォルトでいろいろ動いてくれます。指定したオプションの意味を解説しておくと

オプション 意味 指定可能な値
-wi ウォームアップ時の繰り返し回数(計測には含まれない) intで指定できる数字(例:3)
-i 計測を行う回数 intで指定できる数字(例:3)
-f フォークの数。ここでは、ベンチマークのセット(ウォームアップから計測まで)の繰り返し回数と捉えればOK intで指定できる数字(例:1)
-r 計測を行う際の、実行時間 100s、 200msなど
-bm ベンチマークのモード thrpt(スループット)、avgt(平均)、sample(Time distribution, percentile estimation)、ss(シングルショット)、all(左に上げたモードを全部実行する)
-tu 結果表示の際の、時間の単位 m、 s、 ms、 us、 ns

指定可能なオプションの一覧は、以下のコマンドで見ることができます。

$ java -jar target/microbenchmarks.jar -h

デフォルト値については、以下を見るといいでしょう。
標準偏差)
http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-core/src/main/java/org/openjdk/jmh/runner/parameters/Defaults.java

繰り返し実行

ベンチマークでの測定対象を複数呼び出す際に、何度の呼び出しを1回の計測と捉えるかをJMHに指定することができます。

以下、コード例。
src/main/java/org/littlewings/jmh/example/Loop.java

package org.littlewings.jmh.example;

import java.util.concurrent.TimeUnit;

import org.openjdk.jmh.annotations.GenerateMicroBenchmark;
import org.openjdk.jmh.annotations.OperationsPerInvocation;

public class Loop {
    public void method(int limit) throws InterruptedException {
        for (int i = 0; i < limit; i++) {
            TimeUnit.MILLISECONDS.sleep(10);
        }
    }

    @GenerateMicroBenchmark
    @OperationsPerInvocation(1)
    public void invoke1() throws InterruptedException {
        method(1);
    }

    @GenerateMicroBenchmark
    @OperationsPerInvocation(100)
    public void invoke100() throws InterruptedException {
        method(100);
    }
}

本当に計測したいのはmethodメソッドだとした場合、計測用のメソッドとしてinvoke1とinvoke100の2つのメソッドを用意します。invoke1は1回の呼び出しで本当に計測したいメソッドをメソッドを1回呼んだことに、invoke100は1回の呼び出しで本当に計測したいメソッドを100回呼んでいることを、JMHに教えていることになっています。

method内では、指定のループごとに10msecスリープします。なので、invoke100メソッドを呼び出すと1秒少々スリープすることになりますね。

これは、ベンチマークモードをallにして結果を見てみましょう。

$ java -jar target/microbenchmarks.jar -wi 3 -i 3 -f 1 -r 1s -bm all -tu s

こんな感じになります。

Benchmark                        Mode Thr     Count  Sec         Mean   Mean error    Units
o.l.j.e.Loop.invoke1            thrpt   1         3    1       87.800       40.489    ops/s
o.l.j.e.Loop.invoke100          thrpt   1         3    1       90.289       10.820    ops/s
o.l.j.e.Loop.invoke1             avgt   1         3    1        0.011        0.001     s/op
o.l.j.e.Loop.invoke100           avgt   1         3    1        0.011        0.000     s/op
o.l.j.e.Loop.invoke1           sample   1       258    1        0.012        0.000     s/op
o.l.j.e.Loop.invoke100         sample   1         3    1        1.191        0.054     s/op
o.l.j.e.Loop.invoke1               ss   1         3    0        0.014        0.041        s
o.l.j.e.Loop.invoke100             ss   1         3    0        1.107        0.130        s

スループットは、100回呼び出しの方が、若干遅いくらい。平均は同じですね。なので、JMH側で@GenerateMicroBenchmarkを付与したメソッド自身が、計測対象を100回呼んだことを認識しています。代わりに、シングルショット(ss)は、スリープの結果がダイレクトに現れているのがわかりやすいと思います。

ベンチマークに状態を持たせる

ベンチマークのクラスにフィールドなどの状態を持たせて、その初期化/終了などをコントロールできます。

では、サンプルを。
src/main/java/org/littlewings/jmh/example/TestState.java

package org.littlewings.jmh.example;

import java.util.concurrent.TimeUnit;

import org.openjdk.jmh.annotations.GenerateMicroBenchmark;
import org.openjdk.jmh.annotations.Level;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.TearDown;

@State(Scope.Thread)
public class TestState {
    private long counter = 0;

    @Setup
    //@Setup(Level.Iteration)
    public void setup() {
        System.out.println("========== setup ==========");
        counter = 0;
    }

    @GenerateMicroBenchmark
    public void methodA() {
        counter++;
    }

    @GenerateMicroBenchmark
    public void methodB() {
        counter++;
    }

    @TearDown
    //@TearDown(Level.Iteration)
    public void tearDown() {
        System.out.println("========== teardown ==========");
        System.out.println("counter = " + counter);
    }
}

最初に、

@State(Scope.Thread)
public class TestState {

と宣言しているところがポイントです。これで、スレッド単位にベンチマークを持つようにします。

その他、必須ではありませんが@Setupアノテーションや@TearDownアノテーションを付与したメソッドを作成することで、初期化/終了処理を書くことができます。

    @Setup
    //@Setup(Level.Iteration)
    public void setup() {
        System.out.println("========== setup ==========");
        counter = 0;
    }

    @TearDown
    //@TearDown(Level.Iteration)
    public void tearDown() {
        System.out.println("========== teardown ==========");
        System.out.println("counter = " + counter);
    }

JMHのサンプルでは、@TearDownアノテーションを付与したメソッドでアサーションを行っていました。

@Setupアノテーション、@TearDownアノテーションでコメントアウトでLevelを書いていますが、これには3つのパターンを指定できます。それぞれ、

が指定できます。が、通常、TrialかIterationを指定するんだと思います。Invocationは、Javadocでものすっごい警告されています…。

http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-core/src/main/java/org/openjdk/jmh/annotations/Level.java

で、今回の例は@Setupと@TearDownでSystem.outしているだけなので、実行すると

$ java -jar target/microbenchmarks.jar -wi 3 -i 3 -f 1 -r 1s -bm thrpt -tu s

ちょっとレポートの結果に割り込まれていますが、こんな表示になります。

# Fork: 1 of 1
========== setup ==========
# Warmup: 3 iterations, 1 s each
# Measurement: 3 iterations, 1 s each
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Running: org.littlewings.jmh.example.TestState.methodB
# Warmup Iteration   1: 393825934.400 ops/s
# Warmup Iteration   2: 384291389.050 ops/s
# Warmup Iteration   3: 402733190.600 ops/s
Iteration   1: 393833628.933 ops/s
Iteration   2: 403786121.067 ops/s
Iteration   3: ========== teardown ==========
counter = 2387745388
404992957.983 ops/s


# Fork: 1 of 1
========== setup ==========
# Warmup: 3 iterations, 1 s each
# Measurement: 3 iterations, 1 s each
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Running: org.littlewings.jmh.example.TestState.methodA
# Warmup Iteration   1: 384264742.033 ops/s
# Warmup Iteration   2: 380980549.233 ops/s
# Warmup Iteration   3: 354685731.983 ops/s
Iteration   1: 355758333.350 ops/s
Iteration   2: 383169984.083 ops/s
Iteration   3: ========== teardown ==========
counter = 2205967045
345683238.517 ops/s

Result : 361537185.317 ±(99.9%) 250075812.730 ops/s
  Statistics: (min, avg, max) = (345683238.517, 361537185.317, 383169984.083), stdev = 19400009.558
  Confidence interval (99.9%): [111461372.587, 611612998.047]

つまり、デフォルトはTrialです。ウォームアップの前に@Setupアノテーションを付与したメソッドが呼び出され、全部が終わると@TearDownを付与したメソッドが呼び出されます。

また、同じクラスの@GenerateMicroBenchmarkアノテーションを付与したメソッド単位に、ベンチマークは実行されるのでこの単位で呼び出されます。

では、ここでIterationに変えて

    @Setup(Level.Iteration)

    @TearDown(Level.Iteration)

実行。

# Fork: 1 of 1
========== setup ==========# Warmup: 3 iterations, 1 s each
# Measurement: 3 iterations, 1 s each
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Running: org.littlewings.jmh.example.TestState.methodA

# Warmup Iteration   1: ========== teardown ==========
counter = 393415410
========== setup ==========
393832584.250 ops/s
# Warmup Iteration   2: ========== teardown ==========
counter = 393429045
389109403.767 ops/s========== setup ==========

# Warmup Iteration   3: ========== teardown ==========
counter = 388305539
387911634.900 ops/s
Iteration   1: ========== setup ==========
========== teardown ==========
counter = 396708771
396541675.083 ops/s
Iteration   2: ========== setup ==========
========== teardown ==========
counter = 396693148
396416333.250 ops/s
========== setup ==========
Iteration   3: ========== teardown ==========
counter = 387101506
387070113.833 ops/s

Result : 393342707.389 ±(99.9%) 70028758.090 ops/s
  Statistics: (min, avg, max) = (387070113.833, 393342707.389, 396541675.083), stdev = 5432586.868
  Confidence interval (99.9%): [323313949.299, 463371465.479]


# Fork: 1 of 1
========== setup ==========
# Warmup: 3 iterations, 1 s each
# Measurement: 3 iterations, 1 s each
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Running: org.littlewings.jmh.example.TestState.methodB
# Warmup Iteration   1: ========== teardown ==========
counter = 382855076
381309718.083 ops/s
# Warmup Iteration   2: ========== setup ==========
========== teardown ==========
counter = 405691075
407024043.733 ops/s
# Warmup Iteration   3: ========== setup ==========
========== teardown ==========
counter = 380215869
379928576.517 ops/s
Iteration   1: ========== setup ==========
========== teardown ==========
counter = 365053007
364777073.200 ops/s
Iteration   2: ========== setup ==========
========== teardown ==========
counter = 408294746
407903593.383 ops/s
========== setup ==========Iteration   3: 
========== teardown ==========
counter = 412189352
411940886.967 ops/s

Result : 394873851.183 ±(99.9%) 336991524.691 ops/s
  Statistics: (min, avg, max) = (364777073.200, 394873851.183, 411940886.967), stdev = 26142627.423
  Confidence interval (99.9%): [57882326.493, 731865375.874]

ウォームアップと、各イテレーション毎に@Setup/@TearDownが呼び出されるようになります。

まあ、このくらいできればいいかな…。

なお、コマンドラインのオプションで指定したパラメータなどは、アノテーションでベンチマーク対象のメソッドやクラスに指定することもできます。詳しくは、以下に定義されているアノテーションや列挙型

http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-core/src/main/java/org/openjdk/jmh/annotations/

そしてサンプルコードで使い方を見てみましょう。

http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-samples/src/main/java/org/openjdk/jmh/samples/

これで、JMHとGatlingが使えるようになった…といいなぁ。