torutkのブログ

ソフトウェア・エンジニアのブログ

JMH - Javaマイクロベンチマークハーネス(枠組み)

Javaプログラムにおいて、ある処理にかかる時間を計測したいということがあります。
Javaの実行環境(JavaVM:Java Virtual Machine)では、JITコンパイルガベージコレクションがプログラム動作中に併せて動作し、プログラムの実行性能に少なからず影響を与えます。

例えば、JITコンパイルは、プログラム実行当初はJavaバイトコード(ソースファイルからJavaコンパイラコンパイルしたクラスファイルに含まれる仮想マシンの命令コード)が、その実行する計算機のCPUの命令に翻訳されて実行されます(いわゆるインタープリターモード)。その後、ある処理部分が繰り返し実行され、ある閾値回数以上の繰り返しになると、その処理部分のバイトコードが実行する計算機のCPUのネイティブコードに「実行時コンパイル」されます。それ以降は実行時コンパイルされたCPUネイティブコードである処理部分が実行されるようになり、処理の実行が高速化されます。
ただし、最近の高度化したJITコンパイルでは、さらに実行を繰り返していくとより最適化されたコードに作り直すことまでやっているので、JITコンパイルされたらあとは一定の処理時間、ということではなくなっています。

ガベージコレクションは、プログラムの実行と並行して、またはあるときはプログラムの実行を停止してメモリ管理の処理を実行します。このガベージコレクションが動くことで処理が遅くなるタイミングが存在します。

処理時間の計測において、非常に短い間の処理時間を計測するマイクロベンチマークでは、JITコンパイルの影響やガベージコレクションの影響は、計測結果が大きく揺らぎます。

そこで、計測時にJITコンパイルの影響を排除するために予め計測対象コードを繰り返し実行しJITコンパイルが動いた後の状態で計測をするように、ウォームアップを行います。

また、ガベージコレクションの影響を小さくするため、計測を繰り返し実行して複数回の結果を取得し、統計処理を行います。

このような計測を、毎回ゼロから作るのはかなりだるい作業なので、お決まりの計測処理をハーネスとして用意しておき、それを利用すると簡単に計測ができるようになります。

また、Java実行環境の振る舞いを熟知していなくても、計測処理のハーネスを利用することで、Java実行環境の振る舞いを考慮した計測ができるようになります。

やってはいけない性能計測

ここで、自力でマイクロベンチマーク計測のコードを書くときにやってしまいがちなコードをいくつか挙げます。

処理の前後をSystem.currentTimeMillisで挟み、処理時間を計測する。
  :
  long start = System.currentTimeMillis();
  Some ret = doSomething();
  long stop = System.currentTimeMillis();
  System.out.println("処理時間は、" + (stop - start) + "ミリ秒でした。");

この問題は、JITコンパイルされる前のインタプリターで実行されたときの処理時間を計測している可能性があります。
また、System.currentTimeMillis()の分解能は、およそ10ミリ秒(OSやCPUによって異なりますが)なので、doSomething()にかかる時間が数十ミリ秒以下の場合、分解能が粗すぎて正確な処理時間を測れてない可能性があります。
また、1回しか処理を計測していないので、ちょうどこのタイミングでガベージコレクションが発生していたり、あるいはOSのスケジューリングでプロセスが中断されたなどの事象が発生し、doSomething()の処理時間を計測しているのではなく、ガベージコレクションやプロセスのコンテキストスイッチによる一時停止時間を計測してしまっていたということがありえます。

処理の前後をSystem.nanoTimeで挟み、処理時間を計測する。
  :
  long start = System.nanoTime();
  Some ret = doSomething();
  long stop = System.nanoTime();
  System.out.println("処理時間は、" + TimeUnit.MILISECONDS.toMillis(stop - start) + "ミリ秒でした。");

JITコンパイルされる前を計測してしまう、ガベージコレクションなどによる中断の影響は前のものと一緒です。
ただし、分解能が向上しています。

多数の繰り返しを行ってその合計時間を計測し、繰り返し回数で割る。
  :
  long start = System.currentTimeMillis();
  for (int i = 0; i < 1_000_000; i++) {
      Some ret = doSomething();
  }
  long stop = System.currentTimeMillis();
  System.out.println("処理時間は、" + (stop - start) / 1_000_000d + "ミリ秒でした。");

これなら、繰り返しの中でJITコンパイルされ、また、繰り返し数が多数なのでJITコンパイルされる前の処理は影響が皆無ではないけれど微小(1%程度)です。また、ガベージコレクションも繰り返し中に数回発生してもこれも影響が少ないです。

しかしながら、このコードではHotSpot(JITコンパイラ)の最適化が働き、ループの中で取得した値がその後の処理では未使用なので、doSomethingの処理を呼ばない(Dead code elimination)コードとなってしまう可能性があります。

では、どうすればよいか

JMHを使います。

JMHについては、過去に本日記で紹介しています。この時の日記では、Mavenを使って雛形を生成し、実行するところまでしか言及していませんでした。
JMHでマイクロベンチマーク - torutkの日記

普段Mavenは使っていないので、できればAnt(あるいはコマンドラインのjavac/java)で使いたいと思っていましたが、最近やっとやり方が見出せました。その内容は次のWikiに記載しました。
JMH - ソフトウェアエンジニアリング - Torutk

JMHについてはちらほら記事・ブログを見かけるようになりました。

なお、JMHで使用するアノテーションの記述で、@GenerateMicroBenchmarkと書かれているものは少し古いバージョンのJMHのようです。

参考文献など

JVMでのベンチマークに潜む落とし穴とその対策」(Java Magazine 2014年7・8月号(翻訳) pp.25-33)
http://www.oracle.com/webfolder/technetwork/jp/javamagazine/javamagazinevol18.zip

「JMHサンプルコード」(OpenJDKのプロジェクトサイトから)
http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-samples/src/main/java/org/openjdk/jmh/samples/