その性能検証、本当に正しいですか？ ～ JMHでJavaのソースコードの性能を正しく評価する

# はじめに

**あなたはJavaのソースコードの性能を正しく評価できますか？**

例えば、次の2つのソースコードの実行速度がどの程度違うか気になった時、どのように評価していますか？

```java
logger.info("Logger is " + logger.getLevel() + " level.");
```

```java
if (logger.isLoggable(Level.INFO))
    logger.info("Logger is " + logger.getLevel() + " level.");
```

もし、次のように評価して正しい結果が得られると考えるのであれば、それは誤りです。

```java
// 2つのログ出力処理の処理時間を求める。ただし、誤差を考慮し1000回ずつ繰り返して比較する
public static void main(String[] args) {

    System.out.println("1000回実行した処理時間の比較（単位：ミリ秒）");

    long startTime = System.currentTimeMillis();
    for (int i = 0; i < 1000; i++) {
        if (logger.isLoggable(Level.INFO))
            logger.info("Logger is " + logger.getLevel() + " level.");
    }
    System.out.println("1つ目: " + (System.currentTimeMillis() - startTime));

    startTime = System.currentTimeMillis();
    for (int i = 0; i < 1000; i++) {
        logger.info("Logger is " + logger.getLevel() + " level.");
    }
    System.out.println("2つ目: " + (System.currentTimeMillis() - startTime));
}
```

# なぜ正しくないと言えるのか

