最初の1リクエスト目で何をしているのか？

1 リクエスト目がもの凄く遅くなると言う話を聞いたので分析してみました。

今回は、SpringBootのアプリケーションを OpenJDK 14 で動かしています。そのアプリケーションへ 5 回のリクエストを投げてみて処理のされ具合にどんな違いがあるのかを確認してみます。

分析するツールとして、今回は OpenJDK 8 から使用できる JDK Flight Recorder を使用してみます。このツールは Java 言語を書く開発者には当たり前のように使われているツールです。今回は、アプリケーションを起動して、処理を投げて、分析が完了するまでおよそ 40 秒ぐらいで解析できました。Java言語を書く開発者なら誰でもこれぐらいでできます。ぜひツールの使い方を覚えましょう。

全体の概要

まず始めにJFRを起動して記録を開始します。今回は、検証環境なのでOpenJDK に標準で含まれる設定では無く全てのイベントを記録するように設定を変更して起動しました。その後、5 回 HTTP リクエストをして、記録をダンプして JDK Mission Control を使って開きます。JMC の画面では、リクエストを処理している前後も含めて、Javaプロセス内のスレッドは以下のように表示されます。

横軸が時間軸になります、左側が古く、右側に時間が流れていきます。縦に積まれているものはそれぞれスレッドを表します。緑色はその時点に特に何もイベントが無いことを表し、白の期間はスレッドが存在していません。

Javaのプロセス内には様々なスレッドがあります。この図を見ると、SpringBootが使用するスレッドプールであるhttp-nio-8080-exec-nというスレッドが 10 個あることがわかります。そのため、処理をする前には、処理をするスレッドプールの準備ができていることも分かります。

この図では不要なスレッドも多くて分かり難いので、この中から、処理をしているスレッドだけを抜き出してみます。

動いているスレッドの内、上の 4 つはコンパイルスレッドで、次にSpringBoot の Acceptor があり、下の 5 つが SpringBoot のスレッドプールです。コンパイルスレッドとは、JIT コンパイラがコンパイルをする時に使用するスレッドです。このスレッドは必要に応じて増減します。この図だと、2つのスレッドが必要に応じて生成され、その後不要になったため削除されているのが分かります。

この中で、黄色はJIT コンパイルのイベント、紫はクラスロードのイベント、黄緑はHTTPリクエストのイベント、赤は例外生成のイベントを表します。それぞれのイベントでは該当する処理が処理されています。

全体の流れを見てみましょう。

まず最初に、Acceptor がリクエストを受付けるとその後の処理に必要なクラスが見つからずClassNotFoundExceptionを生成（赤色）してからクラスロード（紫色）が行われます。その後 JIT コンパイル（黄色）が行われています。これは起動時に使われてAcceptorでも使われるような Java の標準APIがたくさんコンパイルされています。

その後、HTTPの処理をするhttp-nio-8080-exec-nというスレッドに処理が渡されて処理を開始します。ですが、HTTPリクエストを処理するのに必要なクラスがまたもや見つからず、こちらでもClassNotFoundExceptionを生成（赤色）してからクラスがたくさんロード（紫色）されます。HTTPリクエストが処理を開始（黄緑色）してからもそれは変わらず続きます。また、HTTPリクエストの処理は1回目と2回目以降ではこの長さが大きく異なっています。

1 回目のリクエスト

1回目のHTTPリクエストをもう少し細かく見てみましょう。

ここではスレッドの中が 4 つに分かれています。上から以下のようになっています。

• Java の待機イベント
• HTTPリクエスト
• JDBC
• それ以外の処理

Java の待機イベントでは、ここにイベントがある間は、アプリケーションは処理を中断しています。そのため、ここはイベントをできるだけ少なく・短くする必要があります。今回は先ほどのとおりクラスロード（紫色）が大量に実行されています。この間でおよそ740クラスをロードしています。ロードされるクラスの多くはSpringBootのクラスです。

HTTPリクエストは長い黄緑があります。これはHTTPリクエストを処理している期間です。この間に 1 回目のリクエストを処理しています。

JDBC は、JDBCに関わる処理をしています。これはJDBCコネクションの取得、SQLの実行、JDBCコネクションのクローズなどJDBCに関するさまざまな情報を記録しています。これを見る限りはJDBCにはあまり時間を使っていません。コネクションプールの準備が出ていないという意見もありましたが、その場合はコネクション取得時間が延びます。今回の例ではそのような事実はありません。

最後のそれ以外の処理は、赤いイベントがあります。これは例外が発生したことを表します。この例の多くはSpringBootがClassNotFoundExceptionをスローしてます。

