JFR Under the hood : StartFlightRecordingのVM引数をJFRへ適用する処理

結論

VM起動引数として指定された-XX:StartFlightRecording=xxx=xxx,yyy=yyyという形式のパラメータは、VMを起動する途中で、JFRのパラメータを初期化するメソッド(JfrOptionSet::initialize)でjcmd の方法に変換されます。その後、VMはJFRのパラメータを設定するメソッド(JfrOptionSet::configure)で内部的に jcmd JFR.configure を実行することで設定を適用します。

VMを起動する処理

VMを起動する処理の一部としてjdk/src/hotspot/share/jfr/recorder/service/jfrOptionSet.cppにあるon_create_vm_2メソッドが実行されます。 この処理では、主に以下の処理が実行されます。

1. JFRのパラメータを初期化JfrOptionSet::initialize
2. 設定JfrOptionSet::configure

VM を作成する処理の一部

bool JfrRecorder::on_create_vm_2() {
（略）
  Thread* const thread = Thread::current();
  if (!JfrOptionSet::initialize(thread)) {
    return false;
  }
  if (!register_jfr_dcmds()) {
    return false;
  }
（略）
    if (!validate_recording_options(thread)) {
      return false;
    }
    if (!JfrOptionSet::configure(thread)) {
      return false;
    }
（略）
}

1. JFR のパラメータを初期化

この処理では、主に以下の処理が実行されます。

• デフォルト値の読み込み
• VM起動引数をjcmdの形式に変換
• 過去の形式の古いパラメータ(ObsoleteOption)が使われていたらメッセージを出力

bool JfrOptionSet::initialize(Thread* thread) {
  register_parser_options();
  if (!parse_flight_recorder_options_internal(thread)) {
    return false;
  }
（略）
}

2. 設定

jcmd を使って設定します。jcmd JFR.configureの実体であるJfrConfigureFlightRecorderDCmdクラスのインスタンスに入力されたパラメータを指定して内部的にコマンドを実行(execute)します。

bool JfrOptionSet::configure(TRAPS) {
（略）
  // delegate to DCmd execution
  JfrConfigureFlightRecorderDCmd configure(&st, false);
（略）
  configure._stack_depth.set_is_set(_dcmd_stackdepth.is_set());
  configure._stack_depth.set_value(_dcmd_stackdepth.value());
（略）
  configure.set_verbose(false);
  configure.execute(DCmd_Source_Internal, THREAD);
（略）
}

どこに設定は格納されているのか？

設定は Java と C/C++ の範囲でそれぞれ格納されています。Java は jdk.jfrモジュールのjdk/jfr/internal/Optionsクラス、C/C++ はhotspot/share/jfr/recorder/jfrRecorder.cpp に格納されます。

jcmd JFR.configure では Options クラスに格納します。Options クラスでは setter で自分の持つフィールドに格納すると共に、JNI で C/++ のメソッドを呼び出して jfrRecorderにも格納します。

Optionsで設定を変更するメソッド

public static synchronized void setGlobalBufferCount(long globalBufCount) {
    jvm.setGlobalBufferCount(globalBufCount);
    globalBufferCount = globalBufCount;
}

jfrRecorder.cppでC/C++ で設定値が格納される変数

jlong JfrOptionSet::_max_chunk_size = 0;
jlong JfrOptionSet::_global_buffer_size = 0;
jlong JfrOptionSet::_thread_buffer_size = 0;
jlong JfrOptionSet::_memory_size = 0;
jlong JfrOptionSet::_num_global_buffers = 0;
jlong JfrOptionSet::_old_object_queue_size = 0;
u4 JfrOptionSet::_stack_depth = STACK_DEPTH_DEFAULT;
jboolean JfrOptionSet::_sample_threads = JNI_TRUE;
jboolean JfrOptionSet::_retransform = JNI_TRUE;

JNIのマッピングは hotspot/share/jfr/jni/jfrJniMethodRegistration.cppとhotspot/share/jfr/jni/jfrJniMethod.cppで行われてます。

JFR Under the hood : ローカルで動くJFR Event Streamingのリアルタイム性

結論

ローカルに作られるリポジトリからイベントを読み込みます。イベントは非同期でこのファイルに書込まれます。そのため、本当の意味でのリアルタイムにはイベントは処理されないため気を付けましょう。

JFR Event Streamingとは

Java 14 で追加された JFR Event Streaming、以下の様に書くと JVM の内部のイベントとかをストリーミングで処理してくれる素晴らしい機能です。

import jdk.jfr.Configuration;
import jdk.jfr.consumer.EventStream;
import jdk.jfr.consumer.RecordingStream;
import java.io.IOException;
import java.text.ParseException;
import java.time.Duration;
import java.util.concurrent.TimeUnit;

public class JfrEventStreamingLocalAsync {
    public static void main(String... args) {
        try (EventStream es = new RecordingStream(Configuration.getConfiguration("default"))) {
            es.onEvent("jdk.JVMInformation", System.out::println);
            es.startAsync();
            creatingEventsProcess();
            es.awaitTermination(Duration.ofSeconds(2));
        } catch (ParseException | IOException | InterruptedException e) {
            System.err.println("Couldn't start JFR Event Streaming");
        }
    }
}

この機能、ローカル実行とリモート実行ができ、それぞれでEventStreamインスタンスを作る方法が異なります。

リモート実行はEventStream.openRepository(Path)メソッドを使用してEventStreamインスタンスを作るので「あ～JFRのリポジトリから取るんだな～。ですよね～」と思ってました。

