Zenn
☕

JFRとモニタリングの融合？ JEP 349: JFR Event Streamingを触ってみる

2020/12/21に公開
Java
監視
jfr
micrometer
tech

この記事はJava Advent Calendar 2020の21日目です。

TL;DR

  • JFRはJavaに組込まれた診断の仕組み
  • JFR Event StraemingはJFRと同じメカニズムを使う監視の仕組み
  • MP Metrics/Micrometerを使ってPrometusなど既存の監視基盤に統合できる

今回使ったソースコードは下記に置いています。
https://github.com/koduki/example-jfr-stream

はじめに

今年もアドベントカレンダーの季節がやってきました。「2018年:JFR APIを使ってメソッドの実行時間をタイムラインレポートにしてみる」, 「2019年:JFRをBigQuery/Metabaseのオレオレダッシュボードで可視化する」とJFRネタをやってきましたが今年はなんと。。。うん、「また」なんだ。済まない。

と言うわけではからずともなのですが、3年連続でJFRネタということで今年は2020年３月にでたJDK14に含まれたJEP 349: JFR Event Streamingに関して解説をしていきたいと思います。JFR Event Streamingを使うことで今まで 「診断」 を主目的にしていたJFRで 「モニタリング」 が実施できるようになります。これは上手く使えば結構強力に使えそうなので、ぜひ活用をしていきたいですね。

JDK Filight Recoder (JFR)ってなに？

JDK Filight Recoder (JFR)はJavaというかOpenJDK([1])に組込まれた 「診断(Diagnosis)ツール」 です。CPUやGCPの状態はもちろんメソッドの呼び出し状況など詳細なプロファイル情報を取りつつ数%以下という超低負荷のため 常時本番環境でも有効 にしておくことができので障害対応を強い味方になります。標準機能なので追加のプラグインとかエージェントが不要なのも良いですね。より正確にはJFRは記録のための仕組みで保存されたファイルの情報をJMC(Java Mission Contorl)などで診断ですかね。

元々はOracleの商用機能だったのですがOpen JDK 11のタイミングでAPIを整備したうえでコミュニティに寄贈されました。なので実装が異なるAndroid以外のほぼすべてのJava環境で無料で利用できます。JVMの機能なのでJava言語以外のScalaやKotlinでも利用可能です。Oracleさん、マジ太っ腹！

詳しくは公式サイトか下記に解説サイトを絶賛作成中なのでご覧ください。なお完成予定は未定です。。。
https://koduki.github.io/docs/book-introduction-of-jfr/site/

診断(Diagnosis)と監視(モニタリング)

本題に入る前に少し言葉の説明を。
診断と監視はどちらもシステムやアプリケーションのメトリクスを収集するという意味においては同様なのですがその目的が少し異なります。

診断とは主に障害発生時に原因を分析する行為です。
JFRの名前の由来が飛行機の墜落事故時に分析するための情報を格納した「フライトレコーダ」、通常「ブラックボックス」に由来するのもそのためです。
そのため、何よりも必要な情報を精緻に記録することが優先されます。JFRではCPUやメモリの使用率といった軽量なメトリクスだけではなくスレッドダンプやメソッドのコール情報、I/Oのレスポンスタイムなど膨大な情報が含まれます。そしてこれらの情報を本番で常時取得するために実行タイミングや保存するバイナリ方式など様々な点で工夫がなされています。この書き込まれたファイルをJMCで分析して診断を行います。半面、バイナリファイルに書き出されるので少し監視用途には使いづらいのです。

一方で監視とは障害の発生またはその予兆を検知することです。
特に現在のシステムは複雑に絡み合っており個別の詳細情報よりも影響範囲を素早く特定できることが求められます。そのためメトリクスを分析基盤に集約的に集めることが重視されます。DatadogでもPrometheus/Grafanaでもなんでも良いですがどっかに集めないと相関分析ができません。システム毎にモニタリングシステムが個別とかつらいのです。半面、リアルタイムな集約のためのコストを加味して集めるメトリクスの量は絞りがちです。

New RelicやDynatraceあるいはInstanaといったAPMツールはそこら辺を両立させようと頑張っていますが本質的には別ものですね。２つのことをシームレスに出来るからこの手のツールは金払ってでも欲しいですよね。

JFR（とJMCを使う従来の方法）は繰り返しになりますが診断のための仕組みです。そこに同様のメカニズムを使いつつも監視に向いたAPIとして整備されたのがJFR Event Streamingです。

JFR Event Streaming

前置きが長くなりましたがここからJFR Event Streamingの話です。

