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）です。
このプログラムの処理を監視してみます。

import java.util.regex.Matcher;
import java.util.regex.Pattern;

public class CopyrightAppender {
    private static final String COPYRIGHT_STRING = "<br/>(c) 2017 Synergy Marketing, Inc.";
    private static final Pattern BODY_END_TAG_PATTERN = Pattern.compile("</body>", Pattern.CASE_INSENSITIVE);

    /**
     * body タグ内の最後にコピーライト文字列を追加して返す
     * @param HTML 文字列
     * @return コピーライトを追加した HTML 文字列
     */
    public String append(String html) {
        if (html == null) {
            throw new IllegalArgumentException("html is required.");
        }
        Matcher m = BODY_END_TAG_PATTERN.matcher(html);
        if (m.find()) {
            StringBuffer sb = new StringBuffer();
            m.appendReplacement(sb, Matcher.quoteReplacement(COPYRIGHT_STRING + m.group(0)));
            m.appendTail(sb);
            return sb.toString();
        }
        return html; //</body> タグがみつからない場合は単純に渡された文字列を返すだけにします
    }
}

import java.util.regex.Matcher;

import java.util.regex.Pattern;

public class CopyrightAppender {

private static final Pattern BODY_END_TAG_PATTERN = Pattern.compile("</body>", Pattern.CASE_INSENSITIVE);

/**

* body タグ内の最後にコピーライト文字列を追加して返す

* @param HTML 文字列

* @return コピーライトを追加した HTML 文字列

public String append(String html) {

if (html == null) {

throw new IllegalArgumentException("html is required.");

}

Matcher m = BODY_END_TAG_PATTERN.matcher(html);

if (m.find()) {

StringBuffer sb = new StringBuffer();

m.appendReplacement(sb, Matcher.quoteReplacement(COPYRIGHT_STRING + m.group(0)));

m.appendTail(sb);

return sb.toString();

}

return html; //</body> タグがみつからない場合は単純に渡された文字列を返すだけにします

}

public class VisualvmTest {

    public static void main(String[] args) {
        sleep(5000);

        final String html = createHtml();
        CopyrightAppender copyrightAppender = new CopyrightAppender();
        for (int i = 0; i < 10000; i++) {
            copyrightAppender.append(html); //負荷状況がわかりやすいように処理を繰り返す
        }

        sleep(2000); //サンプラの更新を待つ
    }

    /**
     * 負荷がかかるように非常に長い HTML を作成する
     * @return HTML 文字列
     */
    private static String createHtml() {
        StringBuilder sb = new StringBuilder();
        sb.append("<html>");
        sb.append("<body>");
        for (int i = 0; i < 100000; i++) {
            sb.append("a");
        }
        sb.append("</body>");
        sb.append("</html>");
        return sb.toString();
    }

    private static void sleep(long ms) {
        try {
            Thread.sleep(ms);
        } catch (InterruptedException e) {
            //本質から離れるため省略します
        }
    }
}

public class VisualvmTest {

public static void main(String[] args) {

sleep(5000);

final String html = createHtml();

CopyrightAppender copyrightAppender = new CopyrightAppender();

for (int i = 0; i < 10000; i++) {

copyrightAppender.append(html); //負荷状況がわかりやすいように処理を繰り返す

}

sleep(2000); //サンプラの更新を待つ

}

/**

* 負荷がかかるように非常に長い HTML を作成する

* @return HTML 文字列

private static String createHtml() {

StringBuilder sb = new StringBuilder();

sb.append("<html>");

sb.append("<body>");

for (int i = 0; i < 100000; i++) {

sb.append("a");

}

sb.append("</body>");

sb.append("</html>");

return sb.toString();

}

private static void sleep(long ms) {

try {

Thread.sleep(ms);

} catch (InterruptedException e) {

//本質から離れるため省略します

}

Java VisualVM を起動する

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

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

$ /usr/bin/jvisualvm

1	$ /usr/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> は、先頭から探索するより末尾から探索したほうが一般的には早く見つかりそうです。

import java.util.regex.Matcher;
import java.util.regex.Pattern;

//変更点1: StringUtils をインポートする
import org.apache.commons.lang3.StringUtils;

public class CopyrightAppender {
    private static final String COPYRIGHT_STRING = "<br/>(c) 2017 Synergy Marketing, Inc.";
    private static final Pattern BODY_END_TAG_PATTERN = Pattern.compile("</body>", Pattern.CASE_INSENSITIVE);

    /**
     * body タグ内の最後にコピーライト文字列を追加して返す
     * @param HTML 文字列
     * @return html コピーライトを追加した HTML 文字列
     */
    public String append(String html) {
        if (html == null) {
            throw new IllegalArgumentException("html is required.");
        }
        //変更点2: </body> の開始位置を末尾から探索する
        int bodyEndTagStartIndex = StringUtils.lastIndexOfIgnoreCase(html, "</body>");
        Matcher m = BODY_END_TAG_PATTERN.matcher(html);
        //変更点3: </body> が見つかった場合は m.find() の開始位置を </body> の開始位置で指定する
        if (bodyEndTagStartIndex >= 0 && m.find(bodyEndTagStartIndex)) {
            StringBuffer sb = new StringBuffer();
            m.appendReplacement(sb, Matcher.quoteReplacement(COPYRIGHT_STRING + m.group(0)));
            m.appendTail(sb);
            return sb.toString();
        }
        return html; //</body> タグがみつからない場合は単純に渡された文字列を返すだけにします
    }
}

import java.util.regex.Matcher;

import java.util.regex.Pattern;

//変更点1: StringUtils をインポートする

import org.apache.commons.lang3.StringUtils;

public class CopyrightAppender {

private static final Pattern BODY_END_TAG_PATTERN = Pattern.compile("</body>", Pattern.CASE_INSENSITIVE);

/**

* body タグ内の最後にコピーライト文字列を追加して返す

* @param HTML 文字列

* @return html コピーライトを追加した HTML 文字列

public String append(String html) {

if (html == null) {

throw new IllegalArgumentException("html is required.");

}

//変更点2: </body> の開始位置を末尾から探索する

int bodyEndTagStartIndex = StringUtils.lastIndexOfIgnoreCase(html, "</body>");

Matcher m = BODY_END_TAG_PATTERN.matcher(html);

//変更点3: </body> が見つかった場合は m.find() の開始位置を </body> の開始位置で指定する

if (bodyEndTagStartIndex >= 0 && m.find(bodyEndTagStartIndex)) {

StringBuffer sb = new StringBuffer();

m.appendReplacement(sb, Matcher.quoteReplacement(COPYRIGHT_STRING + m.group(0)));

m.appendTail(sb);

return sb.toString();

}

return html; //</body> タグがみつからない場合は単純に渡された文字列を返すだけにします

}

修正後の監視結果です。

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

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

最後に

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