CLOVER🍀

That was when it all began.

JDK Flight Recorder(JEP 328/JFR)とJDK Mission Control(JMC)を試す

これは、なにをしたくて書いたもの?

JDK Flight Recorder(JFR)とJDK Mission Control(JMC)について見てみようと思いつつ、ずっとそのままにしていたのでそろそろ
ちゃんと見ておこうかなということで。

なお、今回はざっくりコマンドの使い方の雰囲気だけを見ることにしておきます。

JEP 328:Flight Recorder(JFR)

JEP 328:Flight Recorder、JDK Flight Recorder(JFR)のページはこちら。

JEP 328: Flight Recorder

JFRはJavaアプリケーションとHotSpot JVMのトラブルシュートのための、オーバヘッドの少ないデータ収集フレームワークです。
要するにトラブルシューティング、モニタリング、プロファイリングを行う仕組みです。OpenJDK 11で導入されています。

JEP 328: Flight Recorder

OpenJDK 8にはu262でバックポートされたみたいです。

OpenJDK 8u262 Released

Backport JFR to OpenJDK 8

もっとも、実際に多くのディストリビューションで使えるのはu272以降のようですが。

モジュールもあり、APIを使って自分でイベントやデータの記録もできるようです。

APIを使用する理由

今回は、javaコマンドやjcmdによるJFRを使ったデータの記録にフォーカスしたいと思います。

javaコマンドに-XX:StartFlightRecordingオプションを使うことで、JFRの記録を開始します。

-XX:StartFlightRecording=parameter=value

指定できるパラメーターはこちらです。オプションを複数指定する場合は、「,」区切りで指定します。

  • delay … Javaアプリケーションの起動から記録を開始するまでの時間。秒(s)、分(m)、時間(h)、日(d)単位で指定可能。デフォルトは0
  • disk … 記録中にディスクを書き込むかどうかをtrue/falseで指定。デフォルトはtrue
  • dumponexit … Java VMが停止する時に実行中の記録をダンプするかどうかをtrue/falseで指定する。trueを指定してfilenameを入力していない場合は、レコーディングをプロセスを起動したディレクトリに保存しファイル名は自動で決定する。デフォルトはfalse
  • duration … 記録の継続時間を秒(s)、分(m)、時間(h)、日(d)単位で指定する。デフォルトは0で期間は制限されない
  • filename … 記録を停止する時に、結果を書き込むファイルパスを指定。%pでJava VMのPID、%tで現在のタイムスタンプを意味する書式文字列を使用可能
  • name … 記録の名前と識別子を指定
  • maxage … 記録を保持するディスクデータの最大保持期間を指定する。disk=trueの場合のみ有効。秒(s)、分(m)、時間(h)、日(d)単位で指定する。デフォルトは0で最大保持期間は制限されない
  • maxsize … 記録を保持するディスクデータの最大サイズ(バイト単位)を指定する。disk=trueの場合のみ有効。-XX:FlightRecorderOptionsのmaxchunksizeの指定値より小さくできない。m/MでMB単位、g/GでGB単位で指定する。デフォルトは0で最大サイズは制限されない。
  • path-to-gc-roots … 記録の終了時にGCのルートへのパスを収集するかどうかをtrue/falseで指定。デフォルトはfalse
  • settings … イベント設定ファイルのパスと名前を指定する。デフォルトは${JAVA_HOME}/lib/jfr/default.jfc

また-XX:FlightRecorderOptionsでJFRの動作を制御するパラメーターを設定できます。こちらはパラメーター名のみ載せておきます。

  • globalbuffersize
  • maxchunksize
  • memorysize
  • numglobalbuffers
  • old-object-queue-size
  • preserve-repository
  • repository
  • retransform
  • stackdepth
  • threadbuffersize

javaコマンド

またjcmdでもJFRの操作や設定ができます。

  • JFR.start … JFRの記録の開始。-XX:StartFlightRecordingと同等で、オプションも同じ
  • JFR.stop … JFRの記録の停止
  • JFR.configure … JFRの設定を行う。-XX:FlightRecorderOptionsで設定できるオプションほぼ同等
  • JFR.dump … JFRの記録をダンプする
  • JFR.check … 実行中のJFRの記録の情報を表示する

jcmdコマンド

