はじめに

私が所属しているチームでJavaアプリケーション(Spring Bootを利用したウェブアプリケーション)の性能改善のため、実行に時間の掛かっている処理(ボトルネック)を調査したいというニーズが生じました。ボトルネック調査を行うには、以下の例のようにいくつかのアプローチが考えられます。

• debugログ等に一連の処理時間を出力するようにコードを修正し、ログからボトルネックを特定する。
• 使っているライブラリやフレームワークのパフォーマンス測定機能を利用してボトルネックを特定する。
• プロファイラを利用してボトルネックを特定する。

私はJava環境でプロファイラを利用したことはないため勉強も兼ねて調査することにしました。また、一般的にプロファイラを用いると、アプリケーションのコード変更やフレームワークに依存することなくボトルネックの調査を行うことができることもJava環境のプロファイラについて調べようと考えた理由です。

この記事では、Java環境(Amazon Corretto 17)で利用できるプロファイラについて、実際に動かして調査した内容を紹介します。

用語

• プロファイリング
  • 関数の実行時間や実行回数、メモリ使用量といったプログラム実行時の情報を取得し解析する手法です。
  • 典型的なユースケースは性能改善や現状把握を目的としてプログラムの動作状況を解析するために実施することです。
• プロファイル
  • プロファイリングに用いる実行履歴等が記録されているデータです。
    • 例. プロファイラで取得したデータが記録されたファイル
• プロファイラ
  • プロファイリングのためにプロファイルの生成や分析を行うツールです。

Javaで利用可能なプロファイラについて

Javaのプロファイラについて調査したところ十分な機能を持ったプロファイラが無償で利用できる事が分かりました。無償利用可能な代表的なプロファイラは以下の2つです。

• JDK Flight Recorder(JFR)/JDK Mission Control(JMC)

  • 元々はOracle JDKの商用機能として提供されていましたが、OSSとして寄贈されOpenJDK 11から無償利用可能となっています。
  • JFRは実行時の動作状況(プロファイル)を記録する機能で、Java Vertual Machine(JVM)に組み込まれています。
    • JVMのレベルでデータを取得しているため非常に詳細なデータを取得可能なこと、オーバーヘッドが小さいこと(1%未満)、が特徴です。
    • オーバーヘッドが小さいことから本番環境でのデータ取得も比較的容易に行え、使い方を覚えれば運用時のトラブルシューティングにも対応可能になると考えられます。
  • JMCはJFRを利用したプロファイル取得を支援する機能と取得したプロファイルを解析する機能を持ったツールです。
  • ダウンロードサイト
    • JFRはJVMに統合されており一般的なjavaのランタイムに含まれています。JMCは独立したバイナリとなっておりオラクルやアマゾンなどJDKのバイナリ提供元がそれぞれリリースしています。
    • JMCのバイナリ取得先についてはOpenJDKのREADMEにて紹介されています。
      • https://github.com/openjdk/jmc ⧉
    • Amazon Correttoの開発チームがビルドしているJMCは以下から取得することができます。
      • https://github.com/corretto/corretto-jmc ⧉

• VisualVM

  • こちらも元々はOracle JDKに含まれていた機能でしたが、現在はJDKからは独立したソフトウェアとして公開されています。
  • アプリケーションレイヤでの情報取得、可視化を得意としており実際の動作(例えばJDBC経由で発行されているSQL等)をリアルタイムに確認する事ができます。
  • JFR/JMCに比べてリアルタイムに可視化できますが、オーバーヘッドは大きくなっています。(数%から10%程度)
  • ダウンロードサイト
    • OpenJDKとは独立して公式サイトで配布されています。
      • https://visualvm.github.io/index.html ⧉

各プロファイラでのデータ取得と解析

どちらのツールを使うか検討するため、以下の環境で実際にJFR/JMC、VisualVMを動かし使い勝手を確認しました。

環境

• OS: Windows 11 Pro
• JDK: Amazon Corretto 17
• コードエディタ: Visual Studio Code(VS code)
  • 拡張機能としてExtension Pack for Java, Spring Boot Extension Packをインストールしています。

JFR/JMC

JFR/JMCでのプロファイリングは、JFRを用いてアプリケーション実行時のプロファイルを取得し、その後JMCを用いて分析する順番で実施します。

プロファイルの取得

• アプリケーション実行時の引数にプロファイルの取得を指定する。
  • 例. -XX:StartFlightRecording:filename=recording.jfr,duration=60sを付与する。
    • このオプションを付与すると、recording.jfrに起動から60秒の間のデータが記録されます。
• jcmdコマンドを利用してプロファイルを取得する。
  • jcmdはJVMに診断コマンドを送るツールで、実行中のJVMに対してGCの情報取得やJFRのstart/stopなどのコマンドを実行できます。
  • 例.

    1
    c:\Users\alpha>jcmd -> 実行中のjavaプログラムがPIDと共にリストされます
    2
    12096 jdk.jcmd/sun.tools.jcmd.JCmd
    3
    18876 org.springframework.ide.vscode.boot.app.BootLanguageServerBootApp
    4
    以下省略
    5
    c:\Users\alpha>jcmd 18876 JFR.start duration=60s filename=recording.jfr

    • jcmdのコマンド実行から60秒間のデータがrecording.jfrに記録されます。
