JDK Flight Recorder という機能が OpenJDK 11 から含まれています。JRockit 由来の機能で、VM 内部のイベントをファイルに記録し、VM の実行中でも終了後でも、Mission Control や JFR API を使ったプログラムでプロファイリング的に解析できるというものです。
動作中の VM に対しても使えるのですが、記録されたイベントを走査していく形の API なので、リアルタイム監視目的にはちょっと使いづらい API でした。
そこにきて今回、ストリーム形式の API が追加され、イベントドリブンな形で JFR イベントにアクセスできるようになりました。インプロセスでの JFR イベント処理はもちろん、記録されたファイルを解析するときも、どちらも EventStream という統一されたインターフェースでアクセスできます。
インプロセス監視の例
簡単に試してみました。import java.time.Duration;
import java.util.Arrays;
import java.util.Random;
import jdk.jfr.consumer.RecordingStream;
public class JFRSample {
public static void main(final String[] args) throws InterruptedException {
try (var rs = new RecordingStream()) {
rs.enable("jdk.CPULoad").withPeriod(Duration.ofSeconds(1));
rs.onEvent("jdk.CPULoad", event -> {
System.out.println("CPULoad - machineTotal: " + event.getFloat("machineTotal"));
});
rs.enable("jdk.JavaMonitorEnter").withThreshold(Duration.ofMillis(10));
rs.onEvent("jdk.JavaMonitorEnter", event -> {
System.out.println("monitorClass: " + event.getClass("monitorClass"));
});
rs.enable("jdk.GCPhasePause").withPeriod(Duration.ofSeconds(1));
rs.onEvent("jdk.GCPhasePause", event -> {
System.out.println("GCPhasePause: " + event);
});
rs.enable("jdk.ThreadStart");
rs.onEvent("jdk.ThreadStart", event -> {
System.out.println("ThreadStart: " + event);
});
rs.enable("jdk.ThreadEnd");
rs.onEvent("jdk.ThreadEnd", event -> {
System.out.println("ThreadEnd: " + event);
});
rs.startAsync();
var r = new Random();
System.out.println("Generate started.");
var data = r.ints(0x10000000).toArray();
System.out.println("Generate finidhed.");
System.out.println("Sort started.");
var result = Arrays.copyOf(data, data.length);
Arrays.parallelSort(result);
System.out.println("Sort finished.");
Thread.sleep(5000);
}
}
}
9行目で RecordingStream を作っています。これがインプロセス監視用の EventStream の実装です。AutoCloseable なので、try-with-resources 構文にしています。
10〜33行目は監視項目の有効化と、イベントハンドラの登録です。CPU 時間、wait 状況、GC 時間、スレッド開始/終了状況を捕捉してみています。
34行目で監視を開始しています。start() を使えば同期的に、startAsync() なら非同期的に動かせます。今回は非同期にしています。
36行目以降は JFR イベントが発生するように、適当に時間がかかってメモリを使うような処理をさせてみているだけです。36〜39行目は大きな配列に乱数を入れています。40〜43行目は大きな配列をコピーし、ソートしています。
44行目は処理終了後の JFR イベントの様子を見るため、5秒ほど待っています。
try-with-resources 構文なので、ブロック終了のところで RecordingStream が close() されて、非同期スレッドが終了するので、プログラム終了です。
実行結果はこんな感じ。
Generate started.
ThreadStart: jdk.ThreadStart {
startTime = 02:28:33.487
thread = N/A
}
GCPhasePause: jdk.GCPhasePause {
startTime = 02:28:33.490
duration = 2.48 ms
gcId = 1
name = "GC Pause"
}
GCPhasePause: jdk.GCPhasePause {
startTime = 02:28:34.006
duration = 5.00 ms
gcId = 2
name = "Pause Remark"
}
GCPhasePause: jdk.GCPhasePause {
startTime = 02:28:34.012
duration = 0.170 ms
gcId = 2
name = "Pause Cleanup"
}
ThreadEnd: jdk.ThreadEnd {
startTime = 02:28:34.443
thread = "C2 CompilerThread2" (javaThreadId = 8)
eventThread = "C2 CompilerThread2" (javaThreadId = 8)
}
ThreadStart: jdk.ThreadStart {
startTime = 02:28:34.453
thread = N/A
}
ThreadEnd: jdk.ThreadEnd {
startTime = 02:28:35.449
thread = N/A
}
ThreadEnd: jdk.ThreadEnd {
startTime = 02:28:35.449
thread = "C2 CompilerThread1" (javaThreadId = 7)
eventThread = "C2 CompilerThread1" (javaThreadId = 7)
}
CPULoad - machineTotal: 0.17267081
ThreadStart: jdk.ThreadStart {
startTime = 02:28:35.463
thread = N/A
}
CPULoad - machineTotal: 0.16334164
Generate finidhed.
Sort started.
ThreadEnd: jdk.ThreadEnd {
startTime = 02:28:36.451
thread = N/A
}
CPULoad - machineTotal: 0.15547264
GCPhasePause: jdk.GCPhasePause {
startTime = 02:28:37.475
duration = 4.44 ms
gcId = 3
name = "GC Pause"
}
GCPhasePause: jdk.GCPhasePause {
startTime = 02:28:38.012
duration = 7.59 ms
gcId = 4
name = "Pause Remark"
}
monitorClass: {
classLoader = null name = "java/lang/ref/ReferenceQueue$Lock"
package = {
name = "java/lang/ref"
module = {
name = "java.base"
version = "14"
location = "jrt:/java.base"
classLoader = null }
exported = true
}
modifiers = 32
}
GCPhasePause: jdk.GCPhasePause {
startTime = 02:28:38.258
duration = 0.274 ms
gcId = 4
name = "Pause Cleanup"
}
CPULoad - machineTotal: 0.16687422
ThreadStart: jdk.ThreadStart {
startTime = 02:28:39.165
thread = N/A
}
ThreadStart: jdk.ThreadStart {
startTime = 02:28:39.165
thread = N/A
}
ThreadStart: jdk.ThreadStart {
startTime = 02:28:39.166
thread = N/A
}
ThreadStart: jdk.ThreadStart {
startTime = 02:28:39.310
thread = N/A
}
ThreadStart: jdk.ThreadStart {
startTime = 02:28:39.324
thread = N/A
}
ThreadStart: jdk.ThreadStart {
startTime = 02:28:39.325
thread = N/A
}
ThreadStart: jdk.ThreadStart {
startTime = 02:28:39.327
thread = N/A
}
CPULoad - machineTotal: 0.31618568
CPULoad - machineTotal: 0.91635454
CPULoad - machineTotal: 0.8955224
CPULoad - machineTotal: 0.88875
CPULoad - machineTotal: 0.8916563
Sort finished.
CPULoad - machineTotal: 0.8873592
CPULoad - machineTotal: 0.08302354
CPULoad - machineTotal: 0.03375
CPULoad - machineTotal: 0.04607721
CPULoad - machineTotal: 0.04109589
CPULoad - machineTotal: 0.05230386
使用可能なイベント情報は API で取得できる
ちなみに、イベント情報の API もあるので、ちょっとしたプログラムを書けば、どんなイベントが取得できるか確認できます。これは昔からある API です。import jdk.jfr.FlightRecorder;
public class JFRInfo {
public static void main(final String[] args) {
FlightRecorder jfr = FlightRecorder.getFlightRecorder();
for (var type: jfr.getEventTypes()) {
System.out.println(type.getName() + ": " + type.getDescription());
System.out.println(" Settings:");
for (var desc: type.getSettingDescriptors()) {
System.out.println(" " + desc.getName() + ": " + desc.getDescription() + " (default: " + desc.getDefaultValue() + ")");
}
System.out.println(" Fields:");
for (var val: type.getFields()) {
System.out.println(" " + val.getName() + ": " + val.getDescription());
}
}
}
}
私の環境では、こんな感じでした。
jdk.X509Validation: Serial numbers from X.509 Certificates forming chain of trust
Settings:
enabled: Record event (default: false)
threshold: Record event with duration above or equal to threshold (default: 0 ns)
stackTrace: Record stack traces (default: false)
Fields:
startTime: null
duration: null
eventThread: Thread in which event was committed in
stackTrace: Stack Trace starting from the method the event was committed in
certificateId: null
certificatePosition: Certificate position in chain of trust, 1 = trust anchor
validationCounter: null
jdk.TLSHandshake: Parameters used in TLS Handshake
Settings:
enabled: Record event (default: false)
threshold: Record event with duration above or equal to threshold (default: 0 ns)
stackTrace: Record stack traces (default: false)
Fields:
startTime: null
duration: null
eventThread: Thread in which event was committed in
stackTrace: Stack Trace starting from the method the event was committed in
peerHost: null
peerPort: null
protocolVersion: null
cipherSuite: null
certificateId: Peer Certificate Id
(snip)
jdk.ShenandoahHeapRegionInformation: Information about a specific heap region in the Shenandoah GC
Settings:
enabled: Record event (default: false)
period: Record event at interval (default: everyChunk)
Fields:
startTime: null
index: null
state: null
start: null
used: null
jdk.Flush: null
Settings:
enabled: Record event (default: false)
threshold: Record event with duration above or equal to threshold (default: 0 ns)
Fields:
startTime: null
duration: null
flushId: null
elements: null
size: null
結構いっぱいあるので、いずれじっくり見てみます。description 無いところけっこうあるなぁ。