【Java】JDK Flight Recorder を調査・検証してみた

こんにちは、技術推進課の uemura_rks です。
私が所属する技術推進課では「各商材の開発チームから課題をヒアリングし、その解決に向けた調査を行う」という取り組みをしています。
取り組みの一環で Java のパフォーマンス分析、診断ツールである JDK Flight Recorder（JFR）について、その機能と導入することによるアプリへの影響を調査・検証しました。

「小さいオーバーヘッドで使えるらしいけど本当にそうなのか？」
を確認してみたので、その結果を報告します。

JFR を使えばトラブルの原因調査に役立つ情報を手軽に収集できます。
Java を扱っている方であればどなたにとっても有益なツールとなりますので是非最後までお付き合いください。

JDK Flight Recorder（JFR）の特徴

検証の前にまずはJFR がどんなツールなのか、その特徴を紹介します。

オーバーヘッドが小さい

アプリケーションを分析、診断するためには多くの情報を計測する必要があります。
JFR は JVM に組み込まれているため、その計測のオーバーヘッドは小さく、1,2%程度だといわれています。
商材に導入したらアプリ全体のパフォーマンスが悪化した、なんてことが起きにくいです。
（と、言いつつこの部分を後半で検証します）

手軽に使い始められる

JFR は各ベンダーの JDK に実装されているので、現在使っている JDK はそのまま、機能を有効化するだけで利用可能です。（有効化には JVM の起動オプションや jcmd を使います）
アプリサーバに何かしらのミドルウェアをインストールしたり、ソースコードに手を加えたりすることなく使い始められます。

JVM やアプリ動作に関する情報を取得できる

JFR のログからは

JVM のリソース状況
GC の情報
スレッドダンプ
コンパイルやコード・キャッシュの情報
ログを自動分析したレポート

など様々な情報を得ることができます。
JVM の動作に関するような低レベル情報を集めてくれるので、トラブル調査に役立つと思います。
いくつか例を載せておきます。

＜JVM のリソース状況＞ CPU 使用率やヒープ使用量、オブジェクトのメモリへの割当てなどを確認できます

＜自動分析のレポート＞ ログの包括的な分析レポートです。潜在的な問題をスコア化して警告してくれます。

＜スレッドダンプ＞
1分間隔でスレッドダンプを記録してくれています。

◆ログの可視化
JFR のログ自体はバイナリになっています。
JDK Mission Control（JMC）というビューアーを使うと上記キャプチャのように可視化できます。

その他、JFR で得られる情報やその見方についてはこちらのチュートリアルが分かりやすいです。

トラブルの再発を待たなくていい

JFR は基本的に常に有効化しておくツールです。
これは「オーバーヘッドが小さいこと」と後ほど紹介する「イベントログのデータフロー」から成っている強みになりますが、それ故に JFR は

「何かトラブルが起きてデータが欲しくなったから計測開始」ではなく、
「何かトラブルが起きたときに備えてずっと計測しておく」

という使い方ができます。
航空機のフライトレコーダーから名前を取っているようなのですが、まさしくその Java 版といったところです。
（もう少し身近なところで、ドライブレコーダーの Java 版と言った方が馴染みがあるかもしれません。）

取得情報はカスタマイズ可能

JFR は事前に定義されたイベントという単位で情報を集めます。*1
数あるイベントのうち、どれを取得するかは設定ファイルでカスタマイズすることができます。
独自の設定を作成することもできますし、テンプレートとして2種類の設定ファイルが JDK に同梱されていますので、それをそのまま使うこともできます。

default.jfc
- 本番環境での継続的な記録に向いたテンプレート設定
- オーバーヘッドは1%ほど
profile.jfc
- 検証向けのテンプレート設定
- オーバーヘッドは2%ほど

＜設定ファイルの一部＞

<event name="jdk.ThreadAllocationStatistics">
  <setting name="enabled">true</setting>
  <setting name="period">everyChunk</setting>
</event>

<event name="jdk.ClassLoadingStatistics">
  <setting name="enabled">true</setting>
  <setting name="period">1000 ms</setting>
</event>

設定ファイルはxml形式になっています。 enabled属性のtrue / falseを切り替えることで取得イベントの選択ができます。

イベントログのデータフロー

JFR が取得するイベントがログファイルとして出力されるまでの流れを紹介します。
登場人物の多くは JFR のオプションでサイズなどの調整が可能です。*2
流れを把握し、環境に合わせて適切なオプションを指定することで、導入によるサーバリソースへの負荷を抑えることができます。

