Java VisualVM でパフォーマンスのボトルネックを突き止める

これは TECHSCORE Advent Calendar 2017 の 11 日目の記事です。

以前、CPU 使用率がボトルネックになっている処理を改善するために、Java VisualVM を利用して高負荷な処理を見つけ出しました。
非常に便利なツールなので、サンプルプログラムを用いて簡単に Java VisualVM の使い方を書いてみます。
ここでのゴールは、CPU 使用率の高いメソッドを見つけることです。

Java VisualVM とは

公式サイトより。

Java VisualVMは、指定されたJava仮想マシン(JVM)でJavaテクノロジベースのアプリケーション(Javaアプリケーション)が実行されているときに、そのJavaアプリケーションに関する詳細な情報を提供する直感的なグラフィカル・ユーザー・インタフェースです。

アプリケーションのメモリ使用率・CPU使用率・スレッドの稼働状況など、GUI で表示してくれるツールです。

サンプルプログラム

HTML の最後にコピーライトを追加する、という簡単なサンプルプログラムを用意しました(テンプレート使えとかいうツッコミは勘弁してください)。
コピーライトを追加するメソッドを持つクラス(CopyrightAppender.java)と、実行クラス(VisualvmTest.java)です。
このプログラムの処理を監視してみます。

Java VisualVM を起動する

Oracle JDK をインストールしている場合は、 Java VisualVM が付属しています。
OpenJDK の場合は付属していませんので、下記 URL から VisualVM がダウンロードできます。
https://visualvm.github.io/

この記事では Oracle JDK 付属の Java VisualVM を利用しますが、VisualVM でも同じように動きます。
JDK をインストールしたディレクトリの bin 以下に実行ファイル jvisualvm がありますので、起動します。

実際に可視化してみる

サンプルプログラムを起動して jvisualvm を見てみます。すると、左側の「アプリケーション」にプロセスが表示されますのでダブルクリックで開きます。
(アプリケーションが終了するとプロセスが消えるため、試される場合はデバッグ接続して停止するなどしてください)

「概要」「監視」「スレッド」「サンプラ」「プロファイラ」と並んでいます。
メソッド毎の CPU 処理時間を監視できるものは「サンプラ」と「プロファイラ」で、大まかな違いは以下です。

  • プロファイラ・・・プログラムのバイトコードを書き換え処理時間を計測します。正確な情報を取得できますが、負荷が高く実行中のプログラムが壊れてしまう可能性があります。
  • サンプラ・・・スレッドダンプを断続的に出力して処理時間を計測します。あまり負荷がかからない上にこちらでも十分正確のようで、プログラムのバイトコードを変えずに動いてくれます。

実際に業務でプロファイラを使用したときは負荷が高かった上にプログラムが壊れてしまいました。
コスパの優れているサンプラを使います。

「CPU」を選択し、先ほどのプログラムを起動して監視してみます。

私の環境では上図の結果になりました。

VisualvmTest.sleep() の「セルフ・タイム(CPU)」は 0.000 ms で、「セルフ・タイム」が 5.005 ms です。
「セルフ・タイム」は、メソッドの処理時間を表し、「セルフ・タイム(CPU)」は、実際に CPU を使用している時間を表しています。
VisualvmTest.sleep() は CPU を使用せずにブロックされて待っているだけの処理ですので、このような結果になっています。
(最終行の sleep(2000) が反映されていないのは、結果が反映される前にアプリケーションが終了したためです)

一方、CopyrightAppender.append() は、「セルフ・タイム」=「セルフ・タイム(CPU)」になっており、CPU をフルに使った処理になっていることがわかります。

今回のサンプルプログラムは非常に単純なケースですが、GUI でメソッド毎に処理時間を表示してくれるため、パフォーマンスのボトルネックがひと目でわかります。

(実際に業務で改善したときのキャプチャが残っていたので掲載します。実際はこの図のように多くのメソッドが実行されると思いますが、どの処理に時間がかかっているかを GUI で直感的に把握しやすいです)

サンプルプログラムを改善する

大まかな使い方がわかったところで、先ほどのサンプルコードを修正して改善結果を見てみます。

</body> は、先頭から探索するより末尾から探索したほうが一般的には早く見つかりそうです。

修正後の監視結果です。

改善前:11,093 ms
改善後:1,798 ms
(1,697 ms(CopyrightAppender.append())+ 101 ms(StringUtils.lastIndexOfIgnoreCase())

16% の処理時間に改善できました!

最後に

例えば DB アクセスで待たされている場合は、JDBC ドライバのメソッドの処理時間が表示されるので、プログラムでなく SQL を修正する、といった判断ができます。
また、この記事では割愛しますが Java VisualVM はリモート接続して使うこともできます。
GUI で表示してくれると、全体が把握しやすくとてもわかりやすいですね。

Comments are closed, but you can leave a trackback: Trackback URL.