2 回目移行のリクエスト

次に、2回目以降のリクエストもまとめてみてみましょう。2回目～5回目のHTTPリクエストの処理にズームインします。

こちらは「Java の待機イベント」や「それ以外の処理」が何も無かったため表示されていません。そのため、スレッドが以下のように分割されています。

• HTTPリクエストの処理
• JDBC の処理

JDBC の処理時間も特に長くありません。そのため、アプリケーションが何も邪魔されずにきちんと処理出来ていることが分かります。

1回目と2回目以降の差

1 回目のHTTPリクエストの処理ではSpringBootが大量のClassNotFoundExceptionをスローし、それによってクラスロードされていました。このクラスロードによってアプリケーションが中断されています。この結果、アプリケーションの処理時間が延びています。2 回目以降ではそれがなかったため、スムーズにアプリケーションが処理出来ているのが分かります。

これで、1 回目のリクエストとそれ以降のリクエストでなぜ処理時間が延びてしまったのかが分かりました。

さらに

実はこの処理は、環境によっては更なる遅延を発生させます。

この期間の CPU 使用率を見てみましょう。

この図は縦軸が CPU 使用率で、横軸が時間軸です。縦軸の一番上が 100% です。オレンジはこのマシン全体のCPU使用率です。オレンジが一番上に達してないので CPU はマシンとしてはまだ余裕があります。紫色がこのプロセスのCPU使用率です。このCPUは 37% 程度使用しています。このマシンは 8 コアですので、3/8 = 0.375 となりおよそ 3 コアの CPU を使っていることになります。

最近のプロセスはクラウドやコンテナ技術上で動かします。これらの中では非常に小さなCPUリソースで動かすことも多いでしょう。そのような環境では、バックグランドで実行され処理によってCPUリソースが奪われ、アプリケーションの実行時間が延びることあります。

Java はこの様なことを避けるためコンテナやクラウドに与えられたリソースを自動で検知して、バックグラウンドで使用するリソース量を自動で調整する機能があります。この機能は OpenJDK 10 以降でどんどん機能が拡充しています。そのため、Java を使って開発して、OpenJDK を使って動かす場合にはできるだけ新しいバージョンを使うことをお奨めします。

また、この問題はバックグラウンドに問題がなくてもアプリケーション側の設定でも発生します。今回は、5 回のリクエストを実行しました。これらは 5 つのスレッドでそれぞれ実行されました。逐次で実行したためリソースの奪い合いは発生しません。ですが、1 コアしかないのに CPU リソースを使う処理が 2 スレッドで動作すると CPU リソースを奪い合うため、同様に処理時間が延びます。

妨害なくアプリケーションを適切に処理するには、アプリケーションやそのランタイムが使用するリソースを把握して、インフラのリソースを適切に与える必要があります。

Rediness Probeでアプリケーションが十分にJITされたことを検知する

どうも、趣味でOpenJDKのコミッタをやってます。JVMの専門家ではないです。

今回はJITコンパイルによる暖気が十分に行われてから処理を受けられるようにする方法を紹介します。

今回の実装は Oracle の有償機能から OpenJDK へ寄贈され OpenJDK 11 に追加された JDK Flight Recorder（JFR）と OpenJDK 14 に追加された JFR Event Streaming を使用します。

JITコンパイルイベント

OpenJDK では、JITコンパイラがコンパイルした情報を内部的にイベントとして記録しています。今回はこのイベントを使用していきます。このイベントのデータ形式は以下になります。

@Name("jdk.Compilation")
@Category({"Java Virtual Machine", "Compiler"})
@Label("Compilation")
class Compilation extends jdk.jfr.Event {
  @Label("Start Time")
  @Timestamp("TICKS")
  long startTime;

  @Label("Duration")
  @Timespan("TICKS")
  long duration;

  @Label("Event Thread")
  @Description("Thread in which event was committed in")
  Thread eventThread;

  @Unsigned
  @CompileId
  @Label("Compilation Identifier")
  int compileId;

  @Label("Compiler")
  String compiler;

  @Label("Method")
  Method method;

  @Unsigned
  @Label("Compilation Level")
  short compileLevel;

  @Label("Succeeded")
  boolean succeded;

  @Label("On Stack Replacement")
  boolean isOsr;

  @Unsigned
  @DataAmount("BYTES")
  @Label("Compiled Code Size")
  long codeSize;

  @Unsigned
  @DataAmount("BYTES")
  @Label("Inlined Code Size")
  long inlinedBytes;
}

