JITとコードの暖気の実体

どうも、趣味でOpenJDKのコミッタをしてます。

とあるブログを読んでいたら気になる点があったので検証してみました。

JITと暖気

Javaプロセスはアプリケーションを動かしながら必要に応じてバックグラウンドでバイトコードをネイティブコードにコンパイルします。このコンパイル時にはCPUリソースを使用します。

コンパイルにはいくつかのレベルがありますが、コンパイルされる前やレベルの低いコンパイルのコードはCPUのリソース効率が悪かったり、アプリケーションの処理中にコンパイルが実行されるとCPUリソースを奪いあったりなどが問題になります。

そのため、Java のアプリケーションで性能を気にする要件がある場合、本番に近いリクエストを投げてコードをJITコンパイルする事があります。これをよく暖気と言います。これにより本番のリクエストが来る前にコードを最適化し、よりCPUリソース効率の高いコードで本番のリクエストを迎え撃ちます。

暖気の対象は？

アプリケーションを動かすときには、以下のように 4 つの分類のコードが実装されます。

• アプリケーションコード
• フレームワークコード
• Java標準API
• JDKの内部コード

アプリケーションコードはみなさんが実際に書くコードです。これはフレームワークが公開しているAPIとJavaの標準APIを組み合わせて実装します。フレームワークコードはアプリ開発者のために公開しているAPIとフレームワークの内部となる実装があります。これらは依存関係のある他のフレームワークとJava標準APIで実装されています。Java標準APIはJavaに含まれている物です。JDKの内部コードはアプリケーション開発者が使えないJVMの内部で実行されるコードです。

暖機をする場合、これら 4 種類のコードがコンパイルされる必要があります。

検証方法

では、どれくらいリクエストを投げれば良いのでしょうか？サンプルアプリケーションを実装してみました。そのアプリケーションは 1 つの API を持ち、その中では以下のような処理をします。

• REST で別の API へリクエスト
• Database に Insert 処理

今回検証した環境は以下のとおりです。

• SpringBoot 2.3.4
• OpenJDK 14 (SpringBoot 2.3.4がサポートする最新)

そのアプリケーションを起動し API に 20,000 回リクエストを投げました。コンパイルは一般的に一番高速なサーバコンパイルされたメソッドだけを計測しています。

結果

次のグラフは1,000回毎にコンパイルされたメソッドの累計を示しています。

リクエストが 0 回というのはアプリケーションが起動してからリクエストを投げる前までです。この段階で 740 メソッドがコンパイルされています。最終的には 2,220 メソッドがコンパイルされていました。

簡単なアプリだったので 20,000 リクエスト投げれば JIT は収束するかなと思ったのですが、まだまだ足りなかったようです。

次のグラフは、1,000 リクエストごとに新規でコンパイルされたメソッド数の推移です。 リクエスト回数が 3,000 というところには 2,001 ～ 3,000 回目のリクエストを投げているときにコンパイルされたメソッドだけを数えています。これらのメソッドを、アプリケーション、フレームワーク、標準API、JDK毎に集計しています。

これを見ると、アプリケーションが起動した時点で標準APIのコードが多くコンパイルされています。これらの内訳はString、Class、ArrayList、HashMapなど、よく使われるクラスのメソッドです。

JDKの内部コードは起動時にほぼコンパイルされています。

Java標準APIは 8,000 リクエストぐらいで収束しています。これは依存関係の最も上位にある java.base モジュールにあるメソッドで使う物は大体コンパイルが終わったことを示しています。

フレームワークも同様に 8,000 リクエストぐらいで収束して居るように見えますが、そのあとも少しずつコンパイルされています。これは、フレームワークの依存関係の上位にある物が先にコンパイルされて、たまに実行されているメソッドが後まで伸びています。

アプリケーションは今回リクエスト対象となる API と JPA のエンティティ の 2 つを作りましたが、API は 1 つ目に 7,000 リクエストでコンパイルされ、JPA のエンティティのコンストラクタが 2 つ目に 19,000 リクエストでコンパイルされました。

これらの結果から、アプリケーションがコンパイルされるのは結構遅いです。これはもちろん実装にもよります。

注意していただきたいのは、API ごとに 7,000 リクエスト投げればOK。ではなく、アプリケーションでコンパイルしたいメソッドがコンパイルされたのをキチンと確認してから Rediness Probe で OK を返すようにしましょう。

どのようにやれば良いかは別のブログで近々書きます。

OpenJDK開発記：IntelliJ IDEA を使って OpenJDK を開発する (WSL編)

これは何？

OpenJDK には、リポジトリを IntelliJ IDEA で開けるように変換するスクリプトがあります。このスクリプトを使うと、IntelliJ IDEA で OpenJDK の Java の部分の開発ができるようになります。 　しかし、このスクリプトは Linux と Cygwin （たぶんMacも）では動くのですが、WSL 上では動きませんでした。

どんな実装だったのか

このスクリプトは WSL 上で実行する必要があるのですが、そもそも WSL は考慮されていませんでした。Windows で開発する場合、昔は Cygwin を使っていたため当然です。 普通の Linux としてスクリプトが実行されますが、以下の 3 つの問題がありました。