◆アーキテクチャ
JFR ではイベントを「スレッドローカルバッファ」「グローバルバッファ」の2つのメモリ領域と「リポジトリ」と呼ばれるディスク領域で保管しています。

◆データフロー
①拾ったイベントを「スレッドローカルバッファ」に格納
　スレッドローカルバッファはスレッド単位の専用バッファのため、他のスレッドと競合することがありません。
　初動でこのバッファを使うことで高速なイベント収集を実現しているそうです。

②「スレッドローカルバッファ」から「グローバルバッファ」にコピー
　スレッドローカルバッファは小さいためすぐに一杯になります。溢れた情報はグローバルバッファに移ります。
　グローバルバッファはスレッド間で共有するプロセスのメモリで、循環バッファの形になっています。

③「グローバルバッファ」から「リポジトリ」にファイル出力
　グローバルバッファからも溢れた情報はリポジトリというディスク領域に.partファイルとして
　出力されます。

④part ファイルからチャンクダンプに変換
　グローバルバッファから溢れた情報はどんどん.partファイルに溜まっていきます。
　こちらも一定のサイズたまると、.jfrファイルに変換されます。
　（これをこの記事ではチャンクダンプと呼びます）
　チャンクダンプは JFR のログファイルとして完全なバイナリになっており、JMC などのビューアーを使って
　可視化することができます。

　また、リポジトリ領域はログの最長保管期間や最大保管サイズをオプションで指定することができます。
　ストレージを圧迫しすぎないような設定をおすすめします。

⑤jcmd やプロセスの停止などによって JFR ファイルを出力
　③④で出力されるチャンクダンプはチャンクサイズごとに細切れになったファイルです。
　jcmd によるダンプ出力の指示やプロセスの停止をトリガーとして、すべての記録が一つにまとまった
　JFR ファイルを生成することができます。*3
　（これをこの記事ではフルダンプと呼ぶことにします）
　フルダンプと一つひとつのチャンクダンプの中身は基本的に一緒ですが、フルダンプにはまだチャンクダンプに
　吐き出されていなかったメモリ領域のイベントログも出力されます。

オーバーヘッドによる影響度検証

オーバーヘッドが小さく、故に常に有効化しておくことのできる JFR ですが、
そのオーバーヘッドが実際にアプリにどれぐらいの影響を与えるかをCPU・Javaヒープ使用量・プロセスが消費する最大メモリ量・ディスク吐き出し時のアプリ動作への影響・ダンプサイズ（ストレージへの影響）の5つの観点で検証してみました。

検証結果

少し長くなるので結果だけ先に述べておきます。
5つの観点ですが...

「Java ヒープ使用量」への影響のみ要注意
その他は無視できるか、オプションで調整可能な範囲の影響

だと言える結果になりました。詳細をこれから記していきます。

CPU

CPUへの影響は次の観点とメトリクスで見ていきます

リクエスト処理中の影響
→ CPUが高稼働になっていた時間を計測
待機中（リクエストを処理していない時）の影響
→ CPU使用率を計測

◆計測方法

リクエスト処理中にひたすらCPU負荷をかけるサンプルを用意してリクエストを繰り返し送りました。
次の3パターンで試行し、2つのメトリクスを計測結果から抽出します。

JFR 無効
JFR 有効 / 本番向け設定ファイル（default.jfc）を使用
JFR 有効 / 検証向け設定ファイル（profile.jfc）を使用

◆計測結果

各パターンの計測値を比較した結果です。

＜リクエスト処理中の影響（CPUが高稼働になっていた時間）＞

	CPU(JVM) 高稼働時間		CPU(マシン) 高稼働時間
	※平均	JFR 無効との差 [増加率]	※平均	JFR 無効との差 [増加率]
JFR 無効	56.88 秒	-	56.90 秒	-
JFR 有効（default.jfc）	57.15 秒	+ 0.27 秒 [+ 0.47 %]	57.35 秒	+ 0.47 秒 [+ 0.79 %]
JFR 有効（profile.jfc）	57.21 秒	+ 0.33 秒 [+ 0.58 %]	57.35 秒	+ 0.47 秒 [+ 0.79 %]

※平均：20リクエストの平均

⇒ 増加率1%未満の範囲でわずかに増加 という結果になりました。

