JFRのイベントをCSVに出力する

JDK Flight RecorderファイルをJDK Mission Controlで分析して異常を見つけたら、レポートを作成するためにExcelに取り込みたいなぁと思うことがあります。その場合はjfrコマンドとjqコマンドを使って任意のイベントをCSVに変換しましょう。

イベントを探す

CSVファイルを作る前に、イベントが持つ要素名を取得しないといけません。そのためにはまず、そのイベントの名前を探して、次にそのイベントが持つ要素名を取得します。

ここで使用するのはjfrコマンドのサブコマンドであるmetadataです。これらを以下のように使います。

jfr metadata <JFR file>  | grep @Name
jfr metadata --events <Event Name> <JFR file>

まず最初に、イベントの名前を探しましょう。イベントの名前はメタデータの@Nameアノテーションに記載されています。そのため、JFRファイルが持っているイベントの@Nameアノテーションを全て表示しましょう。たくさん出力されるので、grepを追加して引っかかりそうなキーワードでフィルタすることをお奨めします。

> jfr metadata <JFR file>  | grep @Name
@Name("jdk.TenuringDistribution")
@Name("jdk.ThreadAllocationStatistics")
@Name("jdk.ThreadCPULoad")
@Name("jdk.ThreadContextSwitchRate")
@Name("jdk.ThreadDump")
@Name("jdk.ThreadEnd")
@Name("jdk.ThreadPark")
@Name("jdk.ThreadSleep")
@Name("jdk.ThreadStart")
@Name("jdk.UnsignedIntFlag")
@Name("jdk.UnsignedIntFlagChanged")
@Name("jdk.UnsignedLongFlag")
@Name("jdk.UnsignedLongFlagChanged")
@Name("jdk.YoungGarbageCollection")

次に、そのイベントが持つメタデータを取得しましょう。metadataサブコマンドではJFRが持つ全てのイベントのメタデータを表示します。イベントの数は膨大にあるのでその出力結果からメタデータを探すのは大変です。そのため、先ほど取得したイベントの名前でフィルタを掛けて実行しましょう。今回はjdk.CPULoadというCPUの負荷情報のメタデータを取得します。

> jfr metadata --events jdk.CPULoad <JFR file>
@Name("jdk.CPULoad")
@Category({"Operating System", "Processor"})
@Label("CPU Load")
@Description("OS CPU Load")
class CPULoad extends jdk.jfr.Event {
  @Label("Start Time")
  @Timestamp("TICKS")
  long startTime;

  @Percentage
  @Label("JVM User")
  float jvmUser;

  @Percentage
  @Label("JVM System")
  float jvmSystem;

  @Percentage
  @Label("Machine Total")
  float machineTotal;
}

イベントをCSVへ出力

これでようやく本題であるイベントをCSVへ出力できます。以下のようなコマンドを使用してCSVへ出力します。

jfr print --json --events <イベント名> <JFR file>  | jq -r ".recording.events[].values | [<出力したい要素を羅列>] | @csv"

出力したい要素は先ほど取得したイベントのメタデータからフィールド名に該当する部分の先頭に.を付けて、各要素間はカンマ区切りで羅列します。CPULoadのJVMのユーザ領域とシステム領域を出力する場合は.jvmUser, .jvmSystemになります。

以下の例は、イベントの発生時間、JVMのユーザ領域の使用量、JVMのシステム領域の使用量、マシン全体の使用量を出力する例です。

jfr print --json --events jdk.CPULoad <JFR file>  | jq -r ".recording.events[].values | [.startTime, .jvmUser, .jvmSystem, .machineTotal] | @csv"
"2022-03-23T1:23:45.123456789+09:00",0.01234567890,0.01234567890,0.01234567
"2022-03-23T1:23:46.123456789+09:00",0.01234567890,0.01234567890,0.01234567
"2022-03-23T1:23:47.123456789+09:00",0.01234567890,0.01234567890,0.01234567

この結果をファイルにリダイレクトすることでCSVファイルが作成されます。

おまけ

JFRのイベントには期間（Duration）を持つイベントが多くあります。そのようなイベントの1つであるソケット読み込みの例も記載しておきます。メタデータの詳細が気になる場合は先述の手順で取得してください。

