A.6.4 アプリケーションの性能ボトルネックを調べる

ここでは、次のように記述したメソッドを持つプログラムを例にして、アプリケーションの性能ボトルネックを調べる方法について説明します。

  private static String doIt(final int nLoops) {
    String ret = "";
    String s = "Test";
    
    for (int i = 0; i < nLoops; i++) {
      ret += s;
    }
    
    return ret;
  }

図 6 性能ボトルネックが存在するメソッドの例

メソッドdoIt()は、Stringオブジェクトに文字列”Test”を連結します。連結する回数は、メソッドの引数で指定します。

例えば、20万回の連結を実行するのに、300秒以上かかるとします（図7は、プログラムでメソッドdoIt()の実行時間を表示した例です。）

今回は、このプログラムの性能ボトルネックを調べていきます。

339328 milliseconds

図 7 性能ボトルネックが存在するメソッドの実行時間の例

アプリケーションの性能に関する情報を採集するには、Java監視機能を使用します。
まず、Java監視機能の[概要]タブを開き、アプリケーションのCPU使用状況を確認してください。
CPU使用率が高い場合は、アプリケーションが、CPUに負荷がかかる処理を実行している可能性があります。

CPU使用率が低い場合は、ロックの取得待ちや、I/O待ちなどによって、アプリケーションがスローダウンしている可能性が考えられます。「A.6.6 ハングアップやスローダウンの原因を調べる」を参照してください。

図 8 Java監視機能による、CPU使用率の確認

このアプリケーションでは、CPU使用率が50%前後で推移しています。今回アプリケーションを実行したマシンのCPUは、デュアルコアでした。つまり、1個のコアを常に使い続けていることが分かります。すなわち、CPUに負荷がかかるアプリケーションだと言えます。

そこで、アプリケーションが頻繁に実行しているメソッドを特定します。[メソッドサンプリング]タブを開いて、[開始]ボタンを押します。ここでは、サンプリング間隔を、デフォルト（50ミリ秒）のままとしています。

図 9 Java監視機能による、メソッドサンプリングの開始方法

ある程度の時間を置いて、[終了]ボタンを押します。次の画面は、サンプリングの結果です。

図 10 Java監視機能による、メソッドサンプリングの結果

サンプリングの結果は、一番下に出力されています。ここで上位に表示されているものは、測定期間中にサンプリングされた回数が多いメソッドを示しています。

図 11 Java監視機能による、メソッドサンプリングの結果（抜粋）

この結果から、java.util.Arrays#copyOf()メソッドと、java.util.Arrays#copyOfRange()メソッドのサンプリング回数が、全体の95%以上を占めていることが分かります。
次に、これらのメソッドの呼び出し関係（スタックトレース）を調べます。ここでは、スタックトレース「300000」「300001」「300002」を参照します。

TRACE 300000:
          java.util.Arrays.copyOf(Arrays.java:2882)
          java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100)
          java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:390)
          java.lang.StringBuilder.append(StringBuilder.java:119)
          com.fujitsu.demo.Slow.doIt(Slow.java:36)
          com.fujitsu.demo.Slow.main(Slow.java:24)

図 12 TRACE 300000のスタックトレース

TRACE 300001:
          java.util.Arrays.copyOfRange(Arrays.java:3209)
          java.lang.String.<init>(String.java:216)
          java.lang.StringBuilder.toString(StringBuilder.java:430)
          com.fujitsu.demo.Slow.doIt(Slow.java:36)
          com.fujitsu.demo.Slow.main(Slow.java:24)

図 13 TRACE 300001のスタックトレース

TRACE 300002:
          java.util.Arrays.copyOf(Arrays.java:2882)
          java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100)
          java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:390)
          java.lang.StringBuilder.append(StringBuilder.java:119)
          com.fujitsu.demo.Slow.doIt(Slow.java:36)
          com.fujitsu.demo.Slow.main(Slow.java:24)

図 14 TRACE 300002のスタックトレース

TRACE 300000とTRACE 300002は、スタックトレースに含まれるメソッドの順序が同じですが、別のトレースとして記録されています。
これは、Java監視機能のメソッドサンプリング機能が、バイトコードのレベルで、メソッドの実行箇所に関する情報を採取するからです。Javaプログラムの行数が同じでも、サンプリング時に実行中のバイトコードが異なれば、違うスタックトレースとして回数を記録します。

これらのスタックトレースを見ると、サンプリング回数が多かった直接のメソッドはjava.util.Arrays#copyOf()とjava.util.Arrays#copyOfRange()です。しかし、これらを呼び出すきっかけになったのは、メソッドcom.fujitsu.demo.Slow#doIt()（プログラムの36行目）で使用している、java.lang.StringBuilderクラスのメソッドだと分かります。

つまり、メソッドcom.fujitsu.demo.Slow#doIt()におけるjava.lang.StringBuilderクラスの使用が、性能負荷の要因だと考えることができます。

メソッドcom.fujitsu.demo.Slow#doIt()には、StringBuilderクラスを使用している箇所はないように見えます。しかし、次の結合演算が、Javaコンパイラによって、メソッドStringBuilder#append()を使う処理に変換されています。そのため、文字列を結合するたびに、StringBuilder#append()が呼び出されます。

図 15 性能ボトルネックの箇所

Java SEのAPI仕様書を見ても分かるように、StringBuilder()コンストラクタは、初期容量が16文字の文字列バッファを構築します。append()の呼び出しを繰り返すうちにバッファが足りなくなると、バッファは自動的に拡張されます。

今回採取したメソッドサンプリングの情報から、java.util.ArraysクラスのメソッドcopyOf ()とcopyOfRange()の実行に、時間がかかっていることが分かります。つまり、StringBuilder#append()によるバッファの拡張処理に、時間がかかっていると考えられます。

そこで、メソッドcom.fujitsu.demo.Slow#doIt()を次のように修正し、StringBuilderのバッファを、あらかじめ大きく確保するようにします。

図 16 性能ボトルネック箇所の修正例

プログラムをこのように修正すると、StringBuilderのバッファ拡張を防ぎ、メソッドの実行時間を飛躍的に短縮できました。
図17は、修正後のプログラムを実行して、メソッドdoIt()の実行時間を出力した例です。

16 milliseconds

図 17 性能ボトルネックを修正したメソッドの実行時間の例

A.6.4 アプリケーションの性能ボトルネックを調べる

A.6.4.1 Java VisualVMを使った調査