イベントの名前はjdk.Compilationです。このイベントは、コンパイルされた時間、コンパイルにかかった期間、コンパイルされたメソッド、コンパイルのレベルなどを記録します。

このイベントは実際に以下のような内容が記録されます。

jdk.Compilation {
  startTime = 14:52:33.762
  duration = 1.029 ms
  compileId = 4710
  compiler = "c1"
  method = sun.rmi.transport.ConnectionInputStream.done(Connection)
  compileLevel = 3
  succeded = true
  isOsr = false
  codeSize = 12.1 kB
  inlinedBytes = 266 bytes
  eventThread = "C1 CompilerThread0" (javaThreadId = 10)
}

JITのウォーミングアップの監視の実装

JIT コンパイルは Java プロセスの起動時から開始されます。そのため、JIT コンパイルをより正確に監視するには Java アプリケーションが起動する前から監視する必要があります。監視は Java の Pre Main で開始して、ウォーミングアップの状態は MBean で持ちます。これらの状態を SpringBoot の中から参照していきます。

注：最初は SpringBoot の中で全てやっていましたが、誤解が広まると嫌なので書き換えました。

JIT コンパイルによるウォーミングアップの状態は以下の MXBean に持たせます。

public interface JitWarmUpMXBean {
    boolean isWarmedUp();
}

実装は以下になります。

public class JitWarmUpMXBeanImpl implements JitWarmUpMXBean{

    private volatile boolean isWarmedUp = false;

    public void warmedUp() {
        this.isWarmedUp = true;
    }

    @Override
    public boolean isWarmedUp() {
        return this.isWarmedUp;
    }
}

状態は isWarmedUp フィールドに持ちます。値がfalseならウォーミングアップが十分ではなく、trueなら期待するレベルでウォーミングアップが完了しています。

次に、暖気による Readiness Probe を確認できるようにしましょう。まずは、暖気が終わってなければDOWNを、暖気が終わっていればUPを返す実装を作ります。これはSpringのお作法に則り、HealthIndicatorを実装します。HealthIndicatorは以下のとおりです。

import org.springframework.boot.actuate.health.Health;
import org.springframework.boot.actuate.health.HealthIndicator;
import org.springframework.stereotype.Component;

import javax.management.*;
import java.lang.management.ManagementFactory;

@Component
public class JitWarmUpHealthIndicator implements HealthIndicator {

    private JitWarmUpMXBean jitWarmUpMXBean;

    public JitWarmUpHealthIndicator() {
        try {
            MBeanServer mbs = ManagementFactory.getPlatformMBeanServer();
            ObjectName mxbeanName = new ObjectName("com.example:type=JitWarmUp");
            this.jitWarmUpMXBean = JMX.newMBeanProxy(mbs, mxbeanName, JitWarmUpMXBean.class);
        } catch (MalformedObjectNameException e) {
            e.printStackTrace();
        }
    }

    @Override
    public Health health() {
        return jitWarmUpMXBean != null && jitWarmUpMXBean.isWarmedUp() ? Health.up().build() : Health.down().build();

    }
}

このクラスは暖気が終わったかどうかを保持するJitWarmUpMXBeanへのプロキシを持ちます。このMBeanはisWarmedUpメソッドを持ち、このメソッドは起動直後は暖気が終わっていないのでfalseを返しますが、暖気が終わるとtrueを返します。health()メソッドは、JitWarmUpMXBeanクラスのisWarmedUpメソッドを見て、暖気が終わっていればUPを、終わっていなければDOWNを返します。

次は、JITコンパイルされたメソッドの数を数える処理です。ここが本質だと思います。今回は、JITコンパイラに一定個数のメソッドがサーバコンパイル（Level 4）されたら暖気完了とします。

注意：先ほどのコンパイルイベントのデータ構造にメソッド名などもありました。それを使えば特定のメソッドがコンパイルされたら暖気を完了するという実装もできます。ですが、サーバコンパイルされるかどうかはJITの気分次第であり、インライン化されたりサーバコンパイルされないと言った可能性もあるのでお奨めしません。実際、何度か検証しましたが、狙ったメソッドがサーバコンパイルされないことが多々ありました。

JITコンパイラの監視は、Pre Main で実行します。JITコンパイルの情報は JDK Flight Recorder に記録され、イベントの数の集計処理はその記録から JFR Event Streaming で処理します。

public class JitWarmUpAgent {

    private static final int threshold = 2000;
    private static final int expectCompileLevel = 4;
    private static volatile boolean isClosed = false;

