この記事は、Jakarta EE / Java EE Advent Calendar 2025 の 18 日目の記事です。

「Javaアプリのトラブル調査で、より詳細な情報を採取したい。」
「そんなとき、JDK Flight Recorder (JFR) はお手軽に試せる方法だ。」

（前回の記事）

「でも、もっとアプリ実装に沿った具体的な情報を集めたい。」
「例えば、アプリのどの処理区間が問題なのか分析できる情報を記録できないだろうか。」

そんなときは、自分でカスタマイズした情報（イベント）を、JFRで出力してみるとよいかもしれません。

JFRイベントとは

JFRイベントとは、JFRで記録されるJava VM プロセス上の事象や情報のことです。
JDKではCPU負荷情報などを示す様々なイベントが既に規定されており、JFRを有効にすれば記録されるようになっています。

加えて、自分で定義したJFRイベントも記録できます。
JFRイベントの定義は簡単で、jdk.jfr.Event を継承したクラスを用意するだけで実現できます。

Java SE アプリでJFRイベントを発行してみる

前回の記事で利用した、処理に1 - 1000 ms程度かかるJavaプログラムを少し改造します。
処理区間を示すJFRイベントとして RandomSleep Event を記録するようにしてみます。

イベントを実装するクラスは、自由に記録データをカスタマイズできますが、今回は jdk.jfr.Event を継承するだけの空実装（デフォルト設定）を利用します。

import java.util.Random;

import jdk.jfr.Category;
import jdk.jfr.Event;
import jdk.jfr.Label;
import jdk.jfr.Name;

public class Main {

    public static void main(String... args) {
        RandomSleep proc = new RandomSleepProxy(); // Changed
        for (int i = 0; i < 10; i++) { // 10 times
            proc.execute();
        }
    }

    interface RandomSleep {
        void execute();
    }

    public static class RandomSleepImpl implements RandomSleep {
        public void execute() {
            // Random number between 1 and 1000
            Random random = new Random();
            int randomNumber = random.nextInt(1000) + 1;
            try {
                System.out.println("Sleep for " + randomNumber + " ms.");
                Thread.sleep(randomNumber);
            } catch (InterruptedException e) {
            }
        }
    }

    public static class RandomSleepProxy implements RandomSleep {
        RandomSleep impl = new RandomSleepImpl();
        public void execute() {
            RandomSleepEvent event = new RandomSleepEvent();
            event.begin();
            impl.execute();
            event.commit();
        }

        @Name("com.example.event.RandomSleepEvent")
        @Label("RandomSleep Event")
        @Category({"RandomSleepApp", "Main"})
        public static class RandomSleepEvent extends Event {
        }
    }

}

JFRを有効にするために、-XX:StartFlightRecording:filename=<filepath> オプションを追加して実行します。
Java VM プロセスが終了すると、JFRログファイル（.jfr）が出力されます。

# java -XX:StartFlightRecording:filename=/work/act-oss/demo-jfr-se/ RandomSleepProxy.java
[0.373s][info][jfr,startup] Started recording 1. No limit specified, using maxsize=250MB as default.
[0.373s][info][jfr,startup] 
[0.373s][info][jfr,startup] Use jcmd 3425974 JFR.dump name=1 to copy recording data to file.
Sleep for 889 ms.
Sleep for 959 ms.
Sleep for 12 ms.
Sleep for 426 ms.
Sleep for 452 ms.
Sleep for 159 ms.
Sleep for 569 ms.
Sleep for 295 ms.
Sleep for 854 ms.
Sleep for 719 ms.

# find /work/act-oss/demo-jfr-se/ -name "*.jfr"
/work/act-oss/demo-jfr-se/hotspot-pid-3425974-id-1-2025_12_11_18_33_47.jfr

JFRログファイルの中には、以下のように今回記録した RandomSleep Event が記録されています。