従来はJFRは 障害発生時に何が問題であったかを分析 する診断のためのツールなのですが、いろいろ便利なので「監視にも利用できないか？」という話題はありました。少なくとも私は欲しかったし無理やりある程度はやってました。
JDK14で入った JFR Event Streaming はまさにその目的を叶えるための仕様です。具体的にはJFRイベントの発生時にイベント内容を「購読 (subscribe)」できるようになりました。何言ってるか良く分かりませんね？　はい、なのでサンプルコードを見てみましょう。

public static void main(String[] args) {
    try (var rs = new RecordingStream()) {
        rs.enable("jdk.CPULoad").withPeriod(Duration.ofSeconds(1));
        rs.onEvent("jdk.CPULoad", event -> {
            System.out.println("jdk.CPULoad: " + event.getFloat("machineTotal"));
        });
        rs.start();
    }
}

実行結果:

jdk.CPULoad: 0.18601191
jdk.CPULoad: 0.037442
jdk.CPULoad: 0.005077672
...

これはjdk.CPULoadのJFRイベントが発生した場合にmachineTotalというイベントの値を出力するコードです。
JFRではJVMやアプリケーションの様々な振舞いを「イベント」として管理します。このイベントが発生したときにコールバックで渡した処理が実行されるのがEvent Streamingの基本的な振舞いです。

この例だと少し分かりづらいのでもう少し実践的なコードに変更します。

public static void main(String[] args) throws InterruptedException {
    try (var rs = new RecordingStream()) {
        // イベントの購読を登録
        rs.enable("jdk.CPULoad").withPeriod(Duration.ofSeconds(1));
        rs.onEvent("jdk.CPULoad", event -> {
            System.out.println("jdk.CPULoad: " + event.getFloat("machineTotal"));
        });
        rs.startAsync();

        // サーバ的な処理
        long cnt = 0;
        while (true) {
            Thread.sleep(1000);
            System.out.println("本来はここでなんかサーバの処理: " + (cnt++));
        }
    }
}

実行結果:

本来はここでなんかサーバの処理: 0
本来はここでなんかサーバの処理: 1
jdk.CPULoad: 0.17361227
本来はここでなんかサーバの処理: 2
jdk.CPULoad: 0.02171118
本来はここでなんかサーバの処理: 3
jdk.CPULoad: 0.0028237326
...

実践的と言いましたが、先ほどとの主な変更点としてrs.start()からrs.startAysnc()に変更しだけです。これにより非同期処理になるので後続では処理を走らせながらもその挙動を監視することができます。実行結果では出力が入り混じっており処理と同時に監視をしているのが分かるかと思います。これだけでもだいぶ実際の利用方法をイメージしやすくなったと思います。

このように他の処理を実行しつつ、裏で任意のJFRイベントをフックしてメトリクスを処理するのがJFR Event Streamingの基本的な動作です。

「いやCPU Load値とか昔からMBeanで取れるでしょ？ 何が新しいの？」 と思う人もいるかもしれません。「君はJavaに詳しいフレンズなんだね！」
その通りでJavaにはJDK 1.5の頃よりMBeanと呼ばれる仕様が存在しておりこちらで基本的なメトリクスやカスタムメトリクスを収集することは出来ました。従来Javaで監視の役割を担っていたのはMBeanです。

ただ、さすがに古い仕様である事と拡張性があまり高くないこと、そしてなによりRESTでの取得などJava以外のエコシステムとの統合が重要視されるようになったので今回JFRと基盤を共通化させて作り直されたという背景があります。

JFRカスタムイベントと連携させてみる

JFRが標準で持つメトリクスも多岐に渡るのでこれを活用するだけでも色々出来ますが、カスタムイベントを使うことでより自分のアプリケーション固有の値やミドルウェア/FWの値も取得できるようになります。典型的なのはコネクションプール数とかスローメソッド/スロークエリですね。
JFRカスタムイベント自体の解説は下記を見てください。
https://docs.oracle.com/javase/jp/14/jfapi/create-events.html
https://koduki.github.io/docs/book-introduction-of-jfr/site/06/02-custom_event.html

ではメソッドの実行時間を計測するカスタムイベントを作成してみます。

@Category("Application Profile")
@Name("myprofile.ApiCall")
@Label("API Call")
public static class ApiCallEvent extends Event {
    @Label("Method")
    String method;
}