    private final static void start() {

        try {
            MBeanServer mbs = ManagementFactory.getPlatformMBeanServer();
            ObjectName mxbeanName = new ObjectName("com.example:type=JitWarmUp");
            JitWarmUpMXBeanImpl mxbean = new JitWarmUpMXBeanImpl();
            mbs.registerMBean(mxbean, mxbeanName);

            RecordingStream es = new RecordingStream();
            es.enable("jdk.Compilation").withThreshold(Duration.ZERO);

            AtomicInteger compiledMethodNum = new AtomicInteger(0);

            Consumer<RecordedEvent> compilation = e -> {
                if (e.getShort("compileLevel") >= expectCompileLevel) {
                    int methodNum = compiledMethodNum.incrementAndGet();
                    if (methodNum >= threshold) {
                        if (!isClosed) {
                            synchronized (es) {
                                if (!isClosed) {
                                    System.out.println("閾値を超える数の " + methodNum + " メソッドがコンパイルされました");
                                    mxbean.warmedUp();
                                    es.close();
                                    isClosed = true;
                                }
                            }
                        }
                    }
                }
            };
            es.onEvent("jdk.Compilation", compilation);

            es.startAsync();

            Runtime.getRuntime().addShutdownHook(new Thread("JitWarmUpShutdownHook") {
                public void run() {
                    if (!isClosed) {
                        es.close();
                    }
                }
            });
        } catch (MalformedObjectNameException e) {
            e.printStackTrace();
        } catch (NotCompliantMBeanException e) {
            e.printStackTrace();
        } catch (InstanceAlreadyExistsException e) {
            e.printStackTrace();
        } catch (MBeanRegistrationException e) {
            e.printStackTrace();
        }

    }

    // Used when loading agent from command line
    public static void premain(String agentArgs, Instrumentation inst) {
        start();
    }

    // Used when loading agent during runtime.
    public static void agentmain(String agentArgs, Instrumentation inst) {
        start();
    }
}

このクラスにはパラメータとして、何個のメソッドをコンパイルすれば暖気終了と見なすのかを表す閾値であるthresholdフィールドと、期待するコンパイルレベルを示すexpectCompileLevelを持ちます。

監視開始の処理はstart()メソッドで、監視の終了はウォーミングアップが済んだときとシャットダウンフックで行います。

起動時の処理ではまず、JFR Event Streaming の記録を開始します。この時、コンパイルのイベントを有効にします。通常、コンパイルのイベントはコンパイルに 100ms 以上かかったものだけが記録されます。しかし、それではコンパイル時間が長いイベントだけが記録されるだけであり、コンパイルされた全てのメソッド数は記録できません。そのため、全てのイベントを記録できるように0 msを指定します。これらの設定を指定して、記録を開始します。

コンパイルされたメソッド数を保持する変数としてAtomicIntegerクラスのcompiledMethodNumを作成します。

次に、コンパイルのイベントで処理されるコンシューマを作成します。この中では、来たコンパイルのイベントが期待するコンパイルレベルかを確認します。期待するコンパイルレベルだった場合には、コンパイルされたメソッドとして記録しています。同じメソッドが何度もコンパイルされる可能性もありますが、今回の実装では無視しています。メソッドの名前などを使えばより正しく記録できるようになるでしょう。その後、コンパイルされたメソッド数が期待する閾値を超えると標準出力へログを出力して、HealthIndicatorを暖気済に変更して、処理を停止させます。

最後にこの処理をコンパイルのイベントで処理されるように設定して、非同期で処理を開始します。

これらの処理によって、起動後に暖気用のリクエストを受けてJITコンパイルされたメソッドが増えると、いつしかその閾値を超えてJitWarmUpMXBean の状態が true になります。そうすると、HealthIndicatorのステータスがUPを返すようになり、そのアプリケーションが本番のリクエストを受けられるようになります。

実際に確認してみましょう。HealthIndicatorの様子が分かるようにapplication.propertiesに以下を追加しています。

management.endpoint.health.show-details=always

まずは起動直後です。jitWarmUpのステータスがDOWNなため、全体のステータスもDOWNになっています。

次に、暖気処理後です。jitWarmUpのステータスがUPになり、全体のステータスもUPになっています。

いかがでしたでしょうか。

この方法を使えば、JITコンパイルが十分に行われてからJavaプロセスが処理を受けられるようになりました。もし、性能に関する要件が厳しく、JITコンパイルが十分に行わないといけない場合にはこの様な方法を使用してみて下さい。そういった要件が無い場合は、使用する必要はありません。

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 を返すようにしましょう。

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