前回でパフォーマンス計測に用いるタイマーについての理解を深めたので、やっとパフォーマンスの計測を始めることができる。
文字列連結についての基礎知識
Javaの文字列連結についての言語仕様まわりは Stringの連結はそう簡単なものではない - じゅんいち☆かとうの技術日誌 が詳しい。しかし、パフォーマンス計測がなっちゃない。パフォーマンスの計測はそう簡単なものではない。
currentTimeMillis()で計測しておいて
plusTime:14780, concatTime:7053, sbuilderTime:7, sbufferTime:13
とか、その7とか13の有効数字はいくつだっての*1。
そんなわけで、計測方法を工夫してみよう。二重ループとし、内側を1000回、それを500回繰り返す。ループが1回まわる間に1回ずつSystem.nanoTime()をとり、配列に格納。計測が終わってから区間タイムを算出する。
public class StringTest { public static void main(String[] args) { long[] builder = builder(); long[] buffer = buffer(); } static int loop = 500; static int innerLoop = 1000; static long[] builder() { long[] time = new long[loop+1]; for (int i=0; i<loop; i++) { time[i] = System.nanoTime(); StringBuilder sb = new StringBuilder(); for (int j=0; j<innerLoop; j++) { sb.append("a"); } } time[loop] = System.nanoTime(); long[] dif = new long[loop]; for (int i=0; i<loop; i++) { dif[i] = time[i+1]-time[i]; } return dif; } static long[] buffer(){ long[] time = new long[loop+1]; for (int i=0; i<loop; i++) { time[i] = System.nanoTime(); StringBuffer sb = new StringBuffer(); for (int j=0; j<innerLoop; j++) { sb.append("a"); } } time[loop] = System.nanoTime(); long[] dif = new long[loop]; for (int i=0; i<loop; i++) { dif[i] = time[i+1]-time[i]; } return dif; } }
これを実行し、builder()メソッドとbuffer()メソッドの順番を入れ替えてさらに実施した。
| 方式 | builder平均(ns) | 標準偏差 | 中央値 | buffer平均(ns) | 標準偏差 | 中央値 |
|---|---|---|---|---|---|---|
| builder-buffer順 | 52,339 | 914,644 | 41,276 | 99,834 | 1,965,754 | 89,327 |
| buffer-builder順 | 51,911 | 2,290,890 | 40,927 | 102,803 | 1,789,987 | 89,537 |
本当はそれぞれ複数回実施するところなんだが、見て取れるように標準偏差が異様に大きい。平均値と中央値の差からも分かるように、やたらと値の大きな異常値が出現しているせいだ。この異常値はGCが主犯と考えられる。
なお、計測値そのものはSystem.nanoTime()の精度から±2μ秒程度と考えられる。下3桁ははなから無効だと考えていい。だが、ここまで標準偏差がでかいと平均値とかあてにならないので中央値で比較するほうがマシとも思える。どうにかして異常値をうまくはじけって話だ。
そして、この計測をグラフにプロットするとアレが見えてくる。
黒がbuilderで赤がbufferだ。グレーのラインは20μ秒ごとに引いてある。左端のほうに大きな落差が見て取れる。そう、JITコンパイラ様だ。
限界まで削る
ところで、先ほどのプログラム、正しくappend()を計測できているのだろうか？見なおしてみると、StringBuilder とStringBuffer のnewがある。ここが余計なんじゃないのってことで修正を加える。
static long[] builder() { long[] time = new long[loop]; long t1, t2; for (int i=0; i<loop; i++) { StringBuilder sb = new StringBuilder(); t1 = System.nanoTime(); for (int j=0; j<innerLoop; j++) { sb.append("a"); } t2 = System.nanoTime(); time[i] = t2-t1; } return time; }
| 方式 | builder平均(ns) | 標準偏差 | 中央値 | buffer平均(ns) | 標準偏差 | 中央値 |
|---|---|---|---|---|---|---|
| new除外 | 51,387 | 1,826,540 | 41,277 | 108,957 | 2,073,185 | 89,816 |
全然変わらない。次はforの内側、変数宣言を行っているjを外にはじき出す。
static long[] builder() { long[] time = new long[loop]; long t1, t2; for (int i=0; i<loop; i++) { StringBuilder sb = new StringBuilder(); int j=0; t1 = System.nanoTime(); for (; j<innerLoop; j++) { sb.append("a"); } t2 = System.nanoTime(); time[i] = t2-t1; } return time; }
| 方式 | builder平均(ns) | 標準偏差 | 中央値 | buffer平均(ns) | 標準偏差 | 中央値 |
|---|---|---|---|---|---|---|
| j除外 | 50,909 | 1,791,464 | 41、905 | 91,856 | 177,505 | 90,165 |
あいかわらず変わらない。やはりGCか。
static long[] builder() { long[] time = new long[loop]; long t1, t2; for (int i=0; i<loop; i++) { { StringBuilder sb = new StringBuilder(); int j=0; t1 = System.nanoTime(); for (; j<innerLoop; j++) { sb.append("a"); } t2 = System.nanoTime(); } time[i] = t2-t1; gc(); } return time; } static void gc() { long pre = Runtime.getRuntime().freeMemory(); for (;;) { System.gc(); long free = Runtime.getRuntime().freeMemory(); if (pre == free) {break;} pre = free; } }
Runtime.getRuntime().freeMemory()が増えなくなるまでGCをかけるという念入りな感じにしてみた。GCによる異常値が減るように祈りをこめて。するとここで思わぬ事態が発生する。
なんだこの2段目の落ち込みは！？
| 方式 | builder平均(ns) | 標準偏差 | 中央値 | buffer平均(ns) | 標準偏差 | 中央値 |
|---|---|---|---|---|---|---|
| GC除外 | 46,475 | 350,258 | 42,254 | 72,991 | 589,260 | 52,241 |
あいかわらず標準偏差はぶっとんだ値になっている。異常値の発生率がややおさえれているような気もするがまるで効いてない気もする。グラフでみるとbuilderのほうは40μ秒の線の上に奇麗に並んでいるわけだが、得られた数値を処理してそれを導くのは存外難しい。最小二乗法とかで近似線を引くでもしないとダメっぽい。平均値地46±2μ、秒標準偏差は350です（キリッ）とか言うと指導教官から指導が入るはずだ。
それにしてもこの赤の落ち込みはなんだろうか。JITの最適化がもう一段進んで、不要なsynchronizedを取り除く最適化がされたのではなかろうか？ならば、単純に実行回数が増えただけでも発生するかもしれない。
そう予測を立てて外側のループを100倍の50000回まわしてみたのが以下のグラフ。横軸のタイムスケールを100倍にしてある。
みごとに再現した。よかったよかった。
結論
パフォーマンス計測は難しい。
JITのかかりかた
僕も詳しい話は知らないのだけど、実行時のプロファイリング結果から最適化が可能かを判断してホットスポットを最適化するようになっているらしい。
そのため、synchronizedが不要と確信するためには、分岐などをもれなく相当回数通過するなどの条件が達成される必要があるらしい。この辺は @nekop の受け売りです。すいません。
だから、JIT後のパフォーマンス計測をしたければ、うまく条件分岐を網羅するようにウォーミングアップさせる必要があるとのことだ。今回はGCを回すことでなんかしらの条件を満たし、最適化が早くかかったようだ。はっきりした条件を知りたければOpenJDKのソースを読めって @nekop がいってた。
それにしても、こう複雑な条件が噛み合わさってくると、どのように数字を理解するべきかが難しいね。