jfr print --json --events jdk.SocketRead <JFR file>  | jq -r ".recording.events[].values | [.startTime, .duration, .host, .address] | @csv"
"2022-03-23T1:23:45.123456789+09:00","PT0.012345678S","service-a","172.30.1.1"
"2022-03-23T1:23:45.123456789+09:00","PT0.012345678S","service-b","172.30.1.2"
"2022-03-23T1:23:45.123456789+09:00","PT0.012345678S","service-a","172.30.1.2"

QuarkusのReactiveからBlockingする処理を呼び出す方法まとめ

前回（Quarkusはどのようにスレッドを使うのか - #chiroito ’s blog）の記事にある通り、QuarkusでReactiveのアプリケーション開発をしていると、Reactiveに対応したデータストアのAPIを使います。これによってReactiveのメリットを完全に得られます。ですが、全てのデータストアがReactiveに対応したAPIを提供しているわけではありません。

Reactiveに対応していないAPIを使う場合、Reactiveの中でBlockingするAPIを呼び出す必要があります。この時、Blockingする処理はReactiveが使うI/Oスレッドとは異なるスレッドで実行するのが良いです。

QuarkusではReactive用のスレッドからBlockingする処理を実行する方法がいくつかあるので、それぞれについて紹介します。

• Blocking用のスレッドを使うようにメソッドシグネチャを指定する
• @Blockingアノテーションを指定してBlocking用のスレッドを使うように明示する
• ReactiveにCompletableFutureを渡す

Blockingするクライアント

今回の検証ではBlockingする処理はReactiveではないREST Clientを使ってREST APIへアクセスします。REST Clientのインターフェースは以下になります。

@Path("/delay")
@RegisterRestClient(configKey = "delay")
public interface BlockingRestClient {

    @GET
    @Produces(MediaType.APPLICATION_JSON)
    @Consumes(MediaType.APPLICATION_JSON)
    Message invoke();
}

このREST ClientをエンドポイントでDIして使用します。

    @Inject
    @RestClient
    BlockingRestClient blockingRestClient;

検証

メソッドシグネチャ

Blocking用のスレッドを使うようにメソッドシグネチャを指定します。戻り値にUniなどReactive系のクラスを使わなければBlocking用のスレッドを使います。

    @GET
    @Path("/api")
    public Message endpoint1() {
        return blockingRestClient.invoke();
    }

JFRを見ると、Blocking処理がexecutor-thread-0で動いているのが分かります。

Reactiveを使わない場合

@Blockingアノテーション

次はメソッドのシグネチャにはReactive系のクラスであるUniを使いますが、@Blockingアノテーションを指定してBlocking用のスレッドを使うように明示します。

    @GET
    @Path("/annotation/api")
    @Blocking
    public Uni<Message> endpoint2() {
        return Uni.createFrom().item(blockingRestClient.invoke());
    }

JFRを見ると、こちらも先ほどと同様にBlocking処理がexecutor-thread-0で動いているのが分かります。

Reactiveを使うが@Blockingアノテーションを指定した場合

CompletableFuture

最後に、Javaの非同期APIであるCompletableFutureを引数としてUniへ渡す方法です。様々なAPIがCompletableFutureに対応しているので既存の知識やコードを流用して実装できるメリットがあります。

    @GET
    @Path("/completableFuture/api")
    public Uni<Message> endpoint3() {
        return Uni.createFrom().completionStage(CompletableFuture.supplyAsync(() -> blockingRestClient.invoke()));
    }

この方法ではこれまでと異なり、Blocking処理はJavaの実行環境が提供するForkJoinPoolのスレッドで実行されます。スレッド名はForkJoinPool.commonPool-worker-nです。

ReactiveとCompletableFutureを使う場合

なお、ForkJoinPoolのスレッド数はJVM起動引数-Djava.util.concurrent.ForkJoinPool.common.parallelismで指定します。

おまけ

当然ながら以下のようにReactive用のI/OスレッドでBlocking処理を実行できます。

    @GET
    @Path("/blocking/api")
    public Uni<Message> endpoint4() {
        return Uni.createFrom().item(blockingRestClient.invoke());
    }

この場合I/OスレッドがBlockingされてるのが分かります。

Reactiveを使ってブロック処理を実行

この方法はスレッドの遷移がなくなるため、これ単体だと多少高速に動くのですが、I/Oスレッドが不足するとNon Blockingで動いている処理のスループットが頭打ちになりやすく、スレッド数のチューニングが必要となります。さまざまな用途で使用されるスレッドプールのチューニングは難しいため、チューニングに慣れてない人はBlockingを使いましょう。

