#chiroito ’s blog

Java を中心とした趣味の技術について

JJUG CCC 2020 Fall で「パフォーマンスのトラブルシュート入門」という内容で喋ってきました

2020年11月7日(土)に開催された JJUG CCC 2020 Fall にて「パフォーマンスのトラブルシュート入門」というタイトルで話をしてきました。

動画はこちらです。


CCC 2020 Fall A02-パフォーマンスのトラブルシュート入門

スライドはこちらになります。

speakerdeck.com

Twitterの履歴はこちらです。#jjug_ccc_a というハッシュタグの 11:00~12:00 の間が私のセッション分になります。

twitter.com

Twitter などでいただいた質問は以下になります。当日回答した質問もありますが、質問部分は公開されないと思うのでこちらに記載しておきます。類似の質問はこちらでまとめさせていただきました。

JFR Stream で、jfrダンプがしなくてもモニタリングできるようになったらいいですね。でもEventの始まりと終わりで異常処理考慮しなくちゃいけないの大変ではありませんか?

JFR Event Stream では、記録の終了後にダンプされた JFR ファイルを読み込む方法に加え、稼働中の記録を内部的に作成しているチャンクファイルから読み込む方法があります。後者の方法を使うことで JFR ファイルをダンプしないでもモニタリングできるようになっています。このチャンクファイルはデフォルトで 1 秒ごとに記録を書込んでいます。そのため JFR Event Stream で読み込む際にはイベントが記録されてから最大で 1 秒遅れるためリアルタイムには処理されないため注意してください。 イベントの書込み処理の実装では、例外処理も気にする必要があります。イベントを書込む処理は基本的には try - catch -finally で囲まれていることが多いので、その場合は finally できちんと書込むようにして下さい。参考までに私が開発している Jfr4Jdbc では JDBC のライブラリ群が投げる SQLException に加えて、非チェック例外である RuntimeException も気にするように実装しています。

JFRが使えるのはJDLK11からですか?

OpenJDK で JDK Flight Recorder が使えるのは OpenJDK 11 からです。その後、OpenJDK 8 update 262 にバックポートされました。前身である Oracle JDK の Java Flight Recorder は HotSpot では Java 7 update 40 から使用できます。Oracle JDK の JRockit の場合はそれ以前のバージョンでも使用できます。

クラウドのサーバーレス環境でもフライトレコーダーって使えるんですか?
コンテナ系のサービスだと、どう監視するのがいいんだろ……?

Java の標準機能のためどの様な環境でも使用できます。サーバレスやコンテナだから使えないという機能ではありません。ただし、ダンプファイルをどこかの永続化ストレージに格納する必要があるので、サーバレスのプロセスが停止する際にオブジェクトストレージなどへアップロードする処理が必要です。

Kubernates や OpenShift などのコンテナオーケストレーションツールを使用する場合は Red Hat から JFR のオペレータが出ているためこちらをご利用下さい。コンテナオーケストレーションツールを使用していない場合は、永続ストレージに JFR や収集した情報を記録する様にして下さい。

この辺の内容のまとまった情報のあるおすすめの書籍などあれば

概要や使い方を紹介した資料はいくつかありますが、JFR の全体や内部構造などのまとまった資料はありません。様々なイベントで Oracle 社のエンジニアが発表している資料が良いと思います。これらの動画は Youtube などで公開されています。

JFR の利用が原因でパフォーマンスが劣化するといったことは考えられますでしょうか?
フライトレコーダーって本番で動きっぱなしにしてもリソース的に大丈夫なものなんでしょうか?(環境次第な気もしますが)
パフォーマンス計測をし続けることにどの程度負荷かかるんだろな

JFR のイベントを書込む処理を記述していても、JFR が動いていなければパフォーマンスは劣化しません。これはイベントの書込み処理などイベントに関わるコードが JIT コンパイラによって取り除かれるように実装されているためです。 JFR を動かす場合には default と profile という標準設定群があります。一般的な使用方法では default で良く、さらに詳細に分析したい場合には profile を使用します。default では一般的な使用方法では 1~2% の負荷になります。この負荷はイベントを書込む頻度などにもよります。profile ではもう少し大きな負荷になるため、本番環境での使用は良く確認してから試しましょう。

JFRは常に有効にしておくものでしょうか?それとも何か発生したら調査のために有効にするものでしょうか?

JFR は常に有効にしておくことをオススメします。JFR は内部的に循環バッファを使用しています。そのため、新しいイベントが書込まれると過去の分はどんどん削除されていきます。そのため、問題が起きたときにダンプすれば過去に遡ってバッファに残っている分の情報が入手できます。また、正常時のダンプも忘れないように取得しておきましょう。

FR カスタム Event を備えたフレームワークはどんなものがあるのでしょうか