デフォルトで記録される情報として、イベントの「開始/終了時間」や「処理スレッド」に加え、「スタックトレース」も参照できます。
勿論、イベントクラスの実装次第で、更に詳細な情報を記録できるようになります。

Jakarta EE アプリでJFRイベントを発行してみる

前回の記事で利用した、Jakarta Servlet のアプリを少し改造します。
こちらも、処理区間を示すJFRイベントとして RandomSleep Event を記録するようにしてみます。

package com.example.servlet;

import java.io.IOException;
import java.io.PrintWriter;
import java.util.Random;

import jakarta.servlet.ServletException;
import jakarta.servlet.annotation.WebServlet;
import jakarta.servlet.http.HttpServlet;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;

import jdk.jfr.Category;
import jdk.jfr.Event;
import jdk.jfr.Label;
import jdk.jfr.Name;

@WebServlet("/RandomSleepProxyServlet")
public class RandomSleepProxyServlet extends HttpServlet {

    @Override
    protected void doGet(HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException {
        response.setContentType("text/plain; charset=UTF-8");
        PrintWriter responseWriter = response.getWriter();

        RandomSleep proc = new RandomSleepProxy(); // Changed
        proc.execute();
    }

    @Override
    protected void doPost(HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException {
        doGet(request, response);
    }

    interface RandomSleep {
        void execute();
    }

    public static class RandomSleepImpl implements RandomSleep {
        public void execute() {
            // Random number between 1 and 1000
            Random random = new Random();
            int randomNumber = random.nextInt(1000) + 1;
            try {
                System.out.println("Sleep for " + randomNumber + " ms.");
                Thread.sleep(randomNumber);
            } catch (InterruptedException e) {
            }
        }
    }

    // Records customized JFR events (RandomSleepEvent).
    public static class RandomSleepProxy implements RandomSleep {
        RandomSleep impl = new RandomSleepImpl();
        public void execute() {
            RandomSleepEvent event = new RandomSleepEvent();
            event.begin();
            impl.execute();
            event.commit();
        }

        @Name("com.example.event.RandomSleepEvent")
        @Label("RandomSleep Event")
        @Category({"RandomSleepWebApp", "RandomSleepProxyServlet"})
        public static class RandomSleepEvent extends Event {
        }
    }

}

このServletを含むWebアプリ（.war）を、Jakarta EEに準拠したランタイムOSSであるGlassFishで動かします。

前回の記事と同じ手順に沿って、2つのJava VM プロセス（GlassFish Server クラスター配下のインスタンス）でアプリを動かします。
各インスタンスでは、HTTPリクエストをポート28080/28081で受け付ける設定となっています。

# asadmin start-domain
...
Successfully started the domain : domain1
domain  Location: /opt/glassfish8/glassfish/domains/domain1
Log File: /opt/glassfish8/glassfish/domains/domain1/logs/server.log
Admin Port: 4,848
Command start-domain executed successfully.

# asadmin create-cluster cluster-1
Command create-cluster executed successfully.

# asadmin create-local-instance --cluster cluster-1 cluster-1-1
...
HTTP_LISTENER_PORT=28080
...
Command create-local-instance executed successfully.

# asadmin create-local-instance --cluster cluster-1 cluster-1-2
...
HTTP_LISTENER_PORT=28081
...
Command create-local-instance executed successfully.

# asadmin deploy --target cluster-1 RandomSleepWebApp.war 
Application deployed with name RandomSleepWebApp.
Command deploy executed successfully.

このとき、JFRを有効にするオプションを設定した上で起動するようにします。

# asadmin create-jvm-options --target cluster-1 -XX\\\:StartFlightRecording=filename\\\=\\\$\\\{com.sun.aas.instanceRoot\\\}/logs
Created 1 option(s)
Command create-jvm-options executed successfully.

# asadmin start-cluster cluster-1
Command start-cluster executed successfully.              

# for i in {1..10}; do for port in 28080 28081; do \
    curl http://localhost:${port}/RandomSleepWebApp/RandomSleepProxyServlet; \
  done; done

Java VM プロセスが終了すると、指定のパスにJFRログファイル（.jfr）が出力されます。

# /opt/glassfish8/glassfish/bin/asadmin stop-cluster cluster-1
Command stop-cluster executed successfully.                 

# find /opt/glassfish8/glassfish/nodes/localhost-domain1/ -name "*.jfr"
/opt/glassfish8/glassfish/nodes/localhost-domain1/cluster-1-1/logs/hotspot-pid-3440557-id-1-2025_12_11_19_06_32.jfr
/opt/glassfish8/glassfish/nodes/localhost-domain1/cluster-1-2/logs/hotspot-pid-3440530-id-1-2025_12_11_19_06_32.jfr

記録内容からもわかるように、GlassFishにデプロイしたアプリの処理は、mainスレッド1つで動くような単純なものではありません。
このため、各処理区間について、デフォルトで「処理スレッド」や「スタックトレース」が記録されているのは、非常に助かります。

また、調査のために何でもかんでもサーバーログ（server.log）に情報を出力させると、情報量の多さに戸惑ってしまいがちです。
一方で、JFRログファイルは、様々な詳細情報を収集していながらも、欲しい情報にアクセスしやすい気がします。

JFRイベントのカスタマイズ

JFRイベントでは、他にも様々な情報を付与したり、チューニングしたりすることができます。
実行環境やアプリに合わせて、よりよいイベント設定を模索するとよいかもしれません。

参考: Flight Recorder API Programmer’s Guide
- https://docs.oracle.com/en/java/javase/21/jfapi/creating-and-recording-your-first-event.html
参考: 富士通製品で提供しているJDK 8のドキュメント
- https://software.fujitsu.com/jp/manual/manualfiles/m230004/b1ws1414/03z200/b1414-00-08-03-01.html
- JDKのバージョンやベンダーによってデフォルト設定などが異なる可能性あり

おまけ: JFRイベントの解析をPythonで

これまで紹介したように、JFRの記録内容は、JDK Mission Control (JMC) を用いることでわかりやすく可視化することができます。

ただし、以下のような大量のデータを分析するケースなどにおいて、既定のGUIでは限界を感じることがあります。

長時間実行した場合の処理時間の分布を確認してみたいとき
稀に生じる問題について調査するために10000回実行した結果を参照したいとき

そんなときは、JFRログファイルの記録内容をPythonで分析することで、欲しい情報に辿り着けるかもしれません。

以下、手順の一例を書いてみます。

1. `jfr print` コマンドによりJFRログファイルの内容をjson形式で出力

まずは、JFRログファイルの記録内容について、Pythonの扱えるデータ形式で出力します。

このとき、分析対象となるデータサイズを抑える工夫をすると良いと思います。
例えば、出力対象のイベントの種類を絞ったり、スタックトレースの出力を抑えたりするとよいかもしれません。

# jfr print --json --stack-depth 0 --events "com.example.event.*" hotspot-pid-3440557-id-1-2025_12_11_19_06_32.jfr > hotspot-pid-3440557-id-1-2025_12_11_19_06_32.json

jsonデータの内容は以下の通り。

{
  "recording": {
    "events": [{
      "type": "com.example.event.RandomSleepEvent", 
      "values": {
        "startTime": "2025-12-11T19:06:01.071798033+09:00", 
        "duration": "PT0.452853212S", 
        "eventThread": {
          "osName": "http-listener-1(2)", 
          "osThreadId": 3440800, 
          "javaName": "http-listener-1(2)", 
          "javaThreadId": 56, 
          "group": {
            "parent": {
              "parent": null, 
              "name": "system"
            }, 
            "name": "main"
          }, 
          "virtual": false
        }, 
        "stackTrace": {
          "truncated": false, 
          "frames": []
        }
      }
    }, ...

2. Pythonスクリプトでjson形式のデータをDataFrameに変換して分析

以下のようなPythonスクリプトを実行することで、jsonデータから pandas.DataFrame に変換します。

import json
import re

import numpy as np
import pandas as pd

import matplotlib.pylab as plt
import japanize_matplotlib

json_path = "hotspot-pid-3440557-id-1-2025_12_11_19_06_32.json"

with open(json_path, "r") as f:
    data = json.load(fp=f)

events = data["recording"]["events"]
rows = []

for event in events:
    rows.append({
        "startTime": event["values"]["startTime"],
        "duration": float(re.search(r"PT(\d+\.?\d*)S", event["values"]["duration"]).group(1)),
        "eventName": event["type"],
        "eventThread": event["values"]["eventThread"]["osName"]
    })

df = pd.DataFrame(rows)

DataFrameの内容は以下の通り。

startTime	duration	eventName	eventThread
2025-12-11T19:06:01.071798033+09:00	0.452853	com.example.event.RandomSleepEvent	http-listener-1(2)
2025-12-11T19:06:02.599324286+09:00	0.128321	com.example.event.RandomSleepEvent	http-listener-1(3)
2025-12-11T19:06:03.355626919+09:00	0.178257	com.example.event.RandomSleepEvent	http-listener-1(5)
2025-12-11T19:06:04.481642554+09:00	0.205251	com.example.event.RandomSleepEvent	http-listener-1(1)
2025-12-11T19:06:05.143724059+09:00	0.52132	com.example.event.RandomSleepEvent	http-listener-1(4)
2025-12-11T19:06:06.535819885+09:00	0.021278	com.example.event.RandomSleepEvent	http-listener-1(2)
2025-12-11T19:06:06.905503174+09:00	0.971279	com.example.event.RandomSleepEvent	http-listener-1(3)
2025-12-11T19:06:07.908614168+09:00	0.053205	com.example.event.RandomSleepEvent	http-listener-1(5)
2025-12-11T19:06:08.958756045+09:00	0.18623	com.example.event.RandomSleepEvent	http-listener-1(1)
2025-12-11T19:06:10.026610316+09:00	0.911234	com.example.event.RandomSleepEvent	http-listener-1(4)

あとは、分析方法に応じて、csvファイルに書き出したり、グラフにプロットしたり、統計値を出したりするとよいかもしれません。

おわりに

JFRイベントは、デフォルトの設定で重要な情報を記録してくれるため、非常にお手軽です。
Jakarta EE 実行環境に合わせてカスタマイズした、詳細な情報を採取できます。

是非、活用を検討してみてください。

付録

Jakarta EE 実行環境

# cat /etc/redhat-release 
Red Hat Enterprise Linux release 8.10 (Ootpa)

# java --version
openjdk 21.0.9 2025-10-21 LTS
OpenJDK Runtime Environment Temurin-21.0.9+10 (build 21.0.9+10-LTS)
OpenJDK 64-Bit Server VM Temurin-21.0.9+10 (build 21.0.9+10-LTS, mixed mode, sharing)

# asadmin version
Version = Eclipse GlassFish 8.0.0-M14 (commit: 66cb8e8b4c6ead7ac3e7705e330613b36818f161)
Command version executed successfully.

インストール物

参考情報

Eclipse GlassFish Reference Manual
- https://glassfish.org/docs/latest/reference-manual.html
Flight Recorder API Programmer’s Guide
- https://docs.oracle.com/en/java/javase/21/jfapi/index.html
Package jdk.jfr
- https://docs.oracle.com/javase/jp/21/docs/api/jdk.jfr/jdk/jfr/package-summary.html
Interstage Application Server V13.1.0 チューニングガイド
- https://software.fujitsu.com/jp/manual/manualfiles/m230004/b1ws1414/03z200/b1414-00-08-03-00.html