2020/04/12

Java 14 の新機能 (4) - JEP 349: JFR Event Streaming

JEP 349: JFR Event Streaming

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 無いところけっこうあるなぁ。