はじめに
あなたはJavaのソースコードの性能を正しく評価できますか？
例えば、次の2つのソースコードの実行速度がどの程度違うか気になった時、どのように評価していますか？
logger.info("Logger is " + logger.getLevel() + " level.");
if (logger.isLoggable(Level.INFO))
logger.info("Logger is " + logger.getLevel() + " level.");
もし、次のように評価して正しい結果が得られると考えるのであれば、それは誤りです。
// 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レベルに設定し、ファイルに出力するように初期化したソースコードがここにあります）。私の手元で結果は次のようになりました。
1000回実行した処理時間の比較（単位：ミリ秒）
1つ目: 388
2つ目: 125
実行結果は、このマシン上で実行されている他のプロセスなどにも影響を受けるので毎回同じ値にはなりません。何回か実行してみましょう。やはり1つ目のループの処理時間が2つ目の3倍ほど大きな値になることが多いようです。したがって、if (logger.isLoggable(Level.INFO))が無い2つ目の方が3倍程度速いという結論を出せそうです。
本当にそうでしょうか？今度は、上記mainメソッドの比較対象の行の位置を入れ替えて、
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つのループの処理時間の差は大きくないと考えられます。
つまり、2つ目のループの処理時間が若干大きくなるはずです。
なぜこのようなことが起きるのか？
では、なぜこのようなことが起きるのでしょうか？実は、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
そのため、こういった短いコードの性能評価を行う場合は、「ウォームアップ」を行う必要があるのです。
性能に影響する要因は他にもあります。例えば、JITコンパイラが不要と判断したコード（使用されない変数に値をセットするようなコード）を無視することで処理時間が速くなったり（最適化）、GCが発生して処理時間が遅くなったりすることが考えられます。正確性を上げるにはそういったことにも配慮が必要なので、こういった性能評価は難しいわけです。
そして、「ウォームアップ」などの処理を行い、正確性の高い性能検証の環境を準備してくれるのが、今回紹介する「JMH」というツールになります。
 ちなみに今回の例のようなとても小さい単位でソースコードの性能を測定するテストを「マイクロベンチマーク」と言います。マイクロベンチマークを実施する上での注意点についてはここでは触れませんが、この本が参考になるのではないかと思います（※JMHについては解説されていません）。
|
|---|
JMHのセットアップ
では、セットアップして実際に使ってみましょう。
JMHはコマンドラインでも実行できますが、それについては他の記事でも紹介されているようなので、IntelliJで実行する方法を先に紹介します。必要なものはIntelliJとMavenだけです。なお、私はUbuntu上で実行しています。
 注意：推奨されるJMHの実行方法は、Mavenを使用してjarファイルを作成し、それをjavaコマンドで実行する方法です（後述します）。この方法は、JMHが正しく初期化され、信頼できる結果が得られるようにするために推奨されます。IDE内からでもJMHを実行することはできますが、結果の信頼性が少し低くなります。
|
|---|
まずは以下のコマンドを実行します。
$ 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プロジェクトが生成されたことが分かります。
MyBenchmarkには@Benchmarkのアノテーションが付与されたtestMethod()という空実装のメソッドがあり、その中に以下のコメントが書かれています。
// 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を再起動します。
再起動が完了すると、MyBenchmarkのクラス定義の横に「▶▶」のマークが、testMethod()のメソッド定義の横に「▶」のマークが表示されます。前者はそのクラス内の@Benchmarkのアノテーションが付与されたメソッドを全て実行し、後者はそのメソッドだけを実行します。これで準備が整いました。
JMHの実行
では、性能を評価したいソースコードを書いてみましょう。
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のクラス定義の横に「▶▶」のマークをクリックし、実行します。
処理を何度も何度も実行するので、実行には時間がかかります。
/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つを追加した結果も載せておきます。
@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クラスに計測したい処理時を書いて次のコマンドを実行するだけです。
$ 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の結果を鵜呑みにするのではなく、その結果が出た理由を追求する必要がある、ということでしょうか。記事の最初に書いた悪いベンチマークの例も、結果だけで判断せずに理由を考えてみたら、それが正しくないことに気づきますね。