Haskellのプログラムをプロファイルしてみる。

Haskell Profile

GHCではプログラムのプロファイルをとってくれる機能があります。
数独ソルバーのパ実行フォーマンスを見るのに使ってみました。

GHCのマニュアルを見れば出ていることなのですが、GHCのプロファイラはいくつかモードがあって、ものによってはメモリの消費情報をグラフ化してくれたりするものもあるようですが、今回は「ふつう」のやつをやってみました。実行速度とメモリの消費を関数ごとに計測してくれます。

プロファイルを行うには2つのステップが必要です。
まずはプログラムを次のオプションを追加してコンパイルします。

  • O2 -prof -auto-all -o Main


そして、出来上がった実行ファイルを次のオプションをつけて実行してみます。

  1. RTS -p

実行が終了した後に *.profというファイルが生成されています。これがプロファイルの結果の書かれたファイルになります。

プロファイル結果の例はこんな感じです。

Time and Allocation Profiling Report  (Final)

  foo +RTS -p -RTS

total time  =        4.34 secs   (217 ticks @ 20 ms)
total alloc = 812,398,524 bytes  (excl. profiling overheads)



    

    COST CENTRE　
    %time
    %alloc
    

    

    exclude
    38.2
    35.8
    

    

    propagate
    33.2
    26.1
    

    

    set
    18.9
    27.0
    

    

    excludeM
    3.7
    1.3
    

    

    uniq
    2.8
    4.6
    

    

    tryChoices
    1.8
    5.1
    

    

    onlyOne
    1.4
    0.0
    





    

     -                     
     -             
     -      
    individual
     
    inherited
     
    

    

    COST CENTRE 
    no.　
    entries
     time　
    alloc　
     time　
    alloc
    

    

    MAIN
    1
    0
    0.0
    0.0
    100.0
    100.0
    

    

    　main
    196
    1
    0.0
    0.0
    100.0
    99.9
    

    

    　　tryChoices
    220
    32444
    1.8
    5.1
    100.0
    99.9
    

    

    　　　set
    222
    155293
    18.9
    27.0
    97.2
    94.8
    

    

    　　　　exclude
    225
    437059
    6.5
    6.0
    6.5
    6.0
    

    

    　　　　propagate
    223
    155293
    33.2
    26.1
    71.9
    61.9
    

    

    　　　　　onlyOne
    229
    721311
    0.5
    0.0
    0.5
    0.0
    

    

    　　　　　excludeM
    226
    1302379
    3.7
    1.3
    12.4
    9.2
    

    

    　　　　　　exclude
    227
    3963625　
    8.8
    7.9
    8.8
    7.9
    

    

    　　　　　uniq
    224
    155293
    2.8
    4.6
    25.8
    26.6
    

    

    　　　　　　exclude
    228
    1282200
    23.0
    21.9
    23.0
    21.9
    

    

    　　　onlyOne
    221
    322671
    0.9
    0.0
    0.9
    0.0
    

    

    　　showSudoku
    215
    6
    0.0
    0.0
    0.0
    0.0
    

    

    　　　showChoice
    218
    162
    0.0
    0.0
    0.0
    0.0
    

    

    　　　printGrid
    217
    162
    0.0
    0.0
    0.0
    0.0
    

    

    　CAF
    190
    33
    0.0
    0.0
    0.0
    0.1
    

    

    　　printGrid
    219
    0
    0.0
    0.0
    0.0
    0.0
    

    

    　　showSudoku
    216
    0
    0.0
    0.0
    0.0
    0.0
    

    

    　　initialConstraintsC　
    213
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　　initialConstraintsY
    212
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　　initialConstraintsX
    205
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　　initialBoard
    203
    2
    0.0
    0.0
    0.0
    0.0
    

    

    　　initialSudoku
    202
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　　p4
    201
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　　sample
    200
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　　allPos
    199
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　　sampleInput
    198
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　　main
    197
    0
    0.0
    0.0
    0.0
    0.0
    

    

    　　　set
    204
    18
    0.0
    0.0
    0.0
    0.0
    

    

    　　　　exclude
    208
    54
    0.0
    0.0
    0.0
    0.0
    

    

    　　　　propagate
    206
    18
    0.0
    0.0
    0.0
    0.0
    

    

    　　　　　onlyOne
    214
    327
    0.0
    0.0
    0.0
    0.0
    

    

    　　　　　excludeM
    209
    327
    0.0
    0.0
    0.0
    0.0
    

    

    　　　　　　exclude
    210
    2529
    0.0
    0.0
    0.0
    0.0
    

    

    　　　　　uniq
    207
    18
    0.0
    0.0
    0.0
    0.0
    

    

    　　　　　　exclude
    211
    327
    0.0
    0.0
    0.0
    0.0
    

    

    　CAF
    169
    8
    0.0
    0.0
    0.0
    0.0
    

    

    　CAF
    164
    1
    0.0
    0.0
    0.0
    0.0
    

    

    　CAF
    121
    4
    0.0
    0.0
    0.0
    0.0
    


