では、まずは最適化無しのprofileを見てみよう。
result: 489261678 Flat profile of 75.86 secs (4802 total ticks): main Interpreted + native Method 44.4% 1833 + 297 Test.expand02 30.9% 1392 + 92 Test.expand03 14.5% 663 + 33 Test.expand04 5.2% 237 + 11 Test.expand05 1.9% 90 + 0 Test.expand01 1.3% 63 + 0 Test.expand06 0.4% 20 + 0 Test.expand07 0.1% 5 + 0 Test.expand08 0.0% 0 + 1 java.io.FileInputStream.open 98.7% 4303 + 434 Total interpreted Thread-local ticks: 0.1% 3 Blocked (of total) 0.0% 1 Class loader 0.5% 22 Interpreter 0.8% 36 Unknown: running frame 0.1% 3 Unknown: thread_state Global summary of 75.88 seconds: 100.0% 4856 Received ticks 0.9% 44 Received GC ticks 0.1% 7 Other VM operations 0.0% 1 Class loader 0.5% 22 Interpreter 0.8% 39 Unknown code
結果としては約76秒となった。
2004.04.05での結果は約90秒だったから、約14秒の改善である。
2004.04.05の結果と最も異なるのは、やはり展開した部分だろうか。
展開せず再帰呼び出しで書いた場合には、以下のようになっていた。
99.1% 5204 + 454 Test.expand
それに該当するのは以下の部分。
44.4% 1833 + 297 Test.expand02 30.9% 1392 + 92 Test.expand03 14.5% 663 + 33 Test.expand04 5.2% 237 + 11 Test.expand05 1.9% 90 + 0 Test.expand01 1.3% 63 + 0 Test.expand06 0.4% 20 + 0 Test.expand07 0.1% 5 + 0 Test.expand08
上記を合計すると、以下のようになる。
98.7% 4303 + 433 （expand01〜expand08合計）
ticks差で922、秒数にすると約14秒だから、やはり再帰呼び出しを展開したのが効いていると考えて良さそうだ。
expand09、expand10、expand11は呼び出される回数が少ないためか、処理全体に占める負荷の割合が少ないのだろう。ここの表示では省略されているようだ。
expand01は処理としてはかなり軽いのだが、回数だけはダントツで多いので、上位に入っている。
他の関数については処理回数の多い順に並んでいるのが分かる。
明日は、最適化有のprofileを見てみよう。
