それでは、今度は最適化有の場合のprofileを見てみよう。
以下のようになった。
result: 489261678 Flat profile of 6.82 secs (407 total ticks): main Interpreted + native Method 0.2% 1 + 0 Test.expand08 0.2% 0 + 1 java.lang.String.indexOf 0.5% 1 + 1 Total interpreted Compiled + native Method 36.5% 145 + 3 Test.expand03 34.1% 132 + 6 Test.expand02 20.0% 80 + 1 Test.expand04 6.7% 27 + 0 Test.expand05 1.7% 7 + 0 Test.expand06 0.2% 1 + 0 Test.expand08 99.3% 392 + 10 Total compiled Thread-local ticks: 0.5% 2 Blocked (of total) 0.2% 1 Compilation Global summary of 6.82 seconds: 100.0% 436 Received ticks 3.7% 16 Received GC ticks 0.5% 2 Compilation 1.6% 7 Other VM operations
約7秒という結果である。
2004.04.06の結果は約9秒だから、約2秒の改善と言える。
昨日と同じように、expand関数の部分だけを取り出して比較してみよう。展開していない場合は以下。
99.6% 530 + 4 Test.expand
これに該当するのは、以下の部分。
Interpreted + native Method 0.2% 1 + 0 Test.expand08 Compiled + native Method 36.5% 145 + 3 Test.expand03 34.1% 132 + 6 Test.expand02 20.0% 80 + 1 Test.expand04 6.7% 27 + 0 Test.expand05 1.7% 7 + 0 Test.expand06 0.2% 1 + 0 Test.expand08
expand08はコンパイルされたものとインタプリタのままのものが混在していたようだ。
それらも全て合わせる形での合計は以下。
99.4% 393 + 10 (expand02〜expand08の合計)
ticks差で131(=約2秒)、ここの改善が支配的なようである。
昨日の最適化無と比べて異なるのは、expand01とexpand07が無くなってしまっていることだろうか。
これは最適化によってインライン展開されてしまったからなのか、それとも計測に上げるまでもない程に負荷が少なかったのかのいずれかだが、ここでは判断できないような気がする。
あとは、昨日は呼び出し回数の多い順に並んでいたのが、今回のものはかなりばらばらとした並びになっているように見える。この原因も良く分からないが、最適化の結果なのだろう。
次は、AOTコンパイラでも実測してみよう。