まずは上記`main`メソッドを実行してみましょう（`Logger`を`INFO`レベルに設定し、ファイルに出力するように初期化したソースコードが[ここ](https://github.com/k-tamura/jmh-examples/blob/master/src/main/java/org/t246osslab/sample/jmh/BadBenchmark.java)にあります）。私の手元で結果は次のようになりました。

```
1000回実行した処理時間の比較（単位：ミリ秒）
1つ目: 388
2つ目: 125
```

実行結果は、このマシン上で実行されている他のプロセスなどにも影響を受けるので毎回同じ値にはなりません。何回か実行してみましょう。やはり1つ目のループの処理時間が2つ目の3倍ほど大きな値になることが多いようです。したがって、`if (logger.isLoggable(Level.INFO))`が無い2つ目の方が3倍程度速いという結論を出せそうです。

本当にそうでしょうか？今度は、上記`main`メソッドの比較対象の行の位置を入れ替えて、

```java
public static void main(String[] args) {

    long startTime = System.currentTimeMillis();
    for (int i = 0; i < 1000; i++) {
        // こちらをif文の無いログ出力に変更し、
        logger.info("Logger is " + logger.getLevel() + " level.");
    }
    System.out.println("1つ目: " + (System.currentTimeMillis() - startTime));

    startTime = System.currentTimeMillis();
    for (int i = 0; i < 1000; i++) {
        // こちらをif文のあるログ出力に変更
        if (logger.isLoggable(Level.INFO))
            logger.info("Logger is " + logger.getLevel() + " level.");
    }
    System.out.println("2つ目: " + (System.currentTimeMillis() - startTime));
}
```

再実行してみて下さい。

```
1000回実行した処理時間の比較（単位：ミリ秒）
1つ目: 397
2つ目: 134
```

入れ替えたにもかかわらず、相変わらず1つ目のループの処理時間が2つ目の3倍ほど大きな値になります。

そもそも理屈の上では、`Logger`が`INFO`レベルの場合は`if`文の1行分だけ処理が多くなるため、2つ目のループ内の処理時間の方が大きくなるはずです。とは言っても、`if`文の判定処理に対して、ファイルへの出力を伴うログ出力処理の方が時間がかかるため、2つのループの処理時間の差は大きくないと考えられます。
![time.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/f4d600ef-24bc-ab18-6107-ee61f1d769a5.png)
つまり、2つ目のループの処理時間が若干大きくなるはずです。

# なぜこのようなことが起きるのか？

では、なぜこのようなことが起きるのでしょうか？実は、**Javaのコードは繰り返し実行されると高速になる**という性質があるからです。次のようなコードを実行してみれば分かります。

```java
public static void main(String[] args) {
    for (int i = 1; i <= 1000; i++) {
        long startTime = System.currentTimeMillis();
        for (int j = 0; j < 1000; j++) {
            logger.info("Logger is " + logger.getLevel());
        }
        System.out.println(i + "回目: " + (System.currentTimeMillis() - startTime));
    }
}
```

最初の1000回の処理時間は大きな値になりますが、その後不安定ながら徐々に小さくなり、後半は小さな値で安定します。

```
1回目: 385
2回目: 122
3回目: 86
4回目: 68
5回目: 71

・・・（省略）・・・

997回目: 41
998回目: 41
999回目: 42
```

そのため、こういった短いコードの性能評価を行う場合は、**「ウォームアップ」**を行う必要があるのです。
　　　　　![warmup.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/a925e050-4fe2-d8c2-8e6f-15331c62563c.png)
性能に影響する要因は他にもあります。例えば、JITコンパイラが不要と判断したコード（使用されない変数に値をセットするようなコード）を無視することで処理時間が速くなったり（最適化）、GCが発生して処理時間が遅くなったりすることが考えられます。正確性を上げるにはそういったことにも配慮が必要なので、こういった性能評価は難しいわけです。

そして、「ウォームアップ」などの処理を行い、正確性の高い性能検証の環境を準備してくれるのが、今回紹介する**「[JMH](https://github.com/openjdk/jmh)」**というツールになります。

|:information_source: <font color="gray">ちなみに今回の例のようなとても小さい単位でソースコードの性能を測定するテストを「マイクロベンチマーク」と言います。マイクロベンチマークを実施する上での注意点についてはここでは触れませんが、この本が参考になるのではないかと思います（※JMHについては解説されていません）。</font><br>[![s_picture_large978-4-87311-718-8.jpg](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/1c78cfda-2e64-5a0f-90fd-88b934f0b259.jpeg)](https://www.oreilly.co.jp/books/9784873117188/)
|:--|

# JMHのセットアップ

では、セットアップして実際に使ってみましょう。

JMHはコマンドラインでも実行できますが、それについては他の記事でも紹介されているようなので、IntelliJで実行する方法を先に紹介します。必要なものはIntelliJとMavenだけです。なお、私はUbuntu上で実行しています。

|:warning: <font color="gray">注意：推奨されるJMHの実行方法は、Mavenを使用してjarファイルを作成し、それを`java`コマンドで実行する方法です（後述します）。この方法は、JMHが正しく初期化され、信頼できる結果が得られるようにするために推奨されます。IDE内からでもJMHを実行することはできますが、結果の信頼性が少し低くなります。</font>
|:--|

まずは以下のコマンドを実行します。

```bash
$ mvn archetype:generate \
  -DinteractiveMode=false \
  -DarchetypeGroupId=org.openjdk.jmh \
  -DarchetypeArtifactId=jmh-java-benchmark-archetype \
  -DgroupId=org.t246osslab.sample.jmh \
  -DartifactId=jmh-examples \
  -Dversion=1.0
```

すると、`artifactId`で指定した`jmh-examples`という名前のディレクトリーが作成されます。これをIntelliJでオープンしてみましょう。`MyBenchmark`というjavaファイルを含む次のようなディレクトリー構成のMavenプロジェクトが生成されたことが分かります。

![before_install.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/f2c7c985-c048-9565-ef9e-e3f92a798752.png)

`MyBenchmark`には`@Benchmark`のアノテーションが付与された`testMethod()`という空実装のメソッドがあり、その中に以下のコメントが書かれています。

```java
// This is a demo/sample template for building your JMH benchmarks. Edit as needed.
// Put your benchmark code here.
```

つまり、このメソッドに記述した処理の性能を評価してくれるというわけです。

ただし、これだけではIntelliJ上からはJMHを動かすことができないので、JMHプラグインをインストールします。「File」 > 「Settings」で「Plugins」を選択し、検索窓で「jmh」と入力し、プラグインを検索します。すると、JMHプラグインが見つかるので、これをインストールしてIntelliJを再起動します。

![スクリーンショット 2020-11-26 21-04-21.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/5f2c5ef2-f66b-6f35-8878-73aaaa7a6eb7.png)

再起動が完了すると、`MyBenchmark`のクラス定義の横に「▶▶」のマークが、`testMethod()`のメソッド定義の横に「▶」のマークが表示されます。前者はそのクラス内の`@Benchmark`のアノテーションが付与されたメソッドを全て実行し、後者はそのメソッドだけを実行します。これで準備が整いました。

![スクリーンショット 2020-11-30 23-09-57.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/530d576b-6bbe-2d95-17ff-e668ae0778bb.png)

# JMHの実行

では、性能を評価したいソースコードを書いてみましょう。

```java
package org.t246osslab.sample.jmh;

import org.openjdk.jmh.annotations.Benchmark;

import java.io.IOException;
import java.util.logging.*;

public class MyBenchmark {
    static Logger logger = Logger.getLogger(MyBenchmark.class.getName());

    static {
        try {
            logger.setLevel(logger.getLevel());
            Handler handler = new FileHandler("test.log");
            logger.addHandler(handler);
            Formatter formatter = new SimpleFormatter();
            handler.setFormatter(formatter);
            logger.setUseParentHandlers(false);
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

    @Benchmark
    public void testMethod() {
        if (logger.isLoggable(Level.INFO))
            logger.info("Logger is " + logger.getLevel() + " level.");
    }

    @Benchmark
    public void testMethod2() {
        logger.info("Logger is " + logger.getLevel() + " level.");
    }
}
```

## IntelliJでの実行

`MyBenchmark`のクラス定義の横に「▶▶」のマークをクリックし、実行します。

![run 251.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/b9625e6e-0eae-f821-28b6-01e5a1bdf4c3.png)

処理を何度も何度も実行するので、実行には時間がかかります。

```
/usr/lib/jvm/java-8-openjdk-amd64/bin/java -javaagent:/snap/intellij-idea-community/265/lib/idea_rt.jar=39983:/snap/intellij-idea-community/265/bin -Dfile.encoding=UTF-8 -classpath /home/tamura/git/jmh-examples/test/target/classes:/home/tamura/.m2/repository/org/openjdk/jmh/jmh-core/1.26/jmh-core-1.26.jar:/home/tamura/.m2/repository/net/sf/jopt-simple/jopt-simple/4.6/jopt-simple-4.6.jar:/home/tamura/.m2/repository/org/apache/commons/commons-math3/3.2/commons-math3-3.2.jar org.openjdk.jmh.Main org.t246osslab.sample.jmh.MyBenchmark.*
# JMH version: 1.26
# VM version: JDK 1.8.0_275, OpenJDK 64-Bit Server VM, 25.275-b01
# VM invoker: /usr/lib/jvm/java-8-openjdk-amd64/jre/bin/java
# VM options: -javaagent:/snap/intellij-idea-community/265/lib/idea_rt.jar=39983:/snap/intellij-idea-community/265/bin -Dfile.encoding=UTF-8
# Warmup: 5 iterations, 10 s each
# Measurement: 5 iterations, 10 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark: org.t246osslab.sample.jmh.MyBenchmark.testMethod

# Run progress: 0.00% complete, ETA 00:25:00
# Fork: 1 of 5
# Warmup Iteration   1: 19956.414 ops/s
# Warmup Iteration   2: 22657.844 ops/s
# Warmup Iteration   3: 22590.825 ops/s
# Warmup Iteration   4: 21417.337 ops/s
# Warmup Iteration   5: 22881.939 ops/s
Iteration   1: 22848.102 ops/s
Iteration   2: 22049.978 ops/s
Iteration   3: 22919.792 ops/s
Iteration   4: 22820.962 ops/s
Iteration   5: 22954.603 ops/s

・・・（長いので省略）・・・

# Run complete. Total time: 00:25:18

REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.

Benchmark                 Mode  Cnt      Score     Error  Units
MyBenchmark.testMethod   thrpt   25  22565.137 ± 436.439  ops/s
MyBenchmark.testMethod2  thrpt   25  22688.629 ± 212.897  ops/s

Process finished with exit code 0
```

ウォームアップと実測を繰り返して、数分待つと結果としてスループットが出力されます。これを見ると、`if`文の無い`testMethod2()`の方が若干早いことが分かります。しかし、その差は実行時間に対してもあまりにも小さい値です。つまり、`Logger`が`INFO`レベルの場合はどちらの書き方でもほとんど同じと結論付けられます。

ちなみに、`Logger`が`WARNING`レベルの場合の結果は以下のようになります。

```
Benchmark                 Mode  Cnt          Score        Error  Units
MyBenchmark.testMethod   thrpt   25  492766923.694 ± 442811.917  ops/s
MyBenchmark.testMethod2  thrpt   25   10483210.240 ±  64122.137  ops/s
```

`if`文のある`testMethod()`の方が圧倒的に早いですね。性能が求められる場合は、ログを出力する前に`isLoggable()`でチェックする理由が分かりますね。

参考までに、次の2つを追加した結果も載せておきます。

```java
@Benchmark
public void testMethod3() {
    logger.info(() -> "Logger is " + logger.getLevel() + " level.");
}

@Benchmark
public void testMethod4() {
    logger.log(Level.INFO, "Logger is {0} level.", logger.getLevel());
}
```

以下のようになりました。

- `Logger`が`INFO`レベルの場合

```
Benchmark                 Mode  Cnt      Score     Error  Units
MyBenchmark.testMethod   thrpt   25  22416.248 ± 422.362  ops/s
MyBenchmark.testMethod2  thrpt   25  22449.464 ± 291.438  ops/s
MyBenchmark.testMethod3  thrpt   25  22335.362 ± 373.647  ops/s
MyBenchmark.testMethod4  thrpt   25  22411.054 ± 203.023  ops/s
```

- `Logger`が`WARNING`レベルの場合

```
Benchmark                 Mode  Cnt          Score        Error  Units
MyBenchmark.testMethod   thrpt   25  494101580.225 ± 163505.676  ops/s
MyBenchmark.testMethod2  thrpt   25   10735858.712 ±  43362.877  ops/s
MyBenchmark.testMethod3  thrpt   25  493981584.062 ± 682159.853  ops/s
MyBenchmark.testMethod4  thrpt   25  412242077.702 ± 329443.026  ops/s
```

2つとも`if`文のあるログ出力と比較して、若干遅いですが、ほぼ同じ結果になりました。

## コマンドラインでの実行

ちなみに前述したコマンドラインで実行する方法もとても簡単です。`mvn`コマンドでプロジェクトのディレクトリーをつくったら、`MyBenchmark`クラスに計測したい処理時を書いて次のコマンドを実行するだけです。

```bash
$ cd jmh-examples/
$ mvn clean install
$ java -jar target/benchmarks.jar
```

たったこれだけです。そして、この方法の方がIntelliJなどのIDEから実行するよりも正確性が高いようです。

# 最後に

ということで、性能を正しく評価することは難しいということと、JMHというツールを使えば、その正確性を高めることができることが分かりました。もちろん、ウォームアップをしないことで生じる誤差が無視できるようなレベルの性能評価にJMHを使う必要はありませんが、とても簡単に使えるツールなので知っておいて損はないと思います。この記事では、JMHの初歩的なことしか紹介しませんでしたが、他にもいろいろな機能があるようなので、興味のある方は実際に動かしてみて下さい。

ところで、JMHのログの最後にこんなメッセージが出力されていました。

```
REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.
```

JMHの結果を鵜呑みにするのではなく、その結果が出た理由を追求する必要がある、ということでしょうか。記事の最初に書いた悪いベンチマークの例も、結果だけで判断せずに理由を考えてみたら、それが正しくないことに気づきますね。

# 参考

- [GitHub - JMH](https://github.com/openjdk/jmh)
- [GitHub - Intellij IDEA plugin for JMH](https://github.com/artyushov/idea-jmh-plugin)

<!--
https://bufferings.hatenablog.com/entry/2018/10/14/232631
https://antoniogoncalves.org/2015/01/15/micro-benchmarking-with-jmh-measure-dont-guess/
https://www.baeldung.com/java-microbenchmark-harness
-->