public static void main(String[] args) throws InterruptedException {
    try (var rs = new RecordingStream()) {
        // イベントの購読を登録
        rs.enable("myprofile.ApiCall").withPeriod(Duration.ofSeconds(1));
        rs.onEvent("myprofile.ApiCall", event -> {
            System.out.println("API Call: " + event.getDuration().getNano());
        });
        rs.startAsync();

        // サーバ的な処理
        long cnt = 0;
        while (true) {
            Thread.sleep(1000);
            var event = new ApiCallEvent();
            event.begin();
            // 本来はなんかの処理
            System.err.println("処理中:" + (cnt++));
            Thread.sleep((int) (Math.random() * 100));
            event.end();
            event.method = "method001";
            event.commit();
        }
    }
}

実行結果はこんな感じ。

処理中:0
処理中:1
API Call: 103033600
処理中:2
処理中:3
API Call: 63336000
API Call: 97383400

作成したApiCallEventを初期化してbeginとendで挟み最後にcommitしています。こうする事でイベントに指定したメソッド名やbeginとendの間の実行時間が記録されます。
そしてcommitが実行されたタイミングでonEventが発火されコールバックで指定した処理が実行されています。

また、これらの値はもちろん指定しておけばJFRとしてちゃんと診断ファイルに書き出されます。
このようにJFRイベントを使って診断も監視も同一のメカニズムで出来るのがStreaming APIの最大のポイントです。つまり監視か診断かに関わらずJavaのメトリクス情報はJFRイベントに統一できます。同じようなこと書かなくて良いのでとても便利ですね。

監視先、どこに連携するべきか？

先ほどからサンプルでは標準出力に垂れ流してますが、これでは監視になりません。やはり監視の集約基盤への連携のさせ方が肝になります。

やり方は色々ありますが大きく分けると下記の3つです。

  1. Kafka Producerなどを使って直接基盤にPushする
  2. MBean/SNMP/REST/gRPCなどを使って監視基盤からPullさせる
  3. ログに出力してログコレクターで集計させる

1はダイレクトに自分で送ってしまう方法です。基本的に監視基盤側のAPIを直接扱うことになるので何でもできますが自前で色々作りこむ必要もあるので個人的にはあまりやりたくないです。3も簡単で良いのですがログコレクタではせっかくリアルタイムに取れるので少しもったいなく感じてしまいます。
というわけで、おすすめは2の「監視基盤からPullさせる」です。特に「MP Metrics/Micrometer」や「OpenTracing/OpenTelemetry」のような標準的な仕様に連携することで監視のエコシステムに乗ることができます。こうすることで監視システム側はJFRのことを知らなくて良いので現代的な運用にスムーズに統合できます。

Quarkus + Micrometerとの連携

それでは具体的な例として Prometheus/Grafanaへの連携を想定 してQuarkus + MicrometerとJFR Event Streamingを組み合わせてみます。最初はMP MetricsでやるつもりだったのですがいつのまにかQuarkusでは非推奨になっていたので推奨されているMicrometerを使います。

3秒以上のSlow Responseを数えるメトリクスを作ってみます。

プロジェクトの作成

Quarkusのプロジェクトを作成します。

mvn io.quarkus:quarkus-maven-plugin:1.10.5.Final:create \
    -DprojectGroupId=dev.nklab.example \
    -DprojectArtifactId=jfr-stream \
    -DclassName="dev.nklab.example.GreetingResource" \
    -Dpath="/hello"

Micrometerを使うのでpom.xmlに下記の依存を追加します。quarkus-undertowはCDIで使うHttpServlet用。

<dependency>
    <groupId>io.quarkus</groupId>
    <artifactId>quarkus-undertow</artifactId>
</dependency>
<dependency>
    <groupId>io.quarkus</groupId>
    <artifactId>quarkus-micrometer</artifactId>
</dependency>
<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-registry-prometheus</artifactId>
</dependency>

JFRは標準機能なのでJDKが14以降であれば準備は必要ありません。

$ java -version
openjdk version "15.0.1" 2020-10-20
OpenJDK Runtime Environment AdoptOpenJDK (build 15.0.1+9)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 15.0.1+9, mixed mode, sharing)

これで準備はOKです。

JFRカスタムイベントとCDIインターセプタの作成

まずはカスタムイベントを作成します。

@Category({"Application Profile"})
@Label("HTTP Request")
@Name("myprofile.HttpRequest")
public class HttpRequestEvent extends Event {

    @Label("Method")
    String method;

    @Label("URL")
    String url;
}

続いて毎回自分でカスタムイベントを初期化するのも大変なのでWebTraceアノテーションを指定したら計測されるインターセプタを作成します。

インターセプト用のアノテーションを作成します。

@Inherited
@InterceptorBinding
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
public @interface WebTrace {
}

つづいてインターセプター。

