JFR Event Streamingについて(デモ解説その1)

はじめに

こんにちは、NADPチームの原木と申します。初めてこちらのNaticウェブサイトに技術ブログを寄稿いたします。よろしくお願いいたします。

Javaアプリケーションでパフォーマンスの解析をしたいとき、昨今ではJFR(Java Flight Recorder)というツールを使った解析がデファクトスタンダードになりつつあります。その中でも、モニタリング機能と親和性が高いJFR Event Streaming という機能を使う機会があったので紹介いたします。

そもそもJFRとは

Java8以上の最新のJVMランタイムを使用していれば、Javaアプリケーションならどの環境でも使用できるパフォーマンスの解析用ツールです。

JFR Event Streamingとは

JFRには二つの側面があります。それはモニタリングとプロファイリング/診断です。

JFRは、従来の使い方ではいったんJFRファイルをダンプファイルとして吐き出してそれを後から解析するプロファイリング/診断の性格が強いものでした。

しかし、Java14でJFR Event Streaming(JEP 349)の実装により、JFR情報をJFRファイルとしていったん出力することなく、プログラム上でJFRのイベントが発生したときにリアルタイムで加工、JFRファイル以外の手段で出力することができるようになりました^*1。これにより、プロファイリング/診断の機能に加えてモニタリングとして使用することも可能になりました。

例えば、Javaアプリケーションが動いているサーバーで、利用可能な物理メモリサイズを知りたいときは次のように書きます。

1
2
3
4
5
6
7
8
9
10
11
// "default" というJFR用のイベント設定ファイルを読み込んで設定します
Configuration c = Configuration.getConfiguration("default");
recordingStream = new RecordingStream(c);
// 一秒ごとにOSの利用可能な物理メモリサイズを取得します
recordingStream.enable("jdk.PhysicalMemory").withPeriod(Duration.ofSeconds(1));
recordingStream.onEvent("jdk.PhysicalMemory", event -> {
    System.out.println(event);
    System.out.println(event.getLong("totalSize"));
    System.out.println(event.getLong("usedSize"));
});
recordingStream.startAsync();

この処理をアプリケーション起動時に仕込んでおくことで、あとは非同期に一秒おきに標準出力に物理メモリサイズを出力します。

1
2
3
4
5
6
7
8
// 下記のように出力されます
jdk.PhysicalMemory {
  startTime = 12:47:10.264
  totalSize = 12.4 GB
  usedSize = 7.2 GB
}
13341421568
7707136000

たったこれだけで、利用可能なOSの物理メモリサイズをプログラム上から把握することができるようになりました。
JFRのイベントにはJDKで予め規定されたイベントと、ユーザーが設定できるカスタムイベントの二種類があります。
前者に関してはJava ChampionのTom Schindlさんが下記のウェブサイトでリファレンスをまとめてくださっているので、どのようなイベントが拾えるか一覧で見たいときはご参照ください。

https://bestsolution-at.github.io/jfr-doc/index.html

後者のユースケースは主にdefaultのイベントがモニタリングの機能要件を満たさない場合に実装します。ユーザーが設定できるカスタムイベントを用いて、独自にイベントを実装し、情報を収集することも可能です。実例は以降の章で随時説明したいと思います。

JFR Event Streamingで拾ったデータをどうやって出力するか？

前段にて、JFR Event Streamingについて説明しましたが、Javaアプリケーションのモニタリングを行うにあたり、JMX(Java Management Extensions)とは異なり、JFR Event Streamingで拾ったデータをどうやって出力するか(外部公開するか)はアプリケーションの実装で作る必要があります。

上記の例では標準出力に出しているだけですが、実際の運用フェーズではAPM用のライブラリなどと組み合わせることでアプリケーションのモニタリングを行います。今回はメソッドの処理時間と名前の情報を、メトリクス用のIFを簡単に実装できるファサードライブラリであるMicrometer経由でPrometheusに出力したいと思います。

また、JavaアプリケーションのフレームワークにはQuarkusを使用しています。

各部解説

独自イベントの設定、取得方法について