実際に使う時はjava-XX:StartFlightRecording〜やjcmd [PID] JFR.start、jcmd [PID] JFR.stop、jcmd [PID] JFR.dump`あたりになるでしょう。

結果を確認するプリミティブな操作としてはjfrコマンドというものも使えるようですが、実際には後述のJDK Mission Controlを使うことに
なるでしょう。

jfrコマンド

JDK Mission Control(JMC)

JDK Mission Control(JMC)は、Java VMに対してJFRによる記録を行ったり、JFRで記録したファイルを分析できたりするツールです。

JDK Mission Control (JMC)

JMCのGitHubリポジトリーはこちら。

GitHub - openjdk/jmc: Repository for OpenJDK Mission Control, a production time profiling and diagnostics tools suite. https://openjdk.org/projects/jmc

JMCはOpenJDKには同梱されておらず、別途ダウンロードする必要があります。

JMCのGitHubリポジトリーに記載がありますが、以下が主要なダウンロード先ですね。

Eclipse Mission Control。

Eclipse Mission Control | Adoptium

Azul Mission Control。

Azul Mission Control - Azul | Better Java Performance, Superior Java Support

Liberica Mission Control。

Liberica Mission Control

JMC for Corretto(OpenJDK 8、11まで)。

GitHub - corretto/corretto-jmc: A build of JDK Mission Control (JMC) by the Corretto team.

そしてOracle、Red HatからもJMCが提供されています(有償)。

JDK Flight RecorderとJDK Mission Controlについては、このあたりも参考にするとよいかもしれません。

Zulu Flight Recorder と Mission Control を使用してデータを確認する | Microsoft Learn

Red Hat build of OpenJDK での JDK Flight Recorder の使用 | Red Hat Product Documentation

Using Java Flight Recorder - Quarkus

今回は簡単なアプリケーションを作成し、JFRで記録、JMC(Eclipse Mission Control)で確認してみたいと思います。
分析のテーマはヒープだったりといくつかあると思いますが、今回は処理に時間のかかるメソッドを実行してどのような結果が得られるのかを
見ていきたいと思います。

環境

今回の環境はこちら。

$ java --version
openjdk 21.0.5 2024-10-15
OpenJDK Runtime Environment (build 21.0.5+11-Ubuntu-1ubuntu124.04)
OpenJDK 64-Bit Server VM (build 21.0.5+11-Ubuntu-1ubuntu124.04, mixed mode, sharing)


$ mvn --version
Apache Maven 3.9.9 (8e8579a9e76f7d015ee5ec7bfcdc97d260186937)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 21.0.5, vendor: Ubuntu, runtime: /usr/lib/jvm/java-21-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "6.8.0-49-generic", arch: "amd64", family: "unix"

サンプルアプリケーションの作成

確認対象のアプリケーションがないと始まらないので、簡単なものを作成します。今回はJakarta RESTful Web Services(JAX-RS)の
SeBootstrapを使うことにしました。実装はRESTEasyです。

    <properties>
        <maven.compiler.release>21</maven.compiler.release>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.jboss.resteasy</groupId>
            <artifactId>resteasy-core</artifactId>
            <version>6.2.11.Final</version>
        </dependency>
        <dependency>
            <groupId>org.jboss.resteasy</groupId>
            <artifactId>resteasy-undertow-cdi</artifactId>
            <version>6.2.11.Final</version>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-dependency-plugin</artifactId>
                <version>3.8.1</version>
                <executions>
                    <execution>
                        <id>copy-dependencies</id>
                        <phase>prepare-package</phase>
                        <goals>
                            <goal>copy-dependencies</goal>
                        </goals>
                        <configuration>
                            <outputDirectory>${project.build.directory}/libs</outputDirectory>
                        </configuration>
                    </execution>
                </executions>
            </plugin>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-jar-plugin</artifactId>
                <version>3.4.2</version>
                <configuration>
                    <archive>
                        <manifest>
                            <addClasspath>true</addClasspath>
                            <classpathPrefix>libs/</classpathPrefix>
                            <mainClass>org.littlewings.jfr.Server</mainClass>
                        </manifest>
                    </archive>
                </configuration>
            </plugin>
            <plugin>
                <groupId>org.jboss.jandex</groupId>
                <artifactId>jandex-maven-plugin</artifactId>
                <version>1.2.3</version>
                <executions>
                    <execution>
                        <id>make-index</id>
                        <goals>
                            <goal>jandex</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>

Maven Dependency PluginとMaven Jar Pluginを使って、java -jarで起動できるようにしてあります。

Jandex Maven PluginはJAX-RSのリソースクラスのスキャン用ですね。ところで、RESTEasyのSeBootstrapで使うJandexはSmallRyeの
groupIdのものではダメなようでしたね。

JAX-RSの有効化。

src/main/java/org/littlewings/jfr/RestApplication.java

package org.littlewings.jfr;

import jakarta.ws.rs.ApplicationPath;
import jakarta.ws.rs.core.Application;

@ApplicationPath("/")
public class RestApplication extends Application {
}

JAX-RSリソースクラス。10秒スリープするエンドポイントと、フィボナッチ数を計算してCPUを消費するエンドポイントを作成しました。
フィボナッチ数も手元の環境ではこの数字で約10秒かかります。

src/main/java/org/littlewings/jfr/JfrTestResource.java

package org.littlewings.jfr;

import java.util.concurrent.TimeUnit;

import jakarta.ws.rs.GET;
import jakarta.ws.rs.Path;
import jakarta.ws.rs.Produces;
import jakarta.ws.rs.core.MediaType;

@Path("/jfr-test")
public class JfrTestResource {
    @GET
    @Path("/sleep")
    @Produces(MediaType.TEXT_PLAIN)
    public String sleep() throws InterruptedException {
        long sleepTime = 10L;

        TimeUnit.SECONDS.sleep(sleepTime);

        return String.format("sleep[%d] sec", sleepTime);
    }

    @GET
    @Path("/heavy")
    @Produces(MediaType.TEXT_PLAIN)
    public String heavy() {
        int n = 46;

        long result = fib(n);

        return String.format("fib[%d]: %d, done", n, result);
    }

    private int fib(int n) {
        if (n <= 1) {
            return n;
        }

        return fib(n - 1) + fib(n - 2);
    }
}

mainメソッドを持ったクラス。サーバーを起動後、Enterを打つと終了します。

src/main/java/org/littlewings/jfr/Server.java

package org.littlewings.jfr;

import java.util.concurrent.ExecutionException;

import jakarta.ws.rs.SeBootstrap;
import org.jboss.logging.Logger;

public class Server {
    public static void main(String... args) throws ExecutionException, InterruptedException {
        Logger logger = Logger.getLogger(Server.class);

        SeBootstrap.Configuration configuration =
                SeBootstrap
                        .Configuration
                        .builder()
                        .host("0.0.0.0")
                        .port(8080)
                        .build();

        SeBootstrap.Instance instance =
                SeBootstrap
                        .start(new RestApplication(), configuration)
                        .toCompletableFuture()
                        .get();

        logger.info("server startup.");
        System.console().readLine("> Enter stop.");

        instance
                .stop()
                .toCompletableFuture()
                .get();
    }
}

動作確認しましょう。パッケージングして起動。

$ mvn package
$ java -jar target/jdk-flight-recorder-example-0.0.1-SNAPSHOT.jar

アクセスして確認。

$ time curl localhost:8080/jfr-test/sleep
sleep[10] sec
real    0m10.141s
user    0m0.007s
sys     0m0.005s


$ time curl localhost:8080/jfr-test/heavy
fib[46]: 1836311903, done
real    0m9.746s
user    0m0.003s
sys     0m0.007s

準備ができました。

JDK Flight Recorderを使って記録を行う、JDK Mission Controlを使って結果を見る

ここから先は、JDK Flight Recorderを使って記録をしてみたり、JDK Mission Controlを使って結果を見ていきたいと思います。

JDK Mission Control(Eclipse Mission Control)をダウンロードする

今回はJDK Mission ControlとしてEclipse Mission Controlを使っていきます。

ダウンロード。

$ curl -LO https://github.com/adoptium/jmc-build/releases/download/9.0.0/org.openjdk.jmc-9.0.0-linux.gtk.x86_64.tar.gz
$ tar xf org.openjdk.jmc-9.0.0-linux.gtk.x86_64.tar.gz

今回使うバージョンは9.0.0です。

Eclipse Mission Control | Adoptium

起動。

$ JDK\ Mission\ Control/jmc &

スプラッシュが表示されて

ようこそ画面へ。こちらを閉じるとJDK Mission Controlを使い始められます。

ここからいくつかの方法でJDK Flight Recorderで記録を取得し、JDK Mission Controlで確認していきたいと思います。

javaコマンド実行時に記録する

まずはjavaコマンド実行時に記録します。

dumponexit=trueをつけて、終了時にダンプするようにしてみましょう。ファイル名は自動にします。

$ java -XX:StartFlightRecording=dumponexit=true -jar target/jdk-flight-recorder-example-0.0.1-SNAPSHOT.jar

アプリケーションを起動すると、こんな表示が出ます。どうも今回の環境ではデフォルトの最大サイズは250MBになっているようですね。

[0.540s][info][jfr,startup] Started recording 1. No limit specified, using maxsize=250MB as default.
[0.540s][info][jfr,startup]
[0.540s][info][jfr,startup] Use jcmd 23504 JFR.dump name=1 filename=FILEPATH to copy recording data to file.

アプリケーションにアクセスします。

$ curl localhost:8080/jfr-test/sleep
sleep[10] sec

$ curl localhost:8080/jfr-test/heavy
fib[46]: 1836311903 , done

アクセスが完了したら、アプリケーションを終了させます。

すると、アプリケーションの実行ディレクトリにこんなファイルが記録されていました。

$ ll -h hotspot-pid-23504-id-1-2024_12_15_16_00_34.jfr
-rw-rw-r-- 1 xxxxx xxxxx 799K 12月 15 16:00 hotspot-pid-23504-id-1-2024_12_15_16_00_34.jfr

こちらをJDK Mission Controlで開きます。

「メソッド・プロファイリング」を開くと、すでにフィボナッチ数の計算でCPUを使っていることが指摘されています。

「Javaアプリケーション」の表示。CPU使用率の欄で、青い部分が特徴的なことがわかります。

またメソッド・プロファイリング・サンプルの数が上位のスレッドを見てみると、よりわかりやすく結果が出ています。

この部分を選択すると、スリープしていることがわかります。

またこの部分を選択すると、フィボナッチ数の計算が時間を使っていることがわかります。

スレッドで見てもイベントが見つけやすい感じがしますね。

よさそうです。

javaコマンドでオプションを指定する、他の例も載せておきましょう。

filename=start-recording.jfrでファイル名を「start-recording.jfr」に、duration=3mで記録時間を3分間にする例。

$ java -XX:StartFlightRecording=filename=start-recording.jfr,duration=3m,dumponexit=true -jar target/jdk-flight-recorder-example-0.0.1-SNAPSHOT.jar

ファイルは起動時に作成されますが、0バイトです。

今回の設定では、3分間経過するかJavaアプリケーションが終了すると記録がダンプされます。

確認結果は省略します。

jcmdでJDK Flight Recorderの操作をする

続いては、jcmdでJDK Flight Recorderの操作をしましょう。

アプリケーションは-XX:StartFlightRecordingをつけずに起動しておきます。

$ java -jar target/jdk-flight-recorder-example-0.0.1-SNAPSHOT.jar

このJavaプロセスのPIDが必要になるので、jcmd自体で確認しましょう。

$ jcmd

記録を開始します。オプションはデフォルトです。

$ jcmd [PID] JFR.start

実行すると、こんな表示が出ます。

[PID]:
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 24986 JFR.dump name=1 filename=FILEPATH to copy recording data to file.

アプリケーションにアクセスします。

$ curl localhost:8080/jfr-test/sleep
sleep[10] sec

$ curl localhost:8080/jfr-test/heavy
fib[46]: 1836311903 , done

記録をダンプします。

$ jcmd [PID] JFR.dump
[PID]:
Dumped recording, 602.2 kB written to:

/path/to/hotspot-pid-24986-2024_12_15_16_23_19.jfr

ダンプすると、記録が出力されたファイルパスが表示されるようです。
※今回のPIDは24986です。

記録を停止します。

$ jcmd [PID] JFR.stop
[PID]:
Command executed successfully

JDK Mission Controlでの結果の確認は省略します。

なお、jcmdでJDK Flight Recorderの操作を行う場合、オプションはスペース区切りで指定するようです。

$ jcmd [PID] JFR.start filename=jmc-recording.jfr duration=1m dumponexit=true

指定可能なオプションについてはドキュメントを確認しましょう。

jcmdコマンド

JDK Mission ControlからJDK Flight Recorderを操作する

最後はJDK Mission ControlからJDK Flight Recorderの操作を行ってみます。

アプリケーションは-XX:StartFlightRecordingをつけずに起動しておきます。

$ java -jar target/jdk-flight-recorder-example-0.0.1-SNAPSHOT.jar

JDK Mission ControlのJVMブラウザを見ると、ローカルで実行しているJava VMプロセスの一覧を見ることができます。
※リモートもできそうです

展開すると、「フライト・レコーダ」が現れます。もちろん記録はありません。

ここで「フライト・レコーダ」を右クリックして「フライト記録の開始」を選ぶと、記録を開始できるようになります。

ファイル名はデフォルトでは自動で決まりますが、設定することもできます。

「終了」を押すと記録が開始され、JVMブラウザでも記録が行われていることがわかります。

今回は記録時間を指定したので、終了すると自動で分析結果に移ります。

ちなみにJVMブラウザの方は「記録がありません」に戻るようです。ここに表示されるのは、記録中のものみたいですね。

今度は連続記録にしてみましょう。下に書かれていますが、連続記録の場合は明示的なダンプ操作が必要になります。

「終了」を押して記録を開始すると、記録が現れますが残り時間が無限大になっています。

この記録を右クリックしてダンプ操作を行います。記録全体をダンプしたり、範囲を絞ってダンプしたりできるようです。

記録全体をダンプすると、すぐに記録の分析結果が表示されます。

また、右クリックで「ダンプ」操作を選ぶとこんな感じで細かく聞かれますが、「記録全体をダンプします」を選ぶとそのまま分析結果を
表示してくれます。

記録を取得し終わったら、「記録」を右クリックして停止しておきましょう。

これでJDK Flight Recorderによる記録が停止します。

おわりに

JDK Flight RecorderとJDK Mission Controlを試してみました。

実はちゃんと使ってきてなかったので…これを機に使っていくようにしたいですね。