haripo.com

プロファイラはいかに狂うか

ここのところ Java のプロファイリングについて調べていたのでまとめます。

はじめに

「推測するな、計測せよ」という言葉もあるように、 プログラムの性能を測定することはパフォーマンス最適化における第一歩です。 プログラム全体の処理効率を改善するためにはプログラムの各部を正しく計測し、 最適化に取り組むべき箇所を正確に見出さなければなりません。

プログラム内部の性能を計測するための方法としては プロファイラ がよく用いられます。 Java でよく使われるのは JProfiler や VisualVM, YourKit でしょうか。 プロファイラはメソッドごとに実行時間や実行回数を計測してくれるので、 パフォーマンス最適化のための強力なツールです。 しかし、プロファイラの表示する実行時間は常に正しいわけではありません。 したがって、正しい計測を行うためには、 プロファイラがどのように実行時間を計測しているのか、 そしてどのような状況で誤るのかを理解する必要があります。

そこで本稿では Java におけるプロファイラの仕組みについて解説し、 プロファイラの計測がどのように誤るかについて実験したいと思います1

プロファイラのしくみ

そもそもプロファイラがメソッドの実行にかかった時間を計測できるって不思議ではないですか。 しかも計測対象のコードを一切変更せずに、外部から計測できます。 そこで、まずはプロファイラがメソッドを計測する 2 種類の方法、 「プロファイリング」と「サンプリング」について説明します。 これらの用語はプロファイラによってまちまちで 「プロファイリング」は「トレーシング」と呼ばれることもあるようですが、 ここでは VisualVM の用語に則って「プロファイリング」と呼称することにします。

プロファイリング はメソッドにコードを追加し直接的に実行時間を取得する方法です。 メソッドの最初と最後で現在時刻を取得し、その差を求めればメソッドの実行時間が分かりますね。 これを自動的に行うのがプロファイリングです。 実は JVM には外部からバイトコードを編集する javaagent という機能があります。 プロファイラは計測対象のプログラムの各メソッドに計測コードを注入(instruments)し、 直接的に実行時間を計測します。

対して サンプリング は関数の実行時間をスレッドダンプから計測する方法です。 スレッドダンプを取得することでその瞬間に実行されている関数がわかります。 連続でスレッドダンプを取得し続ければ、 実行時間の長いメソッドほどスレッドダンプ現れる回数が多くなるはずです。 このように、メソッドがスレッドダンプに現れる頻度から近似的に実行時間を計測するのがサンプリングという方法です。

プロファイリング

上述したようにプロファイリングは、メソッドの実行時間を直接に測定する方法です。 メソッドの正確な実行時間がわかる上に、そのメソッドが実行された回数も正確に取得できます。 じゃあプロファイリングで正確なパフォーマンスが計測できるのなら、 サンプリングは必要ないのではないかと思われるかもしれません。

しかし、プロファイリングには大きなデメリットがあります。 それは計測コードの追加によるパフォーマンスの悪化です。 プロファイリングはメソッドに対して新たなコードを追加するため、メソッドの実行時間が微増します。 実行時間の短いメソッドが大量に呼び出されるシチュエーションではこのオーバーヘッドが無視できなくなります。 例として、次のコードをご覧ください。

class Fib {
  private static int fib(int n) {
    if (n <= 1) return 1;
    return fib(n - 1) + fib(n - 2);
  }

  public static void main(String[] args) throws Exception {
    Thread.sleep(15000); // この間に VisualVM を操作する
    System.out.println(fib(40));
  }
}

フィボナッチ数列の 40 番目の項を求めるプログラムです。 メモ化もせず末尾再帰でもない愚直な実装です。 fib は短時間で膨大な回数コールされるので、まさにプロファイリングが苦手とするメソッドといえます。 このコードでどれほどプロファイリングによるオーバーヘッドが発生するかを確認するために、 普通に実行した場合、サンプリングで測定した場合、プロファイリングで測定した場合 の 3 通りで実行時間(time コマンドによる user CPU 時間)を比較してみました。 また、メソッドの実行回数による変化を検証するため fib(20), fib(30), fib(40) の 3 パターンを試しています。

fib(n) の実行時間の比較(秒)
n 測定なし サンプリング プロファイリング
20 0.08 1.72 2.06
30 0.09 1.81 2.45
40 0.46 2.20 47.66

プロファイリングで追加される計測コードによって n = 40 のときの実行時間が大幅に増加しています。 メソッドの実行回数が多いほどプロファイリングのオーバーヘッドが大きくなるのです。 このようにパフォーマンスに大きな影響を与える場合があるので、 プロダクションのコードに対してプロファイリングを使うのは難しいのではないかと思います。

サンプリング

サンプリングはスレッドダンプからメソッドの実行時間を計測する方法です。 計測対象のコードを編集しないので計測対象への影響が比較的小さく、 上記の実験のようなパフォーマンス劣化が起こりにくい計測方法です。