@Interceptor
@Priority(Interceptor.Priority.APPLICATION)
@WebTrace
public class WebTraceIntersepter {
    @Inject
    HttpServletRequest req;

    @AroundInvoke
    public Object invoke(InvocationContext ic) throws Exception {
        var event = new HttpRequestEvent();

        event.begin();
        var result = ic.proceed();
        event.end();

        event.url = req.getRequestURI();
        event.method = req.getMethod();
        event.commit();

        return result;
    }
}

インターセプターで呼ばれた処理に対してJFRイベントで挟んで実行したうえでメタデータとしてパスとメソッドタイプを書き込んでいます。

計測対象のアプリケーションの実装

テスト対象のアプリケーションの実装をします。まあ、あまり複雑さは要らないと思うのでテンプレートのGreetingResource.javaを以下のように改造します。ランダムで遅延が再現できるように処理はスリープを入れます。

@Path("/")
public class GreetingResource {
    @WebTrace
    @GET
    @Produces(MediaType.TEXT_PLAIN)
    @Path("hello")
    public String hello() throws InterruptedException {
        Thread.sleep((int) (Math.random() * 5000));
        return "Hello JFR";
    }
}

ポイントはWebリクエストに@WebTraceアノテーションを指定していることです。これにより先ほどのCDIインターセプトが有効になるので自動的にJFRに記録されます。
計測対象のアプリケーション実装はこれだけです。アノテーションを指定する以外の対応は不要です。

JFRイベントを購読してMicrometerのメトリクスを更新

では肝心のMicrometerのメトリクスの更新処理を書きます。まず、JFRイベントの購読はアプリケーション起動時に一度だけやれば良いので@ApplicationScoped/onStartup(@Observes StartupEvent se)を使います。

@ApplicationScoped
public class MetricsRegister {

    private RecordingStream recordingStream;
    private final MeterRegistry registry;

    public MetricsRegister(MeterRegistry registry) {
        this.registry = registry;
    }

    public void onStartup(@Observes StartupEvent se) throws IOException, ParseException {
        // micrometer向けにカスタムのカウンターを作成
        var slowCounter = registry.counter("my_request_slow");
        var totalCounter = registry.counter("my_request_all");

        // JFRイベントを購読
        recordingStream = new RecordingStream();
        recordingStream.enable("myprofile.HttpRequest").withPeriod(Duration.ofNanos(1));
        recordingStream.onEvent("myprofile.HttpRequest", event -> {
            // JFRからHTTP Requestの実行時間を取得
            var url = event.getString("url");
            var sec = event.getDuration().getSeconds();
            var nano = event.getDuration().getNano();
            System.out.println("url:" + url + ", sec:" + sec + ", nano:" + nano);

            // Micrometerのメトリクスを更新
            totalCounter.increment();
            if (sec >= 3) {
                slowCounter.increment();
            }
        });
        recordingStream.startAsync();
    }