Quarkusはどのようにスレッドを使うのか

Quarkusを使ったアプリケーション開発では、従来のフレームワークなどで使われている命令型に加え、ここ最近のフレームワークで使われているReactive型の２種類の実装方法が選べます。命令型の実装ではBlockingとして動作し、Reactiveの実装ではNon Blockingで動作します。

Quarkus自体はReactiveネイティブで実装されています。そのため、HTTPのエンドポイントを命令型で実装しても、エンドポイントの部分だけBlockingで動きますが、他の部分はReactiveの恩恵を受けられます。また、そのエンドポイントをReactiveで実装することで全てNon Blockingで動作します。アプリケーションはRDBMSやREST APIなどへ通信することがありますが、これらをReactiveで実装するにはこれらのAPIがReactiveに対応している必要があります。

今回は従来型の実装とReactive型の実装で使われるBlockingとNon Blockingの２つが、どの様に性能に影響し、どの様にスレッドを使用しているかを確認します。

ReactiveやBlocking/Non Blockingについての聞き慣れない方もいると思いますが、本記事では説明を省略します。検索すると素晴らしい記事がたくさん見つかりますので、そちらを確認してぜひ知識として身に付けてみてください。

性能検証の構成

今回の検証では、検証対象となるアプリケーションから別のサービスを呼び出します。このサービスでは処理を擬似的に再現するため10ms遅延します。

命令型の実装では検証対象となるコードからサービスの呼び出しをBlockingで呼び出し、Reactive型の実装ではNon Blockingで呼び出します。

性能検証の構成

今回の検証では0.5コアを割り当てたコンテナを2つ動かして1コアを使い切る形にしています。その理由は、1コア*1プロセスではHTTPリクエストを受け付けるスレッドをおよそ1900件/秒で使い切ったためです。この際のCPU使用率は70%程度であり、この負荷が上限でした。そのため、プロセスを2つに分けることでこのスレッドの負荷を半減しています。

また、性能試験をするにあたり、負荷ツールや呼び出されるサービスがボトルネックにならないようにもしています。今回用意した環境では、負荷ツールは8,000件/秒の負荷を生成でき、呼び出されるサービスは30,000件/秒処理できます。この性能は検証対象と比べてはるかに大きいため、検証対象以外がボトルネックになりません。

性能の違い

命令型とReactive型のどちらでもCPUを1コア使いきりました。Reactiveによる実装のスループットは、同じリソース量で動く従来型と比べておよそ30%高いです。

スループットの比較

実装例

次にアプリケーションの実装を見ていきます。

今回は負荷ツールから検証対象のREST APIにアクセスして、そのAPIからさらにサービスを呼び出します。 QuarkusではBlocking用のスレッドであるワーカースレッドとNon Blocking用のスレッドであるI/Oスレッドを用意しています。REST APIのメソッドシグネチャによってどちらのスレッドを使うかが決まります。

この使い分けは非常に重要で、必ず守らないといけません。

参考：Quarkus - RESTEasy Reactive - ブロックするか、ブロックしないか

今回、全ての箇所でやり取りするオブジェクトは以下のMessageクラスのオブジェクトです。

public class Message {
    public String message;

    public Message(String message) {
        this.message = message;
    }

    public Message() {
    }
}

命令型の実装

Quarkusでは命令型の実装を使うには以下の依存関係を使用します。quarkus-resteasyはHTTPを受け付けるもので、quarkus-rest-clientはREST APIクライアントです。

<dependency>
    <groupId>io.quarkus</groupId>
    <artifactId>quarkus-resteasy</artifactId>
</dependency>
<dependency>
    <groupId>io.quarkus</groupId>
    <artifactId>quarkus-rest-client</artifactId>
</dependency>

Quarkusでは、REST APIのクライアントはインターフェースを定義するだけで作成されます。このインターフェースではBlocking/Non Blockingどちらも対応していますが、こちらはBlockingの実装です。

@Path("/delay")
@RegisterRestClient(configKey = "delay")
public interface BlockingRestClient {

    @GET
    @Produces(MediaType.APPLICATION_JSON)
    @Consumes(MediaType.APPLICATION_JSON)
    Message invoke();
}

最後に負荷ツールがアクセスするエンドポイントを作成し、その中で別のサービスを呼び出します。フィールドとして、上記のクライアントをDIします。