しかし、サンプリングの求めるメソッドの実行時間はあくまで近似です。 十分な数のスレッドダンプを取得しないと信頼に足る計測結果は得られません。 だいたいの目安として、Microsoft の解説2に によると “5000+ samples is ideal” とあります。 状況によるとは思いますが、5000 個のスレッドダンプ(サンプル)を収集するのが理想的だろうということです。 これを満たすようにサンプリングの間隔などを設定する必要があります。

極端な例ですが、サンプリング間隔の設定によって計測に失敗するケースを紹介します。 次の例ではサンプリングはうまくいきません。

class Test {
  private static int a = 0;
  private static int b = 0;

  private static void funcA() {
    long begin = System.currentTimeMillis();
    while (System.currentTimeMillis() < begin + 50) {
      a += 1;
    }
  }

  private static void funcB() {
    long begin = System.currentTimeMillis();
    while (System.currentTimeMillis() < begin + 50) {
      b += 1;
    }
  }

  public static void main(String[] args) throws Exception {
    Thread.sleep(15000); // この間に VisualVM を操作してサンプリングを開始する
    for (int i = 0; i < 1000; i++) {
      funcA();
      funcB();
    }
    System.out.println(a);
    System.out.println(b);
  }
}

funcA, funcB はそれぞれ変数 a, b に 1 ずつ加算し続けるコードです。 どちらも 50ms 経過したらループから抜け、互いに制御を交換し合う構造になっています。 funcAfuncB どちらも同じくらいの実行時間がかかっているはずです。 しかし、このコードに対して VisualVM のサンプリングを実行すると、うまくいきません。

alt
サンプリングでは funcA のほうがかなり実行時間が長いようにみえる

プロファイリングでは正しく計測することができます。

alt
プロファイリングでは funcA, funcB の実行時間が正しく計測される

これは VisualVM のサンプリング間隔デフォルトで 100ms となっていることが原因です3funcA, funcB は 50ms ごとに交代で実行されるので、 100ms ごとに観測するとどちらか片方だけが実行されているように見えるのです。 したがって、サンプリングでは片方のメソッドだけが長く実行されているように計測されるというわけです。

safe-point problem

最後に safe-point problem という JVM 特有の問題について紹介します。 以下のコードをみてください。 Evaluating the Accuracy of Java Profilers4 という論文からの引用です(すこし改変しています)。

class Safepoint {
  static int[] array = new int[1024];

  public static void hot(int i) {
    int ii = (i + 10 * 100) % array.length;
    int jj = (ii + i / 33) % array.length;
    if (ii < 0) ii =- ii;
    if (jj < 0) jj =- jj;
    array[ii] = array[jj] + 1;
  }

  public static void cold() {
    for (int i = 0; i < Integer.MAX_VALUE; i++) {
      hot(i);
    }
  }

  public static void main(String[] args) throws Exception {
    Thread.sleep(15000);
    cold();
  }
}

これをサンプリングで計測すると次の結果が得られます。

alt
一見 main の時間が長いように見える

サンプリングの結果では main の Self time [%] が 100 になっています。 しかし CPU time はどのメソッドも 0 です。 hot メソッドも cold メソッドも明らかに CPU を使っているはずですが、いったいどういうことでしょうか。

サンプリングは関数の実行時間をスレッドダンプから取得する方法です。 実は safe-point という仕組みによってスレッドダンプの取得できるタイミングにバイアスがかかっており、 プロファイラは計測に必要なスレッドダンプが取得できていなかったのです。 OpenJDK のドキュメントでは safe-point は次のように説明されています。

“A point during program execution at which all GC roots are known and all heap object contents are consistent. From a global point of view, all threads must block at a safepoint before the GC can run.”5

多くの場合 GC を実行できるタイミングと言い換えてもいいかもしれません。 しかし GC 以外にも safe-point でしか行えない操作がいくつかあって、 スレッドダンプを取得することがそのひとつです。 また safe-point は JIT コンパイラの最適化によって配置・削除されます。 これによって、コード中にスレッドダンプが取得できない区間が発生するわけです。

safe-point の発生は -XX:+PrintSafepointStatistics オプションで観測することができます。 VisualVM のサンプリングを動作させながら実行した結果を以下に記載します。

$ java -XX:+PrintSafepointStatistics Safepoint
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
2.504: Deoptimize                       [       9          0              0    ]      [     0     0     0     0     0    ]  0
3.508: no vm operation                  [       9          0              0    ]      [     0     0     0     0     0    ]  0
4.119: EnableBiasedLocking              [       9          0              0    ]      [     0     0     0     0     0    ]  0
7.635: RevokeBias                       [      10          0              1    ]      [     0     0     0     0     0    ]  0
7.636: RevokeBias                       [      10          0              1    ]      [     0     0     0     0     0    ]  0
7.639: Deoptimize                       [      10          0              0    ]      [     0     0     0     0     0    ]  0