＜待機中の影響（CPU使用率）＞

	CPU(JVM) 使用率		CPU(マシン) 使用率
	※平均	JFR 無効との差	※平均	JFR 無効との差
JFR 無効	0.986 %	-	1.207 %	-
JFR 有効（default.jfc）	1.640 %	+ 0.654 %	1.738 %	+ 0.531 %
JFR 有効（profile.jfc）	1.830 %	+ 0.844 %	1.869 %	+ 0.662 %

※平均：19期間の平均

⇒ 増加量1%未満の範囲でわずかに増加 という結果になりました。

Javaヒープ使用量

Java ヒープへの影響を見ていきます。
こちらもリクエスト処理中と待機中の2つの観点で使用量の変化を確認しました。

◆計測方法
リクエスト処理中にメモリ負荷をかけ続けるサンプルとシンプルなDBアクセスのみをするサンプル
の2種類のサンプルを用意して、それぞれでヒープの変化を計測しました。

また、こちらは正確な関係がわかっていないのですが、JFR を有効化していると初回のリクエスト終了後にフルGCが走るという動きが見られました。
（Java ヒープの New 領域や Old 領域に余白があってもフルGCが走っていました）
そのため、リクエスト処理中 待機中それぞれでフルGC前 フルGC後の2地点の計測を行いました。

こちらもCPUと同じく JFR の有無で結果を比較します。

◆計測結果
こちらはいくつか条件を組み合わせて計測したのですが、その条件の違いや同一条件内でも試行ごとで計測値のブレが大きい結果となりました。
結果の一例を載せますが、こちらの結果では一部（平均値で）20%近い増加率も記録されています。

サンプルアプリの範囲での結果ですので実商材でも同じ結果になるとは言い切れませんが、
導入を検討する際の要注意項目となりました。

＜リクエスト処理中の影響（Javaヒープ使用量）＞

	Javaヒープ使用量(フルGC前)		Javaヒープ使用量(フルGC後)
	※平均	JFR 無効との差 [増加率]	※平均	JFR 無効との差 [増加率]
JFR 無効	247.8 MB	-	32.9 MB	-
JFR 有効（default.jfc）	270.6 MB	+ 22.8 MB [+ 9.2 %]	36.8 MB	+ 3.9 MB [+ 11.9 %]
JFR 有効（profile.jfc）	279.5 MB	+ 31.7 MB [+ 12.8 %]	34.5 MB	+ 1.6 MB [+4.9 %]

※同一条件で3回計測した平均

＜待機中の影響（Javaヒープ使用量）＞

	Javaヒープ使用量(フルGC前)		Javaヒープ使用量(フルGC後)
	※平均	JFR 無効との差 [増加率]	※平均	JFR 無効との差 [増加率]
JFR 無効	205.2 MB	-	30.6 MB	-
JFR 有効（default.jfc）	244.1 MB	+ 38.9 MB [+ 19.0 %]	34.7 MB	+ 4.1 MB [+ 13.4 %]
JFR 有効（profile.jfc）	238.4 MB	+ 33.2 MB [+ 16.2 %]	32.5 MB	+ 1.8 MB [+5.9 %]

※同一条件で3回計測した平均

プロセスが消費する最大メモリ量

JFR がイベントログを溜める上で、プロセスとしてどこまでメモリを使用するか確認しました。
おそらくグローバルバッファのサイズに比例するだろうと仮定しつつも、際限なく食い潰される危険がないかを検証します。

計測メトリクスとしては「3日間アプリを稼働させた中で記録した RSS の最大値」を見ていきます。
検証でいろいろ試していく中で、JFR のイベントログはCヒープ領域に保持されていそうだと理解したため、RSS を取っています。（JVM に組み込まれているという特徴も相まってそう判断しています）

◆計測方法

サンプルアプリを立ち上げ、3日間ひたすらリクエストを送り続けました。

◆計測結果

⇒ 想定通り、グローバルバッファのサイズに準じて増加する という結果が得られました。
グローバルバッファのサイズは JVM 起動時のオプションなどで指定できます。
サイズの大きさとディスク吐出しの頻度はトレードオフですが、
環境に合わせてサイズを指定してあげれば影響は小さくできると言えます。

ディスク吐き出し時のアプリ動作への影響

JFRはそのデータフローの中で3種類のディスク吐出しを行います

.partファイル出力
チャンクダンプ出力
フルダンプ出力

それぞれのファイル出力時において、アプリに遅延が発生しないかを確認します。
リクエストの処理時間をメトリクスとし、ファイル出力の有無による時間の差を見ます。

