マージソート性能調査

昨日書いたマージソートはlengthを使うから遅くなるのではないかという漠然とした不安を持っていました。そこでlengthの使用頻度を抑えた関数を実装した上で、パフォーマンスをより細かく調べていくことにします。

lengthを使わないMergeSort

リストの長さも引数に渡すように変更しただけです。

速度比較

それでは実際に速度を測ってみます。以下のようなmain関数を実行し、timeコマンドで所要時間をまとめてみます。

main :: IO ()
main = do
  print ([1..1000000] == fastMergeSort [1000000,999999..1]) -- => "True"

結果は以下のとおりです。期待ほど高速化につながっていないことがわかりました。最適化を使用しても500万要素のソートに10秒以上かかっています。

アルゴリズム	要素数 1,000,000[個]	要素数 2,000,000[個]	要素数 5,000,000[個]
再起するたびにlength関数を使用	2.235s	4.509s	12.120s
length関数を1度だけ使用	2.075s	4.421s	11.816s
length関数を1度だけ使用 --make -O2コンパイルオプション付き	-	-	10.138s
（参考）Listモジュールのsort関数	1.594s	3.230s	8.759s

プロファイリング

つまりlengthの多用はボトルネックではなかったということです。Haskellに詳しいわけでもないのにカンに頼ってはいけませんね。さっそくプロファイリングしていきましょう。
Read World Haskellによると、プログラムの実行時引数を用いるだけでjmapやjstackに相当する様々なプロファイリングが可能なようです。

In particular, we can ask the runtime system to gather memory and garbage collector performance numbers with the -s flag

http://book.realworldhaskell.org/read/profiling-and-optimization.html

とりあえず標準エラー出力に統計情報を出力してみます。

$ time ./mergeSort +RTS -sstderr
./mergeSort +RTS -sstderr
True
6,429,254,632 bytes allocated in the heap
3,822,585,176 bytes copied during GC
239,604,824 bytes maximum residency (32 sample(s))
5,393,536 bytes maximum slop
674 MB total memory in use (5 MB lost due to fragmentation)

Generation 0: 12232 collections, 0 parallel, 3.65s, 4.11s elapsed
Generation 1: 32 collections, 0 parallel, 3.19s, 4.16s elapsed

INIT time 0.00s ( 0.00s elapsed)
MUT time 6.53s ( 7.33s elapsed)
GC time 6.84s ( 8.27s elapsed)
RP time 0.00s ( 0.00s elapsed)
PROF time 0.00s ( 0.00s elapsed)
EXIT time 0.00s ( 0.00s elapsed)
Total time 13.37s ( 15.60s elapsed)

%GC time 51.2% (53.0% elapsed)

Alloc rate 985,050,868 bytes per MUT second

Productivity 48.8% of total user, 41.8% of total elapsed

GCに50％以上の時間を費やしていることがわかりました。そりゃ遅いわけだ。
ついでに消費時間の内訳も出力してみましたが、こちらからはfastMergeSort関数で全体の9割程度の時間を使っていること、4GBものメモリ空間をallocしているらしいことがわかります。

$ ghc -O2 --make A.hs -prof -auto-all -caf-all -fforce-recomp
$ time ./mergeSort +RTS -p
$ cat mergeSort.prof
Tue Apr 19 07:11 2011 Time and Allocation Profiling Report (Final)

mergeSort +RTS -p -K100M -RTS

total time = 1.72 secs (86 ticks @ 20 ms)
total alloc = 4,132,704,532 bytes (excludes profiling overheads)

COST CENTRE MODULE %time %alloc

fastMergeSort Main 80.2 87.4
main Main 11.6 9.7
CAF:main_a Main 8.1 2.9

individual inherited
COST CENTRE MODULE no. entries %time %alloc %time %alloc

MAIN MAIN 1 0 0.0 0.0 100.0 100.0
main Main 228 1 0.0 0.0 0.0 0.0
CAF:main2 Main 222 1 0.0 0.0 0.0 0.0
CAF:main3 Main 221 1 0.0 0.0 0.0 0.0
CAF:main4 Main 220 1 0.0 0.0 80.2 87.4
main Main 232 0 0.0 0.0 80.2 87.4
fastMergeSort Main 233 1 80.2 87.4 80.2 87.4
CAF:main_a Main 219 1 8.1 2.9 8.1 2.9
CAF:main10 Main 218 1 0.0 0.0 5.8 4.8
main Main 231 0 5.8 4.8 5.8 4.8
CAF:main5 Main 217 1 0.0 0.0 5.8 4.8
main Main 234 0 5.8 4.8 5.8 4.8
CAF:main7 Main 216 1 0.0 0.0 0.0 0.0
main Main 235 0 0.0 0.0 0.0 0.0
CAF GHC.Show 212 2 0.0 0.0 0.0 0.0
CAF GHC.IO.Handle.FD 153 2 0.0 0.0 0.0 0.0
CAF System.Posix.Internals 152 1 0.0 0.0 0.0 0.0
CAF GHC.Conc 136 1 0.0 0.0 0.0 0.0
CAF GHC.IO.Handle.Internals 127 1 0.0 0.0 0.0 0.0
CAF GHC.IO.Encoding.Iconv 121 5 0.0 0.0 0.0 0.0

メモリの使い方を調べる

いくつかダンプを取って調べてみましたが、-hyオプションによる型ごとのプロファイルが最も有用でした。

$ ./mergeSort +RTS -hy
$ hp2ps -e8in -c mergeSort.hp

つまりリストを使い捨て過ぎているということなんでしょう。
詳しくは追えていませんが、Javaで言うと「関数呼び出しごとにLinkedListを作ってはaddAllして返す」ようなことになっているのではと想像しています。リストを使うこと自体、特にtakeやdropやmergeに問題がありそうです。改善方法に何があるのか、次回探してみることにします。