• JMCを利用してプロファイルを取得する。

  • 例.

    (1) JMCを起動し、対象のプロセスを右クリックしてフライトの記録開始を選択する。(証明書エラーが表示されますが今回はローカルでの作業のため無視します。) (2) 宛先ファイルを指定して終了を押す。(この設定では実行から60秒間のデータがrecording.jfrに記録されます。今回は他と揃えるために名前を変えましたが、ファイル名はデフォルトで問題はないでしょう。)

各コマンドやツールではより細かい指定が可能となっています。詳細はJVM/jcmdのオプション及びJMCのドキュメントを参照してください。

実行状態の解析

取得したデータの解析には、JMCを利用します。JMCを起動し先ほど取得したrecording.jfrを開きます。 今回サンプルで表示しているデータはVS code拡張のLanguage Support for Java(TM) by Red Hatに含まれているJavaアプリケーションです。バージョンやJMCのバイナリの取得先で多少違いがあるかもしれませんが、ファイルを開くと以下の画面が表示されるでしょう。 時間のかかっている処理を特定するために、まずメソッド・プロファイリングを利用します。メソッド・プロファイリングを選択すると以下の図のような画面が表示されます。 上部にサンプリングされた回数とメソッドが表示され、下部に各メソッド実行時のスタックの状態が表示されています。 下部のスタック・トレースの表示設定はツリー表示でスレッド・ルートからのグループ・トレースを選択しています。

サンプリング回数が多いメソッドは、1回あたりの実行時間が長かったり、実行回数が多いと見ることができます。 例えば、特定の通信メソッドで時間がかかっているようだと推測されたら、次はソケットI/Oをみて原因を推測していくといった順に進めます。 ここではすべてを紹介しきれませんが、メモリやGCの稼働状況など分析することができるので色々と試してみると面白いと思います。

VisualVM

VisualVMは単体でプロファイルの取得、解析が行え手軽に実行することが可能です。

プロファイルの取得と解析

VisualVMを起動してプロファイルを取得する対象を右クリックしOpenを選択します。 profilerタブを開いて、CPUを押すとプロファイルを取得し始めてからの実行状態をリアルタイムにモニタリングすることができます。

モニタリングしている状態でアプリケーション側の操作を行うと以下の図のように実行状態や実行にかかった時間が表示されます。実際に動作している最中に時間のかかる処理などをその場で確認することができます。 JDBCのようにJFR/JMCでは表示されないような情報もあり、開発時に特定の操作を実施した際の動作を解析する用途では非常に強力なツールと考えられます。

以下の図は弊社のとある製品のサーバにVisualVMを接続してJDBCの実行を見た例です。 特別な設定をしなくてもVS codeからSpring Bootのアプリケーションをデバッグモードで起動してVisualVMで接続することができています。 JFR/JMCよりもアプリケーションに特化した情報をリアルタイムに追えることは実装を行っている際には非常に便利であると感じました。その反面、VisualVMで接続した状態を維持しなければならないことから、長期間のプロファイル取得や本番環境での解析には向かないと考えられます。

VisualVMのJFR対応について

VisualVMもJFRに対応していますが、現状ではJMCを利用したほうがよいと考えられます。例えば、先ほどJMCで開いたrecording.jfrをVisualVMで開いてネットワーク情報を見ると以下の図のような画面が表示されます。JMCの方がより詳しく表示されています。

ツールの使い分けについて

これまで見てきたツールの特徴から使い分けについては次のことが言えると考えられます。

VisualVMはリアルタイムにアプリケーションの実行状態を可視化する機能に優れているので、以下のようなケースに適していると考えられます。

• 1つのAPI呼び出しの実行を調査するケース
• あるメソッドのコードを変えてbefore/afterの違いをみるというようなケース

JFR/JMCはオーバーヘッドが小さいこと、プロファイル取得時にJMCによる接続を維持する必要がないことなどプロファイルの取得しやすさに優れているので、以下のようなケースに適していると考えられます。

• 負荷シナリオなど複数からの要求を多数処理する場合や本番環境の解析を行うケース
• 比較的長期間のデータ取得/分析を行うケース

おわりに

Java環境のプロファイラはOSSで必要十分な機能が提供されていました。利用用途次第のためJFR/JMCとVisualVMのどちらが優れているという事は言えませんが、私は適用範囲の広いJFR/JMCの使い方を先に覚えるほうがよいと思います。本番環境でプロファイリングを実施しやすいというのは大きなメリットだと思います。一度プロファイラの使い方に慣れてしまえば、一連の作業(プロファイル取得/解析)とメトリクス(実行時間、I/O待ち等)は変わらないため、VisualVMに限らず他の環境のプロファイラもすぐに使えるようになると思います。

参考URL

• OpenJDK Mission Controlのソースリポジトリ https://github.com/openjdk/jmc ⧉
• JMCのドキュメント https://www.oracle.com/java/technologies/jdk-mission-control.html ⧉
• VisualVMのサイト https://visualvm.github.io/ ⧉
• Amazon Correttoの開発チームによるJMCのビルド https://github.com/corretto/corretto-jmc ⧉