1. Java コンパイラの実行ファイル名が違う (javacとjavac.exe)
2. JDK の実行ファイルはWSLのディレクトリを含むと動かない （たぶん正確ではないが良く知らない･･･）
3. IntelliJ IDEA は Windows で実行するため Windows のパスが必要なのに WSL のパスでファイルが生成される

そのため、これらの問題を解決していきます。

バグレポートはこちらです。

[JDK-8250818] idea.sh script doesn't work on WSL 1 and 2 - Java Bug System

どう直したの？

全てが WSL の絶対パスになっていたため、以下の様な方針で修正しました。

1. Javaコンパイラのファイル名を javac と javac.exe で変更できるよう
2. スクリプト内で行われる処理は相対パスを使って全て Windows が管理する領域上で処理されるようにする
3. 成果物は全て Windows のパスになるようにする

WSL_DISTRO_NAME という環境変数がある場合は WSL 上での実行としています。その場合は、パスを相対パスにしてくれる realpath と、パスを Windows のパスにしてくれる wslpath を使って変換しています。

相対パスにしたものは以下の環境変数に格納されてるパスです。

• JAVAC_CP：クラスパス
• JAVAC_CLASSES：クラスファイルの出力先ディレクトリ
• JAVAC_SOURCE_FILE：コンパイル対象のクラス
• JAVAC_SOURCE_PATH：クラスまたはインタフェースの定義を検索するソースパス

ここまで修正すると、スクリプトは実行できるようになります。ただ、成果物内のパスは WSL のパスのままなので、成果物に含まれるパスを Windows のパスになるようにします。以下の環境変数に格納されているパスを修正しています。

• MODULE_ROOTS 内の各要素
• SPEC_DIR
• TOPLEVEL_DIR
• IDEA_OUTPUT
• JT_HOME

パッチはこちらです。

8250818: idea.sh script doesn't work on WSL 1 and 2 · openjdk/jdk@ee5dc7c · GitHub

OpenJDK開発記：JDK-8249720: Generated bytecodes of EventWriter don't be output to the logを直してみた。

これは何？

今回、パッチを書いたのはJDK-8249720のGenerated bytecodes of EventWriter don't be output to the logです。

[JDK-8249720] Generated bytecodes of EventWriter don't be output to the log - Java Bug System

VM起動引数に-Xlog:jfr+system+bytecode=traceを付けてJFRを実行すると、JFRの中で動的に作成されて使用されるEventWriterが生成されたときに、そのクラスのオペコードをログに出力する機能があります。 たまたまその機能を使ってバイトコードの変化を探してたらこのバグを発見しました。 OpenJDK の 15 からそれがデグレにより出力されなくなったため、それを修正しました。

どんな実装だったのか

原因としては、JFR のログ出力周りのオーバーヘッドを減らすという修正が入ったときに、修正ミスによってログが出力されなくなってしまいました。

-        Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.TRACE, () -> {
+        if (Logger.shouldLog(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.TRACE)) {
            ClassReader cr = new ClassReader(bytes);
            ByteArrayOutputStream baos = new ByteArrayOutputStream();
            PrintWriter w = new PrintWriter(baos);
            w.println("Bytecode:");
            cr.accept(new TraceClassVisitor(w), 0);
-            return baos.toString();
-        });
+        };

以前の実装では、最後の行のreturn baos.toString();がロガーに渡されてログを出力していました。これを消してしまったためログが出なくなっています。

8247320: JFR: Reduce logging overhead · openjdk/jdk@65c461e · GitHub

どう直したの？

単純にログを出力する行を足しただけです。それに加えて、もうデグレしないようにテストケースを追加しています。

パッチはこちら

パッチの抜粋はこちらです。

--- old/src/jdk.jfr/share/classes/jdk/jfr/internal/ASMToolkit.java   2020-07-19 21:31:04.125291400 +0900
+++ new/src/jdk.jfr/share/classes/jdk/jfr/internal/ASMToolkit.java    2020-07-19 21:31:03.955544600 +0900
@@ -155,6 +155,7 @@
             PrintWriter w = new PrintWriter(baos);
             w.println("Bytecode:");
             cr.accept(new TraceClassVisitor(w), 0);
+            Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.TRACE, baos.toString());
         };
     }
 
--- /dev/null 2020-07-19 21:20:25.577740400 +0900
+++ new/test/jdk/jdk/jfr/jvm/TestEventWriterLog.java  2020-07-19 21:31:05.847842600 +0900
@@ -0,0 +1,44 @@
+ * @test TestEventWriterLog
+ * @summary Test that log message of JFR when handle bytecodes
+ * @key jfr
+ * @requires vm.hasJFR
+ * @library /test/lib /test/jdk
+ * @run main/othervm TestEventWriterLog
+ */
+
+import jdk.test.lib.process.ProcessTools;
+import jdk.test.lib.process.OutputAnalyzer;
+
+public class TestEventWriterLog {
+    public static void main(String[] args) throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:jfr+system+bytecode=trace", "-XX:StartFlightRecording", "-version");
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldContain("extends jdk/jfr/internal/handlers/EventHandler");
+    }
+}