JFR APIで作るマイクロベンチマーク

はじめに
----------

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

使い方はこんな感じ。

```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と違って性能ホットスポットをある程度自動で分析するみたいです。なにそれすごい。

![001.png](https://qiita-image-store.s3.amazonaws.com/0/54904/e8ab1962-3538-b9ec-3bcd-661ced1e4cd5.png)
![002.png](https://qiita-image-store.s3.amazonaws.com/0/54904/83568a5f-ba19-fb0c-3963-d63f75a05854.png)
![003.png](https://qiita-image-store.s3.amazonaws.com/0/54904/39e7f2a0-107a-6e11-47d5-abf4ed7ad66f.png)

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

カスタムイベントの作成
---------------

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

```java
@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`以外にもいっぱいあるのですが、まだちゃんと押さえれてないです。[ここの記事](http://hirt.se/blog/?p=870)が詳しいですが具体的な内容はjavadocやソースを見るしかないですね。

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

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

```java
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からわざわざアタッチしなくて良いのはとても便利ですね。

```java
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`を使います。

```java
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!

参考
-------
- [Java Flight Recorder in JDK 9](http://hirt.se/blog/?p=870)
- [Mission Possible - Near zero overhead profiling](https://www.jfokus.se/jfokus18/preso/Mission-Possible--Near-zero-overhead-profiling.pdf)
- [Javaコード内でjfrファイルを読もうとすると互換性に気をつけないといけない話](http://ka-ka-xyz.hatenablog.com/entry/20180617/1529234604)
- [(Tech DeepDive #1) Java Flight Recorder を活用した問題解決](https://www.slideshare.net/oracle4engineer/tech-deepdive-1-java-flight-recorder)