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 リソースを奪い合うため、同様に処理時間が延びます。
妨害なくアプリケーションを適切に処理するには、アプリケーションやそのランタイムが使用するリソースを把握して、インフラのリソースを適切に与える必要があります。