原文はこちら。
The original article was written by Erik Gahlin (Consulting Member of Technical Staff, Java Platform Group, Oracle).
https://egahlin.github.io/2022/05/31/improved-ergonomics.html
JDK 17がリリースされましたが、JFRにもいくつかの改善が入っています。
Configuration wizard
イベントの構成を簡単にするための新たなconfigureコマンドがjfrツールに追加されました。
$ jfr configure
このコマンドでは、以前はJMC Recording Wizardでのみ利用可能だったオプションを使い、イベントの構成が対話モードで可能になっています。
JDK Mission Control (JMC) 8 Downloads
https://www.oracle.com/java/technologies/javase/products-jmc8-downloads.html
対話モードを開始するには、--interactive フラグを使います。
$ jfr configure --interactive
============== .jfc Configuration Wizard ============
This wizard will generate a JFR configuration file by
asking 12 questions. Press ENTER to use the default
value, or type Q to abort the wizard.
Garbage Collector: Normal (default)
1. Off
2. Normal
3. Detailed
4. High, incl. TLABs/PLABs (may cause many events)
5. All, incl. Heap Statistics (may cause long GCs)
Using default: Normal
Allocation Profiling: Low (default)
1. Off
2. Low
3. Medium
4. High
5. Maximum
Using default: Low
Compiler: Normal (default)
1. Off
2. Normal
3. Detailed
4. All
...
Socket I/O Threshold: 20 ms (default)
Using default: 20 ms
Class Loading [Y/N]: No (default)
Using default: No
Filename: custom.jfc (default)
Configuration written successfully to:
/Users/jfr/custom.jfc
デフォルトでは、構成をcustom.jfcというファイルに書き込みます。記録を開始する際にこのファイルを -XX:StartFlightRecording もしくは jcmd に渡すことができます。
Java Command
https://docs.oracle.com/en/java/javase/17/docs/specs/man/java.html
https://docs.oracle.com/javase/jp/17/docs/specs/man/java.html
Jcmd Command
https://docs.oracle.com/en/java/javase/17/docs/specs/man/jcmd.html
https://docs.oracle.com/javase/jp/17/docs/specs/man/jcmd.html
$ java -XX:StartFlightRecording:settings=custom.jfc -jar app.jar
$ jcmd <pid> JFR.start settings=custom.jfc
対話ウィザードを使わずにオプションを構成することも可能です。以下はその例です。
$ jfr configure method-profiling=high gc=high class-loading=true
利用可能なオプションはJDKバージョン次第です。help configureを使ってリストを確認してください。
$ jfr help configure
以下はJDK 17/18のデフォルト構成 (default.jfc) で利用可能なオプションです。
gc=<off|normal|detailed|high|all>
allocation-profiling=<off|low|medium|high|maximum>
compiler=<off|normal|detailed|all>
method-profiling=<off|normal|high|max>
thread-dump=<off|once|60s|10s|1s>
exceptions=<off|errors|all>
memory-leaks=<off|types|stack-traces|gc-roots>
locking-threshold=<timespan>
file-threshold=<timespan>
socket-threshold=<timespan>
class-loading=<true|false>
明示的に出力ファイルを制御したい、つまりcustom.jfcという名前以外のものを使いたいのであれば、--output オプションを使ってファイル名を指定します。
$ jfr configure exceptions=all --output exceptions.jfc
$ java -XX:StartFlightRecording:settings=exceptions.jfc
JDKのイベント設定をデフォルトから変更した場合、オーバーヘッドが1％を超え、結果としてアプリケーションのレスポンスに影響する場合があることを覚えておいてください。例えば、memory-leaks=gc-roots オプションを使うと、記録終了時にすべてのJavaスレッドを停止し、ヒープを一掃します。これにより、アプリケーションが数秒間停止する可能性があります。カスタム設定を実運用で使用する前に、必ず試用して、オーバーヘッドが許容範囲であることを確認してください。
configureコマンドでは、個々のイベント設定を変更することもできます。これはアプリケーション固有の問題をトラブルシュートするためのユーザー定義イベント作成時に有用です。アプリケーションにイベントを追加する際にはあまりオーバーヘッドを心配する必要はありません。イベントが無効化されていれば、実装は空です。
Event.java
https://github.com/openjdk/jdk/blob/master/src/jdk.jfr/share/classes/jdk/jfr/Event.java
HotSpot C2コンパイラは通常、オブジェクトがメソッドをエスケープしない場合、イベントを排除できます。
C2 Compiler
https://openjdk.java.net/groups/hotspot/docs/HotSpotGlossary.html#C2Compiler
Continuous Monitoring with JDK Flight Recorder (JFR)
https://www.youtube.com/watch?v=xrdLLx6YoDM&t=1456s
以下はユーザー定義イベントの例です。
@Name("com.company.HttpGetRequest")
@Label("HTTP GET Request")
@Category("HTTP")
@Enabled(false)
@StackTrace(false)
@Threshold("0 ms")
public class HttpGetRequest extends jdk.jfr.Event {
@Label("Request URI")
String uri;
}
protected void doGet(HttpServletRequest req, HttpServletResponse resp) {
HttpGetRequest request = new HttpGetRequest();
request.begin();
request.uri = req.getRequestURI();
...
request.commit();
}
イベントを構成ファイルに追加するには、イベント名の後に#とKey-Valueペアを付けてください。
$ jfr configure +com.company.HttpGetRequest#enabled=true --output http.jfc
＋符号はここでは指定された設定がデフォルトの設定に追加されることを意味します。
＋符号を省略した場合、ツールは既存の設定を変更するものと見なします。com.company.HttpGetRequest はJDKイベントの一部ではないので、ツールはエラーメッセージを表示して失敗します。この動作により、スペルに間違いのあるJDKイベントを設定ファイルに入力するリスクが軽減されます。
あるJDKリリースで利用可能なすべてのイベントを一覧表示するには、metadataコマンドを使用します。
$ jfr metadata
以下のコマンドでは、ソケットとメソッドのサンプリングイベントを個別に設定する方法を示しています。
$ jfr configure jdk.SocketRead#enabled=true jdk.SocketRead#threshold=0ms jdk.SocketRead#stackTrace=true
$ jfr configure jdk.ExecutionSample#enabled=true jdk.ExecutionSample#period=10ms
とはいえ、大抵の場合はオプションを使ったほうが簡単です。
$ jfr configure socket-threshold=0ms method-profiling=high
configureコマンドで構成ファイルをマージすることもできます。
$ jfr configure --input my.jfc,default.jfc --output combined.jfc
イベント設定の構文に関する詳細は、APIドキュメントをご覧ください。
Package jdk.jfr
https://docs.oracle.com/en/java/javase/17/docs/api/jdk.jfr/jdk/jfr/package-summary.html
https://docs.oracle.com/javase/jp/17/docs/api/jdk.jfr/jdk/jfr/package-summary.html
Configure events on command line
ここまで読んで、なぜ -XX:StartFlightRecording を使い直接オプションや設定を指定できないのか不思議に思われたかもしれませんが、もちろん可能です。
$ java -XX:StartFlightRecording:allocation-profiling=high
$ java -XX:StartFlightRecording:+com.company.HttpGetRequest#enabled=true
ユーザー定義.jfcファイルをオーバーライドすることもできます。
$ java -XX:StartFlightRecording:settings=http.jfc,com.company.HttpGetRequest#enabled=false
すでにhttp.jfcにある設定を変更するため、ここでは＋符号は必要ありません。単一のイベントを有効化するには、settings=noneというオプションを使います。これはJFRをデフォルト構成（default.jfc）を使わずにスタートするためのオプションです。
$ java -XX:StartFlightRecording:settings=none,+com.company.HttpGetRequest#enabled=true
$ java -XX:StartFlightRecording:settings=none,+jdk.SocketRead#enabled=true,+jdk.SocketRead#threshold=1ms
イベントは、@Enabledアノテーションによってデフォルトで有効または無効になります。すべてのJDKイベントはデフォルトで無効ですが、-XX:StartFlightRecording:settingsオプションが指定されていない場合、デフォルト設定（default.jfc）が使用され、運用時に安全に使用できるイベント（オーバーヘッド1%未満）が有効になります。
上記のHttpGetRequestイベントはカスタムイベント設定で拡張でき、特定のURIに対してのみイベントが発行されるようになります。SettingControlのAPIドキュメントと、Gunnar Morlingのエントリをご覧ください。
Class SettingControl
https://docs.oracle.com/en/java/javase/17/docs/api/jdk.jfr/jdk/jfr/SettingControl.html
https://docs.oracle.com/javase/jp/17/docs/api/jdk.jfr/jdk/jfr/SettingControl.html
Monitoring REST APIs with Custom JDK Flight Recorder Events
https://www.morling.dev/blog/rest-api-monitoring-with-custom-jdk-flight-recorder-events/
URIフィルタはコマンドラインで指定できます。
$ java '-XX:StartFlightRecording:+com.company.HttpGetRequest#uriFilter=https://www.example.com/list/.*'
Log events for debugging
JDK 17では、イベントをJVMログに書き出す機能も追加されています。ロックしつつ出力整形したり、イベント出力したりすることからオーバーヘッドが大きいため、これは開発時向け機能であり、本運用向け機能ではありません。
JEP 158: Unified JVM Logging
https://openjdk.java.net/jeps/158
以下は出力例です。
[6.227s][trace][jfr,system,event] jdk.ThreadCPULoad {
[6.227s][trace][jfr,system,event] startTime = 18:19:27.820 (2022-05-30)
[6.227s][trace][jfr,system,event] user = 0,08%
[6.227s][trace][jfr,system,event] system = 0,00%
[6.227s][trace][jfr,system,event] eventThread = "Image Fetcher 0" (javaThreadId = 37)
[6.227s][trace][jfr,system,event] }
[6.227s][trace][jfr,system,event] jdk.JavaMonitorWait {
[6.227s][trace][jfr,system,event] startTime = 18:19:22.816 (2022-05-30)
[6.227s][trace][jfr,system,event] duration = 5,01 s
[6.227s][trace][jfr,system,event] monitorClass = java.util.Vector (classLoader = bootstrap)
[6.227s][trace][jfr,system,event] notifier = N/A
[6.227s][trace][jfr,system,event] timeout = 5,00 s
[6.227s][trace][jfr,system,event] timedOut = true
[6.227s][trace][jfr,system,event] address = 0x600002146700
[6.227s][trace][jfr,system,event] eventThread = "Image Fetcher 1" (javaThreadId = 38)
[6.227s][trace][jfr,system,event] stackTrace = [
[6.227s][trace][jfr,system,event] java.lang.Object.wait0(long)
[6.227s][trace][jfr,system,event] java.lang.Object.wait(long) line: 366
[6.227s][trace][jfr,system,event] sun.awt.image.ImageFetcher.nextImage() line: 154
[6.227s][trace][jfr,system,event] sun.awt.image.ImageFetcher.fetchloop() line: 207
[6.227s][trace][jfr,system,event] sun.awt.image.ImageFetcher.run() line: 176
[6.227s][trace][jfr,system,event] ]
[6.227s][trace][jfr,system,event] }
ユーザー定義イベントを完全なスタックトレース付きでログ出力するには、-Xlog:jfr+event=traceオプションを付けてJVMを起動します。
$ java -Xlog:jfr+event=trace -XX:StartFlightRecording
スタックの深さを最大5フレームに制限するには、-Xlog:jfr+event=debugを使います。JDKイベントの場合は、-Xlog:jfr+system+eventを使用します。
ノイズを減らすために、この機能は-XX:StartFlightRecording:settings=noneおよびデバッグするイベントを指定して使用するとよいでしょう。
$ java -XX:StartFlightRecording:settings=none,+com.company.HttpGetRequest#enabled=true
イベントは1秒ごとにログに書き込まれます。
JVMがシャットダウンする際、終了前に書き込まれるイベントを待つことはありませんのでご注意ください。最後のイベントが見あたらない場合にも驚かないでください。
Resources
jfr command
https://docs.oracle.com/en/java/javase/17/docs/specs/man/jfr.html
https://docs.oracle.com/javase/jp/17/docs/specs/man/jfr.html
Logico Inside 