また、ローカル実行の場合はEventStreamクラスのサブクラスであるRecordingStreamコンストラクタを使用します。このコンストラクタにどの設定でJFRを開始するかを指定してインスタンスを作ります。ローカル実行の場合はstartする時に新たに JFR の記録を開始します。そのため、JFRが内部で持つバッファを見ていてイベントが追加された瞬間にリアルタイムにイベントが処理されるのだろうなぁと思っていました。

読む場所はどこか

「Javaからバッファを見るAPIが追加されてるだろうから見てみるか」と思ってソースを見たところ、EventDirectoryStreamとなっていました。これはリポジトリからイベントを読み込むクラスです。このクラスのコンストラクタは第２引数にリポジトリのパスを指定します。しかし、この引数はnullが渡されていました。

    public RecordingStream() {
        Utils.checkAccessFlightRecorder();
        AccessControlContext acc = AccessController.getContext();
        this.recording = new Recording();
        try {
            PlatformRecording pr = PrivateAccess.getInstance().getPlatformRecording(recording);
            this.directoryStream = new EventDirectoryStream(acc, null, SecuritySupport.PRIVILEGED, pr);
        } catch (IOException ioe) {
            this.recording.close();
            throw new IllegalStateException(ioe.getMessage());
        }
    }

https://github.com/openjdk/jdk/blob/6d137a36169956171bfd0afef91e8ce29b568e33/src/jdk.jfr/share/classes/jdk/jfr/consumer/RecordingStream.java#L88

「バッファから読む場合は null なのかな？」と思って読み進めてみると、パスを決めるために実行されるRepositoryFilesクラスのprivate boolean updatePaths() throws IOExceptionメソッドに以下の様なコメントが記載されていました。

// Always get the latest repository if 'jcmd JFR.configure
// repositorypath=...' has been executed
SafePath sf = Repository.getRepository().getRepositoryPath();

https://github.com/openjdk/jdk/blob/6d137a36169956171bfd0afef91e8ce29b568e33/src/jdk.jfr/share/classes/jdk/jfr/internal/consumer/RepositoryFiles.java#L166

どうやら JFR の内部 API である Repositoryクラスを使用して最新のリポジトリを取得しているようです。このクラスはシングルトンで、名前の通り JFR のリポジトリを管理しています。

まとめ

これまでのソースコードで、JFR Event Streaming をローカル実行すると、その JVM にある最新のリポジトリからイベントを読み込んでいるのが分かります。JVM によって記録されるイベントは非同期でこのファイルへ書込み、JFR Event Streaming は書込まれたイベントを都度読み込んで処理されます。そのため、イベントの処理はリアルタイムではなく少し遅れて処理されます。

Quarkus で JFR Event Streaming

Java 14 から JDK Flight Recorder で取得した情報を Java プロセス内で処理する JFR Event Streaming が導入されました。今回はこれを Quarkus で使ってみたいと思います。

今回のサンプルでは JFR では標準的な情報を取得するようにします。JFR Event Streaming は、JVMの情報を記録するイベントを受け取ったらそのイベントを標準出力に処理します。Java MP のアプリケーションスコープの開始処理と終了処理で JFR Event Streaming をそれぞれ開始/終了します。

開始処理では、JFCファイルというJFRの設定ファイル名を指定して設定を読み込み、ストリームを作成します。さらに、ストリームを流れるイベントの種類ごとに処理内容を指定し、ストリームを開始します。今回読み込むJFCファイルはdefault.jfcなので、defaultを指定します。また、今回受け取るイベントの名前はjdk.JVMInformationです。

終了処理では、ストリームがあれば閉じます。

import javax.enterprise.context.ApplicationScoped;
import javax.enterprise.event.Observes;
import java.io.IOException;
import java.text.ParseException;

@ApplicationScoped
public class JfrStreamingBean {

    private EventStream es;

    void onStart(@Observes StartupEvent ev) {
        try {
            Configuration config = Configuration.getConfiguration("default");
            this.es = new RecordingStream(config);
            this.es.onEvent("jdk.JVMInformation", System.out::println);

            this.es.startAsync();
        } catch (ParseException | IOException e) {
            System.err.println("Couldn't start JFR Event Streaming");
        }
    }

    void onStop(@Observes ShutdownEvent ev) {
        if (this.es != null) {
            es.close();
        }
    }
}

このプログラムを実行してみます。Quarkus の通常の実行方法で実行します。今回は開発者モードで実行します。

mvnw.cmd quarkus:dev

Quarkus が実行したあとに、JVM情報のイベントであるjdk.JVMInformationというイベントが出力されます。

__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2020-05-28 18:16:55,594 INFO  [io.quarkus] (Quarkus Main Thread) quarkus-jfr-streaming 1.0-SNAPSHOT (powered by Quarkus 1.4.2.Final) started in 1.110s. Listening on: http://0.0.0.0:8080
2020-05-28 18:16:55,605 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2020-05-28 18:16:55,605 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [cdi, resteasy, smallrye-metrics]
jdk.JVMInformation {
  startTime = 18:16:55.549
  jvmName = "OpenJDK 64-Bit Server VM"
  jvmVersion = "OpenJDK 64-Bit Server VM (14+36-1461) for windows-amd64 JRE (14+36-1461), built on Feb  6 2020 19:03:18 by "mach5one" with MS VC++ 15.9 (VS2017)"
  jvmArguments = "-XX:TieredStopAtLevel=1 -Xverify:none -Xdebug -Xrunjdwp:transport=dt_socket,address=0.0.0.0:5005,server=y,suspend=n -Djava.util.logging.manager=org.jboss.logmanager.LogManager"
  jvmFlags = N/A
  javaArguments = "C:\Users\cito\develop\quarkus-sample\quarkus-jfr-streaming\target\quarkus-jfr-streaming-dev.jar"
  jvmStartTime = 18:16:54.186
  pid = 9092
}