    public void stop(@Observes ShutdownEvent se) {
        recordingStream.close();
        try {
            recordingStream.awaitTermination();
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

onStartupがアプリケーションの起動時、stopがアプリケーションの終了時です。起動時にJFRイベントの購読処理を書いて、終了時にクローズさせています。
購読時のコールバック処理として、JFRイベントから取得した情報をもとにMicrometerに書き込んでいます。
もちろん、JFRイベントで取得した値すべてを連携することも可能なのですが、本来的なメトリクスの意義とかを考えると統計情報があれば良いのでアプリケーション側でこのような軽い前処理をするのもパフォーマンス的に良い気がします。
このあたりの 何をメトリクスとして監視ツールに連携するか？ はケースバイケースだと思うので試行錯誤が必要そうです。

なお、Micrometer自体の細かな使い方は下記が参考になります。
https://micrometer.io/docs/concepts

メトリクスを確認する

最後に実際にメトリクスを確認してみます。まず軽く負荷をかけたいのでsiegeを入れます。まあabでもGatlingでも何でも構いません。

sudo apt-get install siege

アプリケーションを起動させます。

$ ./mvnw compile quarkus:dev
...
2020-12-20 22:52:29,807 INFO  [io.quarkus] (Quarkus Main Thread) example-jfr-stream 1.0.0-SNAPSHOT on JVM (powered by Quarkus 1.10.5.Final) started in 1.392s. Listening on: http://localhost:8080
..
2020-12-20 22:52:29,820 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [cdi, micrometer, resteasy, servlet]

続いて負荷を適当に書けます。

$ siege -c 5 -t 30S "http://localhost:8080/hello"

サーバ側のログは下記のようになっているはずです。JFR Event Stramingが適切に購読出来ていることが分かります。

url:/hello, sec:0, nano:681152600
url:/hello, sec:3, nano:488120000
url:/hello, sec:4, nano:584124800
url:/hello, sec:0, nano:361325600
url:/hello, sec:0, nano:520161500
url:/hello, sec:4, nano:527123300

ではメトリクスを確認します。/metricsにアクセスしてみます。

$ curl "http://localhost:8080/metrics"|grep my_request
# HELP my_request_all_total
# TYPE my_request_all_total counter
my_request_all_total 56.0
# HELP my_request_slow_total
# TYPE my_request_slow_total counter
my_request_slow_total 25.0

Prometheus形式でちゃんと値が取れてますね！ 数えてないですがslowの方が数が少ないのでちゃんと意図通りにトータルリクエスト数とスローリクエスト数のメトリクスをJFRの値から取得できました。

この値はJFRの診断情報としても登録されているので監視系と診断系でメトリクスを2重で取得する必要もなく非常に効率的ですね。

JFR Event Streamingでするべきではないこと

ここまで「JFR Event Straeming良いよ！ 監視に最適だよ！」と言ってきたわけですが、ではどのような処理はJFR Event Streamを避けるべきでしょうか？

Marcus Hirtさんによると特定の処理ではJFR Event Stramingの利用は避けるべきだと言っています。それは「診断」です。
最初に説明した「診断」と「監視」の違いを思い出してください。診断では監視と違い大量の情報を必要とします。そのためJFRには様々な仕掛けがあり効率的に収集しファイルに格納できますが、JFR Event Streamingにはそれがありません。元の仕組みが同じなので収集の部分はさておきとして、効率的にイベントプロセスを実行したりデータを送信するためには様々な工夫が必要です。そうした効率的にファイルに大量の方法を書き出すのはすでにJFRでされてることなので可能であればそちらを活用するべきです。なので新しいAPIだからなんでもEvent Streamingという分けではなく適材適所で既存のJFRの機能と組み合わせた運用になります。てか、目的が別ですからね。

また、これは私見ですがJDK14以降を使うことが前提にできるならメトリクスの基盤としてMBeanを使う必要はほぼないでしょう。レガシー互換としてMBeanのI/F自体は作って問題ないと思いますが、その場合も内部実装はJFR Event Stramingを使ってMicrometerのMBean I/Fなどを使うのがよいかと思います。
この理解は間違ってそうなので取り下げます。

自分で頑張るしかないの？

いろいろ便利そうですが自分で色々作りこむの面倒という方もいると思います。今回、記事を書くために調べていたなんか良さそうなのを見つけましたので紹介します。

container-jfr-operatorはどうやらJFRをsidecarで取得してWeb画面で分析したりGrafanaに展開する機能を持っているようです。コンテナでJavaの運用をする場合はJFRとの相性が悪かったのですが、こいつを使えばかなりの部分が解決しそうですね。

https://github.com/rh-jmc-team/container-jfr-operator

まだエアプなのでどのくらい使えるかは分かりませんが、動画の発表を見る限りだとかなり良さそうだったので機会があれば使ってみたいです。

まとめ

通算3回目のJFRネタなアドベンドカレンダーになりました。実は「JDK Flight Recorder入門」を完成させてアドカレで出せないかとも思ったのですが普通に間に合いませんでしたorz
　なので、そのネタの一部として今回JFR Event Straemingに関してまとめたという感じです。

JFR Event Straemingはなんだかんだであまり触れてなかったのですが、今回試してみた限りだとやはり中々良さそうです。
Event Streamを介する事でJFRの強力な分析能力をOpenTracingやMetrics/Micrometerといった標準的な仕組みにシームレスに取り込む事ができます。「これからのJava」という感じの機能です。もうJavaエコシステムの中だけで完結する時代ではないですから。今後はJava系のライブラリやミドルウェアを作るときはJFRカスタムイベントをベースに集計の基盤を作り、必要に応じてMicrometerなどに連携する事で診断と監視の両立をJava以外のエコシステムとともにできそうです。

また、今回はMicrometerで試しましたが、トレーシング機能も含めてOpenTelemetryとうまく統合できないかも試してみたいです。また確か別のプロセスを監視する機能もあったはずなのでこの辺をうまく使うと負荷の分離とかができるかもしれません。いずれにしてもまだまだ調査が必要ですね。

それでは2021年もJavaとJavaエンジニアが楽しく過ごせますように。それではHappy Hacking!

参考

脚注

  1. Oracle JDKを含めたほぼすべての主要なJDKのコードベース。有名な別実装はIBMのOpen J9とAndroidのDalvik/ART。 ↩︎

Discussion