はじめに

みんな大好Flight RecorderですがJava9から公式にJFR APIが追加されています。
気にはなってたものの試せて無かったんですが、今回マイクロベンチマークを単に実行時間だけじゃなくてJFRで色々情報取れたら素敵じゃない？と思ってJFR APIを使って作って見ました。
Gist - koduki/TinyBenchmark.java

使い方はこんな感じ。

public static void main(String[] args) throws IOException, ParseException {
    Path path = Paths.get("test.jfr");

    benchmarks(path, "ConcatString Benchmark", 3, (loop) -> {
        System.err.println("benchmarking...");
        benchmark(loop, "Concat all string by 'plus'", () -> ConcatString.fixedStringWithPlus(1_000), 1_000);
        benchmark(loop, "Concat all string by 'plus'", () -> ConcatString.fixedStringWithPlus(100_000), 10_000);
    });
    printReport(makeReport(path));
}

benchmarksメソッドでtest.jfrを出力して、makeReportでJFRを解析して今回作ったカスタムイベントのみならず標準で取得するGCの値もサマリしてLTSVで出力してしています。
JFRが持ってるならなんの値でも取れるのでCPUとかファイルI/Oとかもやろうと思えば自在です。

実行結果:

testcase:Concat all string by 'plus'	loop:0	arguments:[1000]	response(ms):113	gc_count:0	gc_total(ms):0	gc_max(ms):0	gc_avg(ms):0.000000
testcase:Concat all string by 'plus'	loop:0	arguments:[10000]	response(ms):20784	gc_count:237	gc_total(ms):250	gc_max(ms):12	gc_avg(ms):1.054852
testcase:Concat all string by 'plus'	loop:1	arguments:[1000]	response(ms):2	gc_count:0	gc_total(ms):0	gc_max(ms):0	gc_avg(ms):0.000000
testcase:Concat all string by 'plus'	loop:1	arguments:[10000]	response(ms):13782	gc_count:224	gc_total(ms):67	gc_max(ms):10	gc_avg(ms):0.299107
testcase:Concat all string by 'plus'	loop:2	arguments:[1000]	response(ms):0	gc_count:0	gc_total(ms):0	gc_max(ms):0	gc_avg(ms):0.000000
testcase:Concat all string by 'plus'	loop:2	arguments:[10000]	response(ms):12776	gc_count:225	gc_total(ms):34	gc_max(ms):2	gc_avg(ms):0.151111

もちろんMission Controlでも見れます。今回はJMC7で開いて見ました。
6以降で結構変わったみたいでJava8についてる5.5と違って性能ホットスポットをある程度自動で分析するみたいです。なにそれすごい。

さて、続いて実装の説明をしていきます。

カスタムイベントの作成

まずはベンチマークの情報を格納するためのカスタムイベントを作ります。

@Label("Benchmark")
static class BenchmarkEvent extends Event {
    @Label("Test Case")
    String testcase;
    @Label("Loop Count")
    int loop;
    @Label("Response")
    long response;
    @Label("Arguments")
    String arguments;
}

基本はjdk.jfr.Eventを継承して必要なフィールドを足していくことで対応できそうです。
アノテーションはLabel以外にもいっぱいあるのですが、まだちゃんと押さえれてないです。ここの記事が詳しいですが具体的な内容はjavadocやソースを見るしかないですね。

カスタムイベントへの記録

続いてカスタムイベントへの記録方法です。
これもかなりシンプルです。実際に使った例はこちら。

BenchmarkEvent event = new BenchmarkEvent();

event.begin();
long s = System.nanoTime();

callback.run();

long e = System.nanoTime();

event.loop = loopCount;
event.testcase = testcase;
event.response = (e - s);
List<String> args = Arrays.stream(arguments).map(x -> x.toString()).collect(Collectors.toList());
event.arguments = "[" + String.join(",", args) + "]";
event.commit();

見ての通り、先ほど作成したカスタムイベントのBenchmarkEventをnewして、イベントの開始タイミングでbeginを実行。
フィールドに必要な値を詰めてcommitとなります。分かりやすいですね。
beginとcommitの間がdurationとして記録されてるっぽいので、今回はその間でベンチマーク対象の処理を実行しています。

プログラムからJFRの記録を実施する

JFRの普通の使い方といえばjava-agentやJVMオプションに引数指定してやる感じですよね？
私もそれしかないと思ってたのですが、最近はJavaコード上から普通に呼べるようです。
ツールとしてちゃんと作り込んだ後なら適切なオプションの指定もやぶさかでは無いですが、開発中のコードをIDEから直接ベンチしたい時にJMCからわざわざアタッチしなくて良いのはとても便利ですね。

Configuration jfrConfig = Configuration.getConfiguration("default");
try (Recording recording = new Recording(jfrConfig)) {
    recording.setName(name);
    recording.start();
    recording.enable(BenchmarkEvent.class);

    for (int i = 0; i < loopCount; i++) {
        callback.accept(i);
    }

    recording.stop();
    recording.dump(path);
}

これまた見ての通りですがjdk.jfr.Recordingを開いてstart/stopそしてdumpという形です。
一点注意点はConfigurationを取得して指定してやら無いと明示的にenableで指定したイベントしか登録されないのでCPUリソースとかメモリ状態とか欲しいならちゃんと指定する必要があります。

JFRの読み込み

長く、そう長く待ち望んでましたこの機能を！まあ、私がキャッチアップ出来てなかっただけで少なくともJava9から、非公式なら8でも出来るのかもですが。
ともかく、待望のJFRをPGで解析する方法です。JFRをCSVに変換とかしたかったので本当に嬉しい。

読み込みにはjdk.jfr.consumer.RecordingFileを使います。

List<RecordedEvent> gcEvents = RecordingFile.readAllEvents(path).stream()
        .filter((e) -> e.getEventType().getName().equals("jdk.G1GarbageCollection"))
        .collect(Collectors.toList());

readAllEventsでJFRに含まれる全イベントを取得して、必要があればStreamAPIとかでフィルタしていく形ですね。

RecordedEventはいくつかの値を含んでいます。良く使いそうなものは以下あたりでしょうか？

getEventType
getValue
getStartTime
getEndTime
getDuration

基本名前の通りなので細かい説明は省きますが、getValueにフィールドの名前を入れることで値が取得できます。Label名では無いので注意しましょう。

まとめ

JFR APIを使ってマイクロベンチマークを作って見ました。
単なる実行時間だけではなくリソース状況も分かるので地味に便利では？と思ってます。

また、今回初めてJFR APIを触ったのですがかなり良い感じですね。使いやすいですし。

カスタムイベントはもちろんですが、解析系のAPIは上手く使えばJFRの値をベースに分散トレーシング的なツールを作ったりWebアプリにしたりKibanaで解析したりと夢が広がりそうです。
JMCもJava11からはOSSでOpenJDKでもJFRが普通に使えるようになったので、今後もっと発展していくことを期待します。

しかし、Javadoc以外に公式ドキュメントが見つからないんだがコード読め的なノリなのかな？知ってる人いたら教えてください＞＜

それではHappy Hacking!

参考