QuarkusはCDI(Contexts and Dependency Injection)が使用できるのでInterceptor機能を使用してアノテーションを付けたら自動的にJFRイベントを拾ってみるようにしました。

JFRイベントの中身はこんな感じです。メソッド名だけのシンプルなEvent情報です。

1
2
3
4
5
6
7
8
9
10
11
12
13
@Name(DatabaseRWInvocationEvent.NAME)
@Label("Database Invocation")
@Category("Database")
@Description("Invocation of a Database Dao resource method")
@StackTrace(true)
public class DatabaseRWInvocationEvent extends Event {
 
    static final String NAME = "dev.jfr.DatabaseRWInvocation";
 
    @Label("Java Method")
    public String javaMethod;
 
}

Interceptorの実装内容です。 @DatabaseRWInvokeInterceptor をつけるとその前後で処理が呼ばれて、JFRイベントを記録します。event.begin()から、 event.end() までが計測範囲になります。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
@Interceptor
@DatabaseRWInvokeInterceptor
@Priority(Interceptor.Priority.APPLICATION + 1)
public class TraceInterceptor {
 
    @AroundInvoke
    public Object obj(InvocationContext ic) throws Exception {
 
        DatabaseRWInvocationEvent event = new DatabaseRWInvocationEvent();
 
        // メソッド実行前
        preProcess(ic, event);
 
        try {
            // 次のインターセプターチェーンの実行
            Object result = ic.proceed();
 
            // メソッドの実行後
            postProcess(ic, event);
 
            return result;
        } catch (Exception ex) {
            // 例外処理
            System.out.println("exceptions happened");
            postProcess(ic, event);
            throw ex;
        }
    }
 
    private void preProcess(InvocationContext ic, DatabaseRWInvocationEvent event) {
        System.out.println("start in Interceptor");
 
        if (event.isEnabled()) {
        　　// JFRイベントの開始
            event.begin();
        }
 
    }
 
    private void postProcess(InvocationContext ic, DatabaseRWInvocationEvent event) {
        System.out.println("end in Interceptor");
        String method = ic.getMethod().getName();
        if (event == null || !event.isEnabled()) {
            return;
        }
 
        // JFRイベントの終了
        event.end();
 
        if (event.shouldCommit()) {
            event.javaMethod = method;
            event.commit();
        }
    }
}

JFRで計測したい対象メソッド、クラスにアノテーションを追加することで、JFRイベントを呼び出してくれます。下記の例では @DatabaseRWInvokeInterceptorをつけたAddressModelServiceImpl クラスのメソッドgetAddressName、getAddressNameNoCacheがJFRイベントの取得対象になります。インスタンスの永続期間に癖がありますが、CDI便利です。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
/**
 * AddressServiceImpl
 */
@ApplicationScoped
@DatabaseRWInvokeInterceptor
public class AddressModelServiceImpl implements AddressModelService {
 
    /**
     * {@inheritDoc}
     */
    @Override
    public List<AddressModel> getAddressName(String postalcode) {
      // 略
    }
 
    /**
     * {@inheritDoc}
     */
    @Override
    public List<AddressModel> getAddressNameNoCache(String postalcode) {
        // 略
    }
 
}

JFRイベントのコールバック、micrometerへの出力について

JFRイベントのコールバックは、JFRイベントの計測後、 event.commit()が呼び出された後で非同期に行われます。一度登録すると後はJFRイベントが呼ばれるたびに自動的に行われるため、Javaアプリケーションの起動時にまとめて処理します。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
@ApplicationScoped
public class Metrics {
 
    private RecordingStream recordingStream;
 
    private final MeterRegistry registry;
 
    Metrics(MeterRegistry registry) {
        this.registry = registry;
    }
 