表をブログでちゃんとフォーマットするためにModule欄を取り除きました…

まず、最初の部分で全体でどれくらい時間がかかってどれくらいメモリを消費したかが記録されています。

total time  =        4.34 secs   (217 ticks @ 20 ms)
total alloc = 812,398,524 bytes  (excludes profiling overheads)

これはわりと難度の高いパズルを一つ解くのにかかった時間とメモリです。初期のころのコードでした。4秒ちょっとというのはまぁまぁだとしても、９ｘ９の数独を解くのに 700Mバイト超のメモリーを使うのはなんともいただけませんね…

そして、その次の部分でメモリ、時間ともに特に消費している関数がリストされています。


    

    COST CENTRE　
    %time
    %alloc
    

    

    exclude
    38.2
    35.8
    

    

    propagate
    33.2
    26.1
    

    

    set
    18.9
    27.0
    

    

    excludeM
    3.7
    1.3
    

    

    uniq
    2.8
    4.6
    

    

    tryChoices
    1.8
    5.1
    

    

    onlyOne
    1.4
    0.0
    

    

    
    


これによると、exclude関数は 4 * 0.382 = 1.528 ほぼ１．５秒、そしてメモリはこの関数単体で２５０Mバイト消費していることがわかります。一体何にそんなにメモリを使っているんでしょう…

そして、最後の部分が詳細のリストになります。詳細といっても、関数一つ丸ごとのパフォーマンスしかわからないので、複雑な関数の場合は、分割してみたり、仮説を立てて検証してみたりしないと何がリソース浪費の原因になっているかははっきりしないときもあります…



    

     -                     
     -             
    individual
     
    inherited
     
    

    

    COST　CENTRE　
    entries
    %time
    %alloc
    %time
    %alloc
    

    

    MAIN
    0
    0.0
    0.0
    100.0
    100.0
    

    

    　main
    1
    0.0
    0.0
    100.0
    99.9
    

    

    　　tryChoices
    32444
    1.8
    5.1
    100.0
    99.9
    

    

    　　　set
    155293
    18.9
    27.0
    97.2
    94.8
    

    

    　　　　exclude
    437059
    6.5
    6.0
    6.5
    6.0
    

    

    　　　　propagate
    155293
    33.2
    26.1
    71.9
    61.9
    

    

    　　　　　onlyOne
    721311
    0.5
    0.0
    0.5
    0.0
    

    

    　　　　　excludeM　
    1302379
    3.7
    1.3
    12.4
    9.2
    

    

    　　　　　　exclude
    3963625　
    8.8
    7.9
    8.8
    7.9
    

    

    　　　　　uniq
    155293
    2.8
    4.6
    25.8
    26.6
    

    

    　　　　　　exclude
    1282200
    23.0
    21.9
    23.0
    21.9
    

    

    　　　onlyOne
    322671
    0.9
    0.0
    0.9
    0.0
    

    

    　　showSudoku
    6
    0.0
    0.0
    0.0
    0.0
    


        :

ここで、entriesの欄はその関数が何回実行されたかを示しています。timeとallocがindividualとinheritedに分けて2回繰り返されているのは、individualがその関数自身の時間とメモリの消費、そしてinheritedがその関数とそこから呼び出される関数全てを含めた時間とメモリの消費を示しています。mainのinheritedが時間、メモリ共に100%になっていることからもわかりますね…

こうやって見ると、excludeはもうとにかくすごい回数呼ばれていますね… excludeMとuniqの両方からかなり呼び出されて合計500万回以上に及びます。ここまで呼ばれてしまうと1回あたりの時間、メモリの消費が少なくてもすぐにすごいことになっちゃいます…いわゆるホットスポットとかインナーループとか言われるやつですね…propagateのほうは回数は excludeの1/33ですが、時間もメモリーもかなり使っています。ここは何か遅い処理が入っているか、関数の中にホットスポットがあるか…

元のリストのほうを見るとCAFとかいうものがリストにあるのが見えますが、これは今のところ僕にはなんだかよくわかっていません。まぁ、マニュアルを見ればいいだけなんでしょうが…

そして、プログラムの効率化(パフォーマンス・チューニング)はこういったプロファイルの結果を見ながらリソース浪費の原因を理解して、改善していくわけです…

次回以降は実際の効率化の話しを書いていきたいと思います。

ではでは。