Oracle 社の Oracle WebLogic Server (WLS) と私が開発している Jfr4Jdbc があります。WLS では Java EE に関するイベントやそれに付随するシステムのイベントを書込んでくれます。これは、特別な処理は不要で WAR ファイルや EAR ファイルをデプロイするだけで各種イベントが記録されます。 また、Jfr4Jdbc は JDBC に関するイベントを書込みます。これらのイベントにはコネクションの接続や切断、クエリの実行、コミット、ロールバックといった JDBC の API を呼び出すだけで記録されるようになります。また、コネクションプールの使用数や割り当て待ち数といった情報も記録されます。これらの情報を取得するために必要な事はデータソースをラップするか、JDBC の 接続 URL に jfr: を追加するだけです。

JFRで記録できるイベントの一覧はどこかで確認できるんでしょうか?

JFR で記録できるイベントは日々追加されています。一覧が記録されている情報はありません。一覧を確認するには、JFR を遊行した Java プロセスを起動し、JDK Mission Control で接続して記録を開始し始めるときに一覧を出せます。また、一度 JFR ファイルをダンプし、その情報に含まれる[環境]-[記録]から確認できます。

JFRが使えないレガシー環境ではどれがおすすめですか?

今回の講演でも紹介しましたが、JFR が使えないレガシー環境では、OS、JVM、アプリケーションできちんとログやメトリクス、リソースといった情報を取るようにしなければなりません。そのためには JVM に標準で含まれているログ機能や JMX/MBean といった物を有効活用するようにします。また、アプリケーションサーバ(フレームワーク含む)がきちんと情報を得られる物を選択しましょう。

OS情報の計測によく使うツールやノウハウがありましたら教えてください。

Linux の場合は iostat/mpstat/sar など OS が使用するリソースの情報を収集系のツールがあります。これらのツールを適切に使うことがオススメです。CPU等の情報は、まとめて取るのではなく論理CPUやディスクなどを個別に収集するようにオプションを設定しましょう。時刻情報が付かないツールも多いので、収集時は時刻情報も含まれるよう工夫すると良いです。 以下がサンプルです(最近動かしてないので動くかは不明ですが・・・)

RESULT_CASE=sample
DATE_FORMAT="%Y %m %d %H %M %S"
INTERVAL_SEC=10
TIMES=1080
mpstat -P ALL ${INTERVAL_SEC} ${TIMES} | awk -v df="${DATE_FORMAT}" '(NR==3 || (NR>3 && /^[0-9].+[0-9]$/)){print strftime(df), $0}' >> ${RESULT_CASE}_mpstat_`date +\%Y\%m\%d`.log &
vmstat -n -S m ${INTERVAL_SEC} ${TIMES} | awk -v df="${DATE_FORMAT}" '(NR>=2){print strftime(df), $0}' >> ${RESULT_CASE}_vmstat_`date +\%Y\%m\%d`.log &
iostat -mx -d -p ALL ${INTERVAL_SEC} ${TIMES} | awk -v df="${DATE_FORMAT}" '(NR==3 || (NR>3 && /.+[0-9]$/)){print strftime(df), $0}' >> ${RESULT_CASE}_iostat_`date +\%Y\%m\%d`.log &

The changes of JVM Specifications - JVM仕様の変更点

Java 8 以降の Java 仮想マシンの仕様のうち、各バージョンの差分を洗い出しました。the が that になったり、item が entry になる変更で、文の意味が変らない変更は除いています。

I listed the differences between each version of the Java Virtual Machine specification for Java 8 and later. I excluded changes that do not change the meaning of the statement, such as the changing of "the" to "that" or the changing of "item" to "entry".

元の情報はこちらです。

The original information is here.

docs.oracle.com

The changes of "The Java Virtual Machine Specification Java SE 15 Edition"

The changes of "The Java Virtual Machine Specification Java SE 14 Edition"

Nothing

The changes of "The Java Virtual Machine Specification Java SE 13 Edition"

The changes of "The Java Virtual Machine Specification Java SE 12 Edition"

The changes of "The Java Virtual Machine Specification Java SE 11 Edition"

The changes of "The Java Virtual Machine Specification Java SE 10 Edition"

The changes of "The Java Virtual Machine Specification Java SE 9 Edition"

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

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

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

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

全体の概要

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

f:id:chiroito:20200920195019p:plain

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

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

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

f:id:chiroito:20200920195315p:plain

動いているスレッドの内、上の 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リクエストをもう少し細かく見てみましょう。

f:id:chiroito:20200920191028p:plain

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

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

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

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

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

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

2 回目移行のリクエスト

次に、2回目以降のリクエストもまとめてみてみましょう。2回目~5回目のHTTPリクエストの処理にズームインします。 f:id:chiroito:20200920205014p:plain

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

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

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

1回目と2回目以降の差

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

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

さらに

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

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

f:id:chiroito:20200920193244p:plain

この図は縦軸が 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 リソースを奪い合うため、同様に処理時間が延びます。

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