    public void onStartup(@Observes StartupEvent se) {
        try {
            Configuration c = Configuration.getConfiguration("default");
 
            recordingStream = new RecordingStream(c);
            // 略
            recordingStream.enable(DatabaseRWInvocationEvent.NAME);
            recordingStream.onEvent(DatabaseRWInvocationEvent.NAME, event -> {
                String method = event.getString("javaMethod");
                String name = method;
                System.out.println("#### Event triggered " + name + ":" + event.getDuration());
 
                RecordedStackTrace rst = event.getStackTrace();
                if (rst != null) {
                    // エラー発生時のログスタックも出力が可能
                    List<RecordedFrame> frames = rst.getFrames();
                    System.out.println("Number of frames: " + frames.size());
                    for (RecordedFrame rf : frames) {
                        rf.getMethod().getName();
                        rf.getLineNumber();
                    }
                }
 
                // eventの処理時間合計をMicrometerのメトリクスとして出力する
                Timer timer = Timer.builder(name).description("a description of what this timer does")
                        .publishPercentiles(0.5, 0.95) // median and 95th percentile
                        .publishPercentileHistogram() // create percentile histogram
                        .minimumExpectedValue(Duration.ofMillis(1)) // 最低1ms
                        .maximumExpectedValue(Duration.ofSeconds(15000)) // 最悪の場合、15秒...
                        .tags("method", method).register(this.registry);
                timer.record(event.getDuration().toNanos(), TimeUnit.NANOSECONDS);
            });
            // 略
            recordingStream.startAsync();
        } catch (IOException |
 
                ParseException e) {
            // TODO Auto-generated catch block
            e.printStackTrace();
        }
    }
 
    public void stop(@Observes ShutdownEvent se) {
        recordingStream.close();
        try {
            recordingStream.awaitTermination();
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

JFR Eventにおける設定情報の取得方法は基本的に名前指定、ConnascenceでいうところのCoNによって行われます。リファクタリングなどの利便性を考えると定数値を積極的に使った方がいいかもしれません。

メソッドの処理時間について、 MicrometerのTimerクラスを活用して、レイテンシーのモニタリングでよく使われるヒストグラムを出力しています。この説明は後日、別の記事で詳しく説明したいと思います。

JFR Event Streamingのいいところ

JFR Event StreamingのいいところはJVMと統合されており拡張性があることだと思ってます。

JVMとの統合という観点で言えば、例えばG1GCの情報を取得できるため、負荷レベルに応じたGCの挙動からフルGCによる停止につなげないための余地保全といったことが可能でしょう。ただ正直、本当に簡単に情報が取得できてしまうので、前座で説明した運用監視の目的をはっきりさせるべきと思います^*2。

Java標準のメトリクス監視機能という観点で言えば、すでにMBeans+JMXというJVM情報をモニタリングするための仕組みがあります。しかし、古い仕様なので拡張性に乏しく、今回JFR Event Streamingのように出力形式を簡単に変えるといったことが難しいです。

まとめ

JFR Event Streamの紹介とユーザーが独自に設定したカスタムイベントの実装方法についてご紹介しました。Java 8以上で対応しているため大体の現場では使用できることから、今後は積極的に使っていきたいです。

補足

^*1 このように書くと、JFRで登録したイベントが起きるたびに処理が呼ばれて、その分遅くなるのではないか？と心配する方もいらっしゃると思いますので補足すると、JFR Event StreamingはJEP 349の記載にもあるようにJFRイベントを取得し、コールバックが発火するまでのオーバーヘッドをなるべく少なくするように設計されています。

これはモニタリングで一般的に言われていることだと思いますが、運用監視用の情報は必要十分最小限であることが大事です。そのためには取得頻度や閾値を調整して実環境に即した値を探るしかないのかなと思います。Azure Application Insightsで採用しているAdaptive Samplingのような自動調整機能があると便利なのですが…

^*2 例えば、 @StackTrace(true) をtrueにするだけでevent計測時のスタックトレースを取得可能なのですが、リアルタイムで監視する場合不要な情報です。参照するケースは障害発生時などインシデント対応が多いと思うので、即時性の高いメトリクスには障害が発生したことのみ通知して、詳細情報はログ情報に書き込むような従来通りのユースケースでいいと思います。

参照文献

実行中のアプリに関する大量のデータ・ポイントからなるストリームを取得する

Monitoring REST APIs with Custom JDK Flight Recorder Events

---

記事担当者:アプリケーション企画開発部　原木
投稿日:2020/11/20