(省略)

13.758: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
13.852: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
13.859: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
13.958: ThreadDump                       [      14          0              1    ]      [     0     0     0     0     0    ]  0
14.058: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
14.160: ThreadDump                       [      14          0              1    ]      [     0     0     0     0     0    ]  0
14.260: ThreadDump                       [      14          0              1    ]      [     0     0     0     0     0    ]  0
14.357: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
14.458: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
14.560: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
14.660: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
14.759: ThreadDump                       [      14          0              1    ]      [     0     0     0     0     0    ]  0
14.853: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
14.860: ThreadDump                       [      14          0              1    ]      [     0     0     0     0     0    ]  0
14.960: ThreadDump                       [      14          0              1    ]      [     0     0     0     0     0    ]  0
15.057: ThreadDump                       [      14          0              0    ]      [     0     0     0     0     0    ]  0
15.157: ThreadDump                       [      14          1              2    ]      [ 11796     0 11796     0     0    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
26.955: RevokeBias                       [      16          0              1    ]      [     0     0     0     0     0    ]  0
26.956: no vm operation                  [      14          0              1    ]      [     0     0     0     0   352    ]  0

Polling page always armed
ThreadDump                        57
FindDeadlocks                      1
Deoptimize                         3
GC_HeapInspection                  1
EnableBiasedLocking                1
RevokeBias                        49
BulkRevokeBias                     7
    0 VM operations coalesced during safepoint
Maximum sync time  11796 ms
Maximum vm operation time (except for Exit VM operation)      6 ms

左端の数値が実行時間(秒)でその右隣が safe-point でのアクションです。 Thread.sleep している最初の 15 秒しかスレッドダンプが取得できていないのが分かります。

逆に上記コードで safe-point を発生させるために改変してみました。 hot, cold 関数中 で String オブジェクトを生成しています。 おそらくヒープオブジェクトを作成することで(GC が走らなければならなくなるので)、 safe-point の最適化による削除を抑止できるのではないでしょうか。


class Safepoint {
  static int[] array = new int[1024];
  static String buf = "";

  public static void hot(int i) {
    int ii = (i + 10 * 100) % array.length;
    int jj = (ii + i / 33) % array.length;
    if (ii < 0) ii=-ii;
    if (jj < 0) jj=-jj;
    array[ii] = array[jj] + 1;
    buf = String.valueOf(i);
  }

  public static void cold() {
    for (int i = 0; i < Integer.MAX_VALUE; i++) {
      hot(i);
      buf = String.valueOf(i);
    }
  }

  public static void main(String[] args) throws Exception {
    Thread.sleep(15000);
    cold();
    System.out.println(buf);
  }
}

これで先ほどと同じパラメータで実行してみましょう。

(省略)
187.555: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     1    ]  0
187.566: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
187.639: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     0    ]  0
187.668: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
187.735: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     0    ]  0
187.764: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
187.833: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     1    ]  0
187.866: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
187.918: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     0    ]  0
187.968: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.003: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     2    ]  0
188.065: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.086: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.105: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     1    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
188.166: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.240: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     2    ]  0
188.268: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.365: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.371: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     2    ]  0
188.465: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.537: ParallelGCFailedAllocation       [      14          0              0    ]      [     0     0     0     0     0    ]  0
188.565: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.666: ThreadDump                       [      14          1              1    ]      [     0     0     0     0     0    ]  1
188.677: no vm operation                  [      12          0              0    ]      [     0     0     0     0   342    ]  0

Polling page always armed
ThreadDump                      1968
FindDeadlocks                     18
Deoptimize                         3
GC_HeapInspection                  1
ParallelGCFailedAllocation      1647
EnableBiasedLocking                1
RevokeBias                        52
BulkRevokeBias                     7
    2 VM operations coalesced during safepoint
Maximum sync time     10 ms
Maximum vm operation time (except for Exit VM operation)     22 ms

ちゃんとスレッドダンプが出力され続けています。

alt
hot, cold の実行時間が計測できている

おわりに

サンプリングとプロファイリングについて解説しました。 実験で示したようにサンプリングとプロファイリングにはそれぞれ得意分野がありうまく使い分ける必要があります。 さらに、誤った計測結果に気づくためにはそれぞれの仕組みを理解しておくことが重要です。 本記事がプロファイラの理解の一助になれば幸いです。

  1. 間違い等あれば是非 twitter で教えてください
  2. How CPU Sampling Works https://blogs.msdn.microsoft.com/devops/2016/04/28/how-cpu-sampling-works/
  3. yourkit だとデフォルトで 20ms となっており、100ms はかなり大きい気がする
  4. http://plv.colorado.edu/papers/mytkowicz-pldi10.pdf
  5. http://openjdk.java.net/groups/hotspot/docs/HotSpotGlossary.html