@Path("/api")
@Produces(MediaType.APPLICATION_JSON)
@Consumes(MediaType.APPLICATION_JSON)
public class TestEndPoint {

    @Inject
    @RestClient
    BlockingRestClient blockingRestClient;

    @GET
    public Message endpoint() {
        return blockingRestClient.invoke();
    }
}

Reactive型の実装

Reactive型の依存関係には命令型のartifactIdの最後に-reactiveを付けます

<dependency>
    <groupId>io.quarkus</groupId>
    <artifactId>quarkus-resteasy-reactive</artifactId>
</dependency>
<dependency>
    <groupId>io.quarkus</groupId>
    <artifactId>quarkus-rest-client-reactive</artifactId>
</dependency>

クライアントの実装方法の違いは戻り値の型がUni<Message>になっていることだけです。UniはQuarkusがReactiveの実装で使用しているsmallryeのクラスです。この違いだけでこのクライアントはNon Blockingになります。

@Path("/delay")
@RegisterRestClient(configKey = "delay")
public interface NonBlockingRestClient {

    @GET
    @Produces(MediaType.APPLICATION_JSON)
    @Consumes(MediaType.APPLICATION_JSON)
    Uni<Message> invoke();
}

エンドポイントの実装では、同様に戻り値の型をUni<Message>にします。その中で上記のクライアントを呼び出します。

@Path("/api")
@Produces(MediaType.APPLICATION_JSON)
@Consumes(MediaType.APPLICATION_JSON)
public class TestEndPoint {

    @Inject
    @RestClient
    NonBlockingRestClient nonBlockingRestClient;

    @GET
    public Uni<Message> endpoint() {
        return nonBlockingRestClient.invoke();
    }
}

スレッドの使い方を確認する

先述の通り、QuarkusではBlocking用のスレッドであるワーカースレッドとNon Blocking用のスレッドであるI/Oスレッドを用意しています。 ワーカースレッドの名前はexecutor-thread-n、I/Oスレッドの名前はvert.x-eventloop-thread-nです。

今回はJDK Flight Recorderを使って記録したスレッドのイベント情報をJDK Mission Controleを使って確認していきます。具体的な図は後述しますが、スレッドの状態では赤がソケットからの読み込み待ち、水色がソケットへの書き込み待ちです。緑の部分は待ちがないことを表しています。

命令型でのスレッドの使い方

まずはじめに命令型でのBlockingのスレッドの使い方を見てみましょう。

Blockingでのスレッドの使い方

Blockingによる実装では、負荷ツールからのHTTPリクエストをvert.x-eventloop-thread-1で受け取り、Blocking処理であるサービスの呼び出しはexecutor-thread-0で実行されています。

サービスの呼び出しを呼び出しているexecutor-thread-0は、ソケット書き込みであるHTTPリクエスト（見えないかもしれませんが、2つの赤の間に記録されてます）をしてからサービスが処理をしている間（今回は10ms）ずっと返事を待っています（大きい赤が該当）。

しかし、負荷ツールとやり取りをするvert.x-eventloop-thread-1はソケットの読み書き待ちにほとんど時間が掛かっていません。

Reactive型でのスレッドの使い方

次にReactive型でNon Blockingのスレッドの使い方を見てみましょう。

Non Blockingでのスレッドの使い方

こちらは全てNon Blockingで動くためexecutor-thread-0は使用しておらず、なにも待機イベントは発生していません。

また、vert.x-eventloop-thread-1は負荷ツールとサービスの呼び出しを実行していますが、全てのソケットの読み書きのイベントは数十μsで終わっています。Blockingにあったように返事を待つようなことをせずにスレッドを有効に活用できるようになっています。

まとめ

Blockingを使った命令型の実装と比べてNon Blockingを使ったReactive型の実装は、スレッドの待機イベントを削減できスレッドを有効的に使えます。同じ量のCPUを割り当ててるにもかかわらず30%以上のスループット向上が実現できます。これによって、CPUを効率よく使えるようになり、インフラに掛かるコストが30%抑えられるようになるでしょう。

Quarkusを使い、JDBCなどのクライアントAPIがReactiveに対応している場合にはReactive型の実装をしてみてください。

次回は、よくありがちな間違った使い方をすると性能やスレッドの使い方がどうなるかについて紹介します。