原文はこちら。
The original article was written by Chris Hegarty (Networking Lead of the Java Platform Group, Oracle).
https://inside.java/2021/06/04/experimenting-with-jfr-mirror-events/
この記事では、JDKの中核部分、特にNetworking APIにてJFRのミラーイベントが使えるかどうかを判断する実験を行った際の、いくつかの観察結果について説明します。ミラーイベントは、jdk.jfrモジュールに依存しないJDKが使用する内部メカニズムで、現在、唯一のミラーイベントがjava.baseで定義されています。ミラーイベントはJDKでしか利用できないため、ここで説明されている内容の多くは、アプリケーションやライブラリの開発者ではなく、JDKに携わる開発者に直接関連するものですが、特定の関心事や技術に対し、より多くの人々に興味を持ってもらえるかもしれません。
JDK、特にbaseモジュールにイベントを実装する場合、現在いくつかのアプローチがあります。
- JVMでのネイティブ実装
- 実行時のバイトコードインストルメンテーション
- ミラーイベント
1個目のJVMでのネイティブ実装は、GC統計など、JVM自身の低レベルのオペレーションに最も適しています。JDK Coreライブラリのモニタリングには、バイトコード・インストルメンテーションやミラー・イベントといった後者の2つのアプローチが適しています。しかし、どのアプローチが良いのか、また、それらの間のトレードオフは何でしょうか？この記事では、ある特定のイベントを例にとり、その疑問に答えるためのインサイトと分析を提供します。
現在（JDK 17では）、ソケットの読み書き操作を監視できるJFRイベント、jdk.SocketReadEventとjdk.SocketWriteEventがあります。これらのイベントでは java.net.Socket と NIO SocketChannel の両方のI/Oを監視できます。ソケットやチャネルの実装コードを見ると、JFRやこれらのイベントへの参照はありませんが、これらのイベントの生成に関連するコードは、JFRが有効な場合、実行時に（ソケットやチャネルの実装クラスの）バイトコードインストゥルメンテーションによって実行されます。ここでは、まず既存のソケット書き込みイベントを記録したときのパフォーマンスデータを作成し、次にミラーイベントとして再実装したときのパフォーマンスデータを作成し、最後に改善の可能性がある分野を検討します。
ソケット書き込みイベントの詳細を説明する前に、イベントの設計と実装に関連する、より高いレベル、より一般的な考慮事項について説明します。
General Considerations
イベント（やイベント群）の設計にあたっては、以下の点を考慮します。
- 公開したい情報
- その情報を収集・記録するためのコスト
- その情報を伝えるために使用するイベントの種類
- イベントの発生頻度
- そのイベントは時限式か、非時限式か
- そのイベントは定期的に発生するか、それともオペレーションごとに発生するか
常にユースケースを念頭に置いて設計を進めるべきです。開発者がどのような質問に答えられるようにしたいのか、システムについてどのような洞察を提供したいのか、などです。
イベントがコードに与える影響を分析する際には、さまざまな問題があります。
| イベントをミラーイベントとして、ソースコードの実装に直接書き込むべきか？ | 保守性：メンテナンスが容易 可読性：あちこちに目をやる必要があり、可読性低下 パフォーマンス：JFR無効時のパフォーマンスへの影響 テストのしやすさ：リグレッションテストと一緒に配置 |
| イベントがインストルメント技術を使用して、実行時にバイトコードをイベントでインストルメントするようにすべきか？ | 保守性：保守しにくく、壊れやすい 可読性：運用コードの乱雑さがなくなる パフォーマンス：JFR無効時のパフォーマンスへの影響なし テストのしやすさ：不具合が発生しないようにするには十分なテストカバレッジが必要 |
パフォーマンスについては複数の懸念事項があります。
- 起動のパフォーマンス：JFRの初期化、起動にかかる時間
- Javaイベントが多くなるほど起動時間が長くなるか？
- JFR無効時の実行時パフォーマンス
- JFR有効時の実行時パフォーマンス（ただし特定のイベントが無効の場合）
- JFR有効時の実行時パフォーマンス（特定のイベントが有効の場合）
この記事の残りの部分では、後者のランタイム・パフォーマンスに関する懸念に焦点を当てます。
Analyzing Socket Write Event
JDK Coreライブラリのイベントでは、バイトコードインストゥルメンテーションとミラーイベントのどちらを使用するかが実装上の重要な問題の1つです。この問題に答えるために、JMHベンチマークを使用します。ベンチマークでは、SocketChannelの単一のメソッドであるwrite(ByteBuffer)を実行しますが、これは他のI/Oを実行するメソッドを代表するものと考えることができます。
JFRが有効な場合、writeメソッドの呼び出しにより、SocketWriteEventが記録されます。このイベントの宣言を以下に示します。
public final class SocketWriteEvent ... {
@Label("Remote Host")
public String host;
@Label("Remote Address")
public String address;
@Label("Remote Port")
public int port;
@Label("Bytes Written")
@Description("Number of bytes written to the socket")
@DataAmount
public long bytesWritten;
}
このイベントは、リモートホストの名前、アドレス、ポート番号、および書き込まれたバイト数をキャプチャします。開始時間や継続時間のような、ここで示されていない値もキャプチャされています。
このイベントは、実行時にSocketChannelImplクラスのwriteメソッドを変換するバイトコードインストゥルメンテーション技術を用いて実装されています。リモートエンドポイントと1バイトのデータを交換する簡単なベンチマークで、このイベントを記録することが書き込み操作の全体的なパフォーマンスに与える影響を測定できます。次に、SocketWriteEventをミラーイベントを使って実装するようにコードを書き換え、ベンチマークを再実行します。以下のケースについて、前後の結果の比較をします。
- JFRが無効（JFR-disabled）
- JFRが有効、SocketWriteイベントが無効（JFR-enabled-socketWrite-no）
- JFRが有効、SocketWriteイベントが有効（JFR-enabled-socketWrite-yes）
JFRが有効で、特定のイベントが有効だが、閾値に達していない場合、という第4のケースが存在します。ノンブロッキングチャネルのソケット書き込みを監視する場合、しきい値を0にして、すべてのイベントを記録したい場合がよくあります。この4つ目のケースについては、より複雑なため、別の記事で紹介します。
ベンチマークでは1回のベンチマーク呼び出しの平均実行時間を算出します。スコアが低いほど良好です。実行時間はLinux x86_64、Intel Xeon-8167M 2.00GHzで計測され、-prof gcプロファイラを使用しています（読みやすさを向上するため、結果では一部の出力行を省略しています）。ベンチマークはSocketChannelReadWriteのバージョンを修正したもので、こちらからご覧いただけます。
Baseline – JDK 17 EA
ソケット書き込みイベントはバイトコードインストゥルメンテーションを使って実装されています。
Benchmark (setupJFR) Mode Cnt Score Error Units
SocketChannelReadWrite.test JFR-disabled avgt 50 2.234 ± 0.009 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-disabled avgt 50 ≈ 10⁻⁴ MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-disabled avgt 50 0.001 ± 0.001 B/op
SocketChannelReadWrite.test JFR-enabled-socketWrite-no avgt 50 2.223 ± 0.006 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-enabled-socketWrite-no avgt 50 0.007 ± 0.004 MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-enabled-socketWrite-no avgt 50 0.024 ± 0.013 B/op
SocketChannelReadWrite.test JFR-enabled-socketWrite-yes avgt 50 3.058 ± 0.046 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-enabled-socketWrite-yes avgt 50 68.974 ± 3.317 MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-enabled-socketWrite-yes avgt 50 332.938 ± 20.804 B/op
SocketChannelReadWrite.test:·gc.churn.G1_Eden_Space.norm JFR-enabled-socketWrite-yes avgt 50 105.106 ± 286.331 B/op
JFR-disabledとJFR-enabled-socketWrite-noの操作あたりの平均時間は非常に似ており、アロケーションもほとんどないことがわかります。これは、最適化されたホットスポットのJITコンパイラによるところが大きいです。JFR-enabled-socketWrite-yesでは、1オペレーションあたりの時間が長くなり（これは予想されることです）、1オペレーションあたり332バイトという正規化された割合でアロケーションが発生しています（そのほとんどがchurnです）。
このベンチマークは、1バイトの書き込みを何度も繰り返す（私のマシンでは1反復あたり約400万回）ため、実際のアプリケーションを代表するものではありません。そのため、イベントが有効になっているときの操作ごとのコストは、このイベントのオーバーヘッドを示す一般的な指標として受け取るべきではありません。というのも、I/Oに大部分の時間が費やされるような大量のデータを書き込むときには、ほとんどが償却されるからです。今回の分析では、イベントのオーバーヘッドに注目できるように、I/Oにかかる時間を減らしたいので、1バイトを使用しています。
Using a Mirror Event
今回の実行では、ソケット書き込みイベントをbaseモジュールのミラーイベントを使って再実装しています（コード変更点はこちら）。イベントによって取得される実際のデータを決定するコードはほとんど以前のバイトコードインストゥルメンテーション版と同じですが、この実装ではミラーイベントを各イベントに割り当てています。
Benchmark (setupJFR) Mode Cnt Score Error Units
SocketChannelReadWrite.test JFR-disabled avgt 50 2.220 ± 0.014 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-disabled avgt 50 ≈ 10⁻⁴ MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-disabled avgt 50 0.001 ± 0.001 B/op
SocketChannelReadWrite.test JFR-enabled-socketWrite-no avgt 50 2.220 ± 0.010 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-enabled-socketWrite-no avgt 50 0.007 ± 0.004 MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-enabled-socketWrite-no avgt 50 0.025 ± 0.013 B/op
SocketChannelReadWrite.test JFR-enabled-socketWrite-yes avgt 50 3.123 ± 0.040 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-enabled-socketWrite-yes avgt 50 81.809 ± 5.572 MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-enabled-socketWrite-yes avgt 50 401.742 ± 25.480 B/op
SocketChannelReadWrite.test:·gc.churn.G1_Eden_Space.norm JFR-enabled-socketWrite-yes avgt 50 155.162 ± 380.211 B/op
JFR-disabledとJFR-enabled-socketWrite-noのオペレーションあたりの平均時間と正規化されたアロケーション率は、前回のベースラインとした実行と非常に似ていることがわかります。JFR-enabled-socketWrite-yesでは、オペレーションあたり401バイトの正規化されたアロケーション率で割り当てが行われ、ベースラインの実行に比べて約20%増加しました。
Tweaking a little
イベントによって取得された実際のデータ、具体的にはリモートホスト名とアドレスを決定するために、ちょっとしたコードを実行する必要があります。このコードではパブリックAPIと文字列操作を使用してホスト名とアドレスを取得していますが、これは最も効率的な方法ではなく、多くのアロケーションの原因となっているかもしれません。（パブリックAPIのみを使用するように制限されている場合、このコードは合理的です）。以下がそのコードです。
String hostString = isa.getAddress().toString();
int delimiterIndex = hostString.lastIndexOf('/');
event.host = hostString.substring(0, delimiterIndex);
event.address = hostString.substring(delimiterIndex + 1);
ミラーイベント版では、コードはチャネル実装と一緒にbaseモジュールに存在しているので、（パブリックAPIを使用しない）より良い代替手段を探す自由が与えられています。すぐに思いつくのは、Net の共有シークレットを拡張して、InetAddressからhostnameの文字列を返すようにすることです。アドレスは、InetAddress::getHostAddress()から取得できます。以下のコードは機能的に同等です。
InetAddress address = isa.getAddress();
var h = JNINA.hostnameValue(address);
event.host = h == null ? "" : h;
event.address = address.getHostAddress();
event.port = isa.getPort();
ミラーイベント版で再度ベンチマークを実行してみましょう。
Benchmark (setupJFR) Mode Cnt Score Error Units
...
SocketChannelReadWrite.test JFR-enabled-socketWrite-yes avgt 50 2.869 ± 0.022 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-enabled-socketWrite-yes avgt 50 40.773 ± 0.319 MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-enabled-socketWrite-yes avgt 50 184.139 ± 0.029 B/op
SocketChannelReadWrite.test:·gc.churn.G1_Eden_Space.norm JFR-enabled-socketWrite-yes avgt 50 55.492 ± 60.860 B/op
1回の操作時間が短縮され、アロケーションも減っていることがわかります。実際、ベースラインと比較すると、1回あたりの操作時間はわずかに改善されただけですが、アロケーションは約45％削減されています。
しかし、さらに改善できます。接続されているチャンネルのホスト名とアドレスをキャッシュするとどうでしょう。
Benchmark (setupJFR) Mode Cnt Score Error Units
SocketChannelReadWrite.test JFR-enabled-socketWrite-yes avgt 50 2.718 ± 0.042 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-enabled-socketWrite-yes avgt 50 11.274 ± 0.180 MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-enabled-socketWrite-yes avgt 50 48.221 ± 0.133 B/op
SocketChannelReadWrite.test:·gc.churn.G1_Eden_Space.norm JFR-enabled-socketWrite-yes avgt 50 50.237 ± 50.490 B/op
操作あたりのオーバーヘッドとアロケーションのオーバーヘッドの両方が大幅に減少していることがわかります。ベースラインと比較して、オペレーションあたりの時間は10％、 アロケーション は85％減少しています。これは、アロケーションのオーバーヘッドの多くが、イベント（およびそのインフラ）そのものではなく、イベントデータの値を決定するコードに関連していることを示しているように思えます。
最後に、apple to appleでの比較のために、バイトコードインストゥルメンテーション版を、キャッシュされたホスト名とアドレスフィールドにアクセスする形で実行した結果を以下に示します。
SocketChannelReadWrite.test JFR-enabled-socketWrite-yes avgt 50 2.630 ± 0.015 us/op
SocketChannelReadWrite.test:·gc.alloc.rate JFR-enabled-socketWrite-yes avgt 50 0.030 ± 0.007 MB/sec
SocketChannelReadWrite.test:·gc.alloc.rate.norm JFR-enabled-socketWrite-yes avgt 50 0.123 ± 0.029 B/op
SocketChannelReadWrite.test:·gc.count JFR-enabled-socketWrite-yes avgt 50 ≈ 0 counts
1回あたりの動作時間は、事前のミラーイベント実行時よりも少し短くなり、アロケーションもほとんどなくなっていることがわかります。これはおそらく良い結果だと思いますが、これまで見てきたように、既存のバイトコードインストルメンテーション版のソケット書き込みイベントを、より良いパフォーマンスとアロケーションのパフォーマンス特性を提供するミラーイベントに置き換えることが可能です。
Conclusion
ミラーイベントの設計では、イベントが発生するたびにイベントオブジェクトを作成する必要がありますが、それ自体はイベントを設計・実装する際の主要な関心事ではありません。むしろ、パフォーマンスとアロケーションの影響を全体的に考慮する必要があります。今回の実験で明らかになったのは、イベントの実装に使うメカニズムよりも、イベントによって取得される実際のデータをどう決定するかが、パフォーマンスに影響を与える可能性が高いということです。さらに、ミラーイベントを使用すると、このデータ決定のためのコード実装方法の自由度が高まります（private internalsへのアクセスがより容易になります）。
Logico Inside 