◆計測方法

サンプルアプリに対して定期的にリクエストを送ります。
.partファイルとチャンクダンプは一定リクエストを送れば自動で出力されますので、そのときのリクエスト処理時間を計測します。
フルダンプは jcmd で出力指示を出して、そのときのリクエスト処理時間を計測します。

◆計測結果

ディスク吐出し時の処理時間と、平均処理時間を比較した結果です。

＜.partファイル出力時＞

吐出しサイズ※	リクエスト処理時間
吐出しサイズ※	平均	ファイル出力時	増加量 [増加率]
39.98 MB	8.809 秒	8.728 秒	- 0.081 秒 [- 0.92 %]
79.96 MB		9.090 秒	+ 0.281 秒 [+ 3.19 %]
119.69 MB		8.917 秒	+ 0.108 秒 [+ 1.23 %]

※partファイルの増加量

＜チャンクダンプ出力時＞

吐出しサイズ※	リクエスト処理時間
吐出しサイズ※	平均	ファイル出力時	増加量 [増加率]
40.4 MB	8.883 秒	8.927 秒	+ 0.044 秒 [+ 0.50 %]
80.7 MB		8.708 秒	- 0.175 秒 [- 1.97 %]
119.0 MB		8.917 秒	+ 0.034 秒 [+ 0.38 %]

※(出力されたチャンクダンプのサイズ) - (直前のpartファイルのサイズ)

＜フルダンプ出力時＞

フルダンプサイズ	リクエスト処理時間
フルダンプサイズ	平均	ファイル出力時	増加量 [増加率]
111.7 MB	8.564 秒	9.645 秒	+ 1.081 秒 [+ 12.6 %]
226.3 MB	8.582 秒	9.912 秒	+ 1.33 秒 [+ 15.5 %]
456.0 MB	8.677 秒	10.505 秒	+ 1.828 秒 [+ 21.1 %]

⇒ 気にするべきは「フルダンプ出力時」になります。
フルダンプ出力時は、指示を出したタイミングで別プロセスが大量に立ち上がり、
アプリ（JVM）の使えるCPUが30%ほど減っていました。
結果、増加率 21.1 % という大きな数値につながっています。
とはいえ、フルダンプ出力は普段プロセスが動いているときに勝手に実行される機能でもありません。
フルダンプ出力の命令タイミングだけ気を付けることで回避可能な影響ですのでクリティカルなものではないと考えています。

また、.partファイルやチャンクダンプ出力時の増加率は1桁%となっており、その影響は十分小さいと言えます。

ダンプサイズ

JFR のダンプサイズがどれぐらいになるか計測します。
自社の商材ではログはアプリサーバからログサーバに転送しているのですが、
そのログサーバを圧迫するようなことがないかを確認します。

◆計測方法

15時間アプリを稼働させ、次の観点の組み合わせで15時間後のダンプサイズを計測します。

設定ファイル
- default.jfc / profile.jfc
リクエスト回数
- 15時間で... 0リクエスト / 約26,500 リクエスト / 約53,000 リクエスト / 約106,000 リクエスト

◆計測結果

⇒ ダンプサイズはリクエスト回数に応じて微増しました。
同じリクエストを投げていたため同じイベントを大量に収集したことになりますが、同一イベントであれば JFR がいい感じに圧縮してくれていそうです。

計測結果から1日当たりのダンプサイズを試算してみると、数万～数十万リクエスト/日規模のシステムであれば、本番運用向けの default.jfc 設定でざっくり 300MB/日程のサイズになると見込めます。
また、ダンプファイルは gzip や bzip2 で圧縮をかければ3割のサイズにまで小さくできました。実質 90MB/日程です。

このサイズをどう捉えるかは各々の環境次第ではありますが、商材の持つリクエスト数やアプリサーバの台数なども加味して、場合によってはログローテートを見直すなどの対応が必要になりそうです。

まとめ

JDK Flight Recorder の特徴と、オーバヘッドによるアプリへの影響を検証した結果を紹介しました。
アプリへの影響としては、Java ヒープへの影響のみ要注意だが、その他は無視できるか、オプションで調整可能な範囲だと言える結果になりました。
また、機能を有効化するだけで使い始められる手軽さと収集できる情報の豊富さは大きな魅力だと思っています。

小さくはじめられて大きなリターンを期待できますので、この記事を読んでくださった方も是非 JFR を使ってみてください。