JEP509 CPU時間プロファイリング
以上、JFRの基本を理解できたところで、ここからはJava 25による変更点について説明していきます。まずは、JEP509での「CPU時間プロファイリング」からです。
従来のCPU時間の計測では、短時間で終了するメソッドなどが十分に捉えられず、純粋なCPU消費量の特定精度が低いという課題がありました。そこで、さらに精度を高め、かつオーバーヘッドを抑えたプロファイリングを可能にしたのが、今回の改善です。
なお、この機能は現時点ではLinux環境限定の実験的機能ですが、--enable-previewなどの実験的ステータスの有効化オプションは不要で、Linux環境であればそのまま利用可能です。
プロファイリングの設定例
CPU時間プロファイリングを利用するには、以下のように設定ファイルを変更します。
<event name="jdk.CPUTimeSample">
<setting name="enabled" control="method-sampling-enabled">true</setting>
<setting name="throttle">20ms</setting>
<setting name="stackTrace">true</setting>
</event>
それぞれの設定の意味は、以下のとおりです。
- enabled：trueでメソッドごとのサンプリング計測の有効化します。controlはデフォルト値のままにしています
- throttle：サンプリング間隔を指定します（この例では20ミリ秒）
- stackTrace：サンプリング時のスタックトレースを記録。ただし、スタックトレース記録はオーバーヘッドを増やすため注意してください
結果を確認する
取得したデータは、以下のコマンドで確認できます。
$jfr view cpu-time-hot-methods jfr_report_jep509.jfr
// ----- 以下、実行結果 -----
Java Methods that Execute the Most from CPU Time Sampler (Experimental)
Method Samples Percent
---------------------------------------------------------------------------------- ------- -------
sun.nio.ch.Util$BufferCache.get(int) 1 25.00%
jdk.jfr.internal.JVM.emitEvent(long, long, long) 1 25.00%
jp.enbind.jfr.controller.JEP509Controller.burnCpu(int) 1 25.00%
java.util.zip.Inflater.inflateBytesBytes(long, byte[], int, int, byte[], int, int) 1 25.00%
また、同様の情報は、図2のようにJMCを使っても確認できます。
JEP520 メソッドの実行時間計測及びトレース機能の改善
特定のJavaメソッドの実行に対して、より詳細なプロファイリング情報が取得できるようになりました。
特に、これまではサンプリングに基づく大まかな統計が中心でしたが、今回の強化によって、例えばほとんど実行されないメソッドや、起動直後に一度だけ呼び出されるメソッドについても、計測／トレースしやすくなっています。
設定の基本
本機能を使うためには、以下のように設定ファイルを変更します。
<event name="jdk.MethodTiming">
<setting name="enabled">true</setting>
<setting name="filter" control="method-timing">
jp.enbind.jfr.controller.JEP520Controller
</setting>
<setting name="period">endChunk</setting>
</event>
それぞれの設定の意味は、以下のとおりです。
- enabled：trueでメソッドごとのサンプリングを有効化します
- filter：サンプリングするメソッド、またはクラスやパッケージ名・アノテーション(@から記述する)を指定します。複数指定する場合には「;」で区切って指定してください。また、controlもデフォルトのままにしてあります
- period：集計／イベントの出力タイミングを指定します。値はデフォルトとして記載されていたものをそのまま使用しています
結果を確認する
取得したデータは、以下のコマンドで確認できます。
$jfr view method-timing jfr_report_jep520_method_timing.jfr
// ----- 以下、実行結果 -----
Method Timing
Timed Method Invocations Minimum Time Average Time Maximum Time
-------------------------------------------------- ----------- ------------- ------------- -------------
jp.enbind.jfr.controller.JEP520Controller.trace() 6 168.000000 ms 175.000000 ms 183.000000 ms
jp.enbind.jfr.controller.JEP520Controller.trace1() 6 168.000000 ms 175.000000 ms 183.000000 ms
jp.enbind.jfr.controller.JEP520Controller.trace2() 60 16.100000 ms 17.500000 ms 24.500000 ms
jp.enbind.jfr.controller.JEP520Controller.trace3() 1,200 0.794000 ms 0.874000 ms 3.510000 ms
jp.enbind.jfr.controller.JEP520Controller.trace4() 24,000 0.039600 ms 0.043600 ms 0.570000 ms
jp.enbind.jfr.controller.JEP520Controller.trace5() 720,000 0.001290 ms 0.001430 ms 0.145000 ms
jp.enbind.jfr.controller.JEP520Controller.trace6() 28,800,000 0.000009 ms 0.000012 ms 0.056900 ms
jp.enbind.jfr.controller.JEP520Controller.<init>() 0 N/A N/A N/A
メソッドのトレース情報を取得する
続いて、メソッドのトレース情報を取得するには、以下のように設定ファイルを修正します。
<event name="jdk.MethodTrace">
<setting name="enabled">true</setting>
<setting name="filter" control="method-trace">
jp.enbind.jfr.controller.JEP520Controller::trace;
@org.springframework.web.bind.annotation.GetMapping
</setting>
<setting name="threshold">0 ms</setting>
<setting name="stackTrace">true</setting>
</event>
それぞれの設定の意味は、以下のとおりです。
- enabled：メソッドごとトレースサンプリングを有効化（true）に設定します
- filter：サンプリングするメソッド、またはクラスやパッケージ名・アノテーション（@から記述する）を指定します。複数指定する場合には「;」で区切って指定してください。また、controlもデフォルトのままにしてあります
- threshold：トレース処理をする場合の閾値の時間設定です。ここでは0としてあるので必ず対象になります
- stackTrace：スタックトレース情報を取得します。falseの場合には、時間情報だけが記録対象となります
トレース情報はパフォーマンスに非常に大きな影響を与えるため、調査したい箇所のみを記述するようにしてください。以上の設定で取得したデータは、以下のコマンドで確認できます。
$jfr view --cell-height 5 MethodTrace jfr_report_method_trace.jfr
// ----- 以下、実行結果 -----
Method Trace
Start Time Duration Event Thread Stack Trace Method
---------- -------- -------------------- --------------------------------------- ---------------------------------------
22:30:03 102 ms http-nio-8080-exec-7 java.lang.invoke.LambdaForm$DMH.0x00... jp.enbind.jfr.controller.JEP509Controll
java.lang.invoke.LambdaForm$MH.0x000... er.low(int)
java.lang.invoke.Invokers$Holder.inv...
jdk.internal.reflect.DirectMethodHan...
jdk.internal.reflect.DirectMethodHan...
22:30:11 170 ms http-nio-8080-exec-1 java.lang.invoke.DirectMethodHandle$... jp.enbind.jfr.controller.JEP520Controll
java.lang.invoke.LambdaForm$MH.0x000... er.trace()
java.lang.invoke.Invokers$Holder.inv...
jdk.internal.reflect.DirectMethodHan...
jdk.internal.reflect.DirectMethodHan...
最後に
Java 25では、JFRが大幅に強化され、低オーバーヘッドでの継続的な監視が可能となりました。これにより、本番環境でも高精度なパフォーマンス分析が実現し、問題発生時の迅速な対応が可能となります。
近年、多様な言語が台頭する中、このような堅牢な「運用・保守性」を強力に支援する環境がJDKに統合されている点は、長年の運用実績を持つJavaの大きなアドバンテージです。この進化により、性能ボトルネックの特定や運用フェーズでのトラブルシューティングが容易になり、Javaはクラウドネイティブ時代においても信頼性の高いプラットフォームとして進化を続けていくことが期待できます。
