第5章 プロファイルを取る

目次

5.1. コスト集約点とコスト集約点スタック
5.1.1. コスト集約点を手動で挿入する
5.1.2. コストの配分規則
5.2. プロファイルについてのコンパイルオプション
5.3. 時間及び確保量のプロファイルを取る
5.4. メモリ使用状況のプロファイルを取る
5.4.1. ヒーププロファイルのためのRTSオプション
5.4.2. 維持原因プロファイル
5.4.2.1. 維持原因プロファイルに関するヒント
5.4.3. 経歴プロファイル
5.4.4. 実際のメモリ使用量
5.5. hp2ps––ヒーププロファイルをPostScriptへ
5.5.1. hpファイルを操作する
5.5.2. プロファイルの特定の部分に注目する
5.5.3. 実行中のプログラムのヒーププロファイルを見る
5.5.4. ヒーププロファイルを実時間で閲覧する
5.6. 並列・並行プログラムのプロファイルを取る
5.7. コード網羅率を観察する
5.7.1. 小さな例: 逆数をとる
5.7.2. 網羅率の測定器を付与するオプション
5.7.3. hpcツールキット
5.7.3.1. hpc report
5.7.3.2. hpc markup
5.7.3.3. hpc sum
5.7.3.4. hpc combine
5.7.3.5. hpc map
5.7.3.6. hpc overlayとhpc draft
5.7.4. Haskell Program Coverageの注意点と短所
5.8. 「ticky-ticky」プロファイルを使う

GHCには時間及び空間のプロファイルをとるためのシステムが付属している。このシステムの目的は、「なぜ私のプログラムはこんなに遅いのか」「なぜ私のプログラムはこんなに沢山のメモリを使うのか」といった疑問に答えられるようにすることである。

プログラムのプロファイルをとるのは三つの段階からなる。

  1. プログラムをプロファイル用にコンパイルする。これには、-profオプションと、多くの場合、自動注釈を付けるオプションの一つを付ける。-fprof-autoが最も一般的である[10]

    cabalで外部ライブラリを使っているなら、それらのライブラリをプロファイル対応付きで再インストールする必要があるかもしれない。これは典型的にはcabal install -p package --reinstallとする。

  2. プログラムをプロファイル用にコンパイルしたら、次はプロファイルを生成するためにそれを走らせる必要がある。例えば、単純な時間プロファイルはプログラムを+RTS -p付きで走らせることによって生成できる。これはprog.profという名前のファイルを生成する。ただしprogはあなたのプログラムの名前である(Windows上なら.exe拡張子を除いたもの)。

    生成できるプロファイルには沢山の種類があり、異なるRTSオプションによって選択できる。この章の残りの部分ではこの色々な種類のプロファイルを記述する。プロファイルの中には、プログラムを実行した後にさらに別のツールで処理することを必要とするものもある。

  3. 生成されたプロファイル情報を調べ、その情報を使ってプログラムを最適化し、必要に応じて繰り返す。

5.1. コスト集約点とコスト集約点スタック

GHCのプロファイルシステムではコストコスト集約点(cost centre)に割り当てられる。コストとは式を評価するのに必要な時間と空間(メモリ)のことである。コスト集約点はプログラム上の注釈で、一定の範囲の式を支配する。注釈の付いた式が発生させたコストは全て、それを直接支配するコスト集約点に割り当てられる。さらに、GHCは任意の式についてそれを支配するコスト集約点のスタックを実行時に記憶していて、どこにどれだけコストが掛かったかという情報の付いた呼び出し木を生成する。

例を一つ見てみよう。

main = print (fib 30)
fib n = if n < 2 then 1 else fib (n-1) + fib (n-2)

このプログラムを次のようにコンパイルし、実行する。

$ ghc -prof -fprof-auto -rtsopts Main.hs
$ ./Main +RTS -p
121393
$

GHCでコンパイルされたプログラムは、-pというRTSオプション付きで実行されると、prog.profというファイルを生成する。この場合、ファイルの内容は以下のようなものである。

        Wed Oct 12 16:14 2011 Time and Allocation Profiling Report  (Final)

           Main +RTS -p -RTS

        total time  =        0.68 secs   (34 ticks @ 20 ms)
        total alloc = 204,677,844 bytes  (excludes profiling overheads)

COST CENTRE MODULE  %time %alloc

fib         Main    100.0  100.0


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

MAIN        MAIN                    102           0    0.0    0.0   100.0  100.0
 CAF        GHC.IO.Handle.FD        128           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Encoding.Iconv   120           0    0.0    0.0     0.0    0.0
 CAF        GHC.Conc.Signal         110           0    0.0    0.0     0.0    0.0
 CAF        Main                    108           0    0.0    0.0   100.0  100.0
  main      Main                    204           1    0.0    0.0   100.0  100.0
   fib      Main                    205     2692537  100.0  100.0   100.0  100.0

ファイルの最初の部分は、プログラムの名前、オプション、実行時に計測された合計実行時間と合計メモリ確保量を示している。(合計メモリ確保量はある一つの時点においてプログラムが必要とする生存メモリの量とは異なることに注意。後者はヒーププロファイルで量れるが、これについては後で5.4. メモリ使用状況のプロファイルを取る内で説明する)

ファイルの二番目の部分は、プログラムの中でコストが高い関数をコスト集約点で分類したものである。この例では、プログラムにはコストの高い関数が一つ(fib)しかなく、これがプログラムの時間と確保量の両方について100%のコストを占めている。

三番目の最後の節はコスト集約点スタックで分類されたプロファイルを表示している。これはプログラムの呼び出し木とだいたい同じである。上記の例では、コストの高いfibの呼び出しがmain由来のものであることが明らかになっている。

プログラムの特定の部分の時間と確保量は二種類が表示されている。「individual」はこのコスト集約点スタックに相当する部分のコードが消費したものだけを示す。「inherited」はこのノードの子が消費したものも全て含む。

例を少し変えると、コスト集約点スタックの有用性がより良く分かるようになる。

main = print (f 30 + g 30)
  where
    f n  = fib n
    g n  = fib (n `div` 2)

fib n = if n < 2 then 1 else fib (n-1) + fib (n-2)

このプログラムを前と同じようにコンパイル・実行し、新しいプロファイル結果を見てみる。

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

MAIN        MAIN                    102           0    0.0    0.0   100.0  100.0
 CAF        GHC.IO.Handle.FD        128           0    0.0    0.0     0.0    0.0
 CAF        GHC.IO.Encoding.Iconv   120           0    0.0    0.0     0.0    0.0
 CAF        GHC.Conc.Signal         110           0    0.0    0.0     0.0    0.0
 CAF        Main                    108           0    0.0    0.0   100.0  100.0
  main      Main                    204           1    0.0    0.0   100.0  100.0
   main.g   Main                    207           1    0.0    0.0     0.0    0.1
    fib     Main                    208        1973    0.0    0.1     0.0    0.1
   main.f   Main                    205           1    0.0    0.0   100.0   99.9
    fib     Main                    206     2692537  100.0   99.9   100.0   99.9

nfibの呼び出しをプログラム中で二回行ったが、時間を食っているのがf経由の呼び出しだということが明らかだ。mainwhere節で定義されている関数fgは、それぞれmain.fmain.gという固有のコスト集約点を与えられている。

出力の各列の実際の意味は以下の通りである。

entries

呼び出し木のこの場所に入った回数。

individual %time

呼び出し木中のこの場所で消費された時間の、総時間に対する割合。

individual %alloc

この呼び出しでなされたメモリ確保量(プロファイルによる余分は除く)の全体に占める割合。

inherited %time

呼び出し木中のこの点以下で消費された時間の、プログラムの総実行時間に占める割合。

inherited %alloc

この呼び出しとその部分呼び出しでなされたメモリ確保量(プロファイルによる余分は除く)の全体に占める割合。

加えて、RTSオプション-Pを使うと、下記の情報が追加される。

ticks

この集約点に割り当てられた生の時刻信号(tick)の数。上記の%timeはこの値から得られている。

bytes

この集約点の支配下でヒープ中に確保されたバイト数。これは上記の%allocの数値の元となるものである。

再帰的関数や相互に再帰的な一群の関数についてはどうだろうか。コストはどこに割り当てられるのか。答えはこうである。GHCは一群の関数が互いに再帰的に呼び合ったという情報は保持するが、時刻と確保の基本プロファイルにおいてはこの情報は表示されず、呼び出しグラフはある方法で平坦化されて木として表示される。すなわち、現在の呼び出しスタックの別の場所に出現する関数を呼び出してもスタックに項目は追加されず、その呼び出しのコストは呼び出し元に集積される。[11]

5.1.1. コスト集約点を手動で挿入する

コスト集約点は、単なるプログラム上の注釈である。コンパイラに-fprof-allを指示すると、INLINE指定されていない全ての関数の周りに自動的にコスト集約点が挿入される。しかし、自分でコスト集約点を挿入するのも完全に自由である。

コスト集約点の注釈の構文は以下である。

     {-# SCC "name" #-} <expression>

ここで、"name"は任意の文字列であり、これがこのコスト集約点の名前としてプロファイル出力に現れる。<expression>は任意のHaskellの式である。パース時にはSCC注釈は右側に可能な限り長く続くように解釈される。(SCCは「Set Cost Centre」(コスト集約点を設定せよ)の意である)。nameがHaskellの識別子であるなら、二重引用符は省略できる。例を示す。

     {-# SCC my_function #-} <expression>

SCCをいくつか使ったプログラムの例を示す。

main :: IO ()
main = do let xs = [1..1000000]
          let ys = [1..2000000]
          print $ {-# SCC last_xs #-} last xs
          print $ {-# SCC last_init_xs #-} last $ init xs
          print $ {-# SCC last_ys #-} last ys
          print $ {-# SCC last_init_ys #-}last $ init ys

実行すると、次のようなプロファイルが得られる。

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

MAIN            MAIN                    102           0    0.0    0.0   100.0  100.0
 CAF            GHC.IO.Handle.FD        130           0    0.0    0.0     0.0    0.0
 CAF            GHC.IO.Encoding.Iconv   122           0    0.0    0.0     0.0    0.0
 CAF            GHC.Conc.Signal         111           0    0.0    0.0     0.0    0.0
 CAF            Main                    108           0    0.0    0.0   100.0  100.0
  main          Main                    204           1    0.0    0.0   100.0  100.0
   last_init_ys Main                    210           1   25.0   27.4    25.0   27.4
   main.ys      Main                    209           1   25.0   39.2    25.0   39.2
   last_ys      Main                    208           1   12.5    0.0    12.5    0.0
   last_init_xs Main                    207           1   12.5   13.7    12.5   13.7
   main.xs      Main                    206           1   18.8   19.6    18.8   19.6
   last_xs      Main                    205           1    6.2    0.0     6.2    0.0

5.1.2. コストの配分規則

プロファイルを有効にしてプログラムを実行している間、GHCは舞台裏でコスト集約点スタックを管理し、発生したあらゆるコスト(メモリ確保量と時間)をその時点でのコスト集約点に配分する。

機構は単純である。プログラムがSCC注釈の付いた式{-# SCC c -#} Eを評価するときはいつも、cがその時点のスタックにプッシュされ、このスタックへの進入回数に1が加算される。このスタックを保存したり復元したりする必要があることもある。特に、プログラムがサンク(lazyな中断)を作るとき、現在のコスト集約点スタックがサンクに保存され、そのサンクが評価されるときに復元される。こうすることで、コスト集約点スタックはGHCが実行時に実際に使う評価の順番とは独立になる。

関数呼び出しに際しては、GHCは呼ばれる関数に保存されているスタック(これは最上位の関数については空)を取り出し、それをその時点のスタックの後ろに連結する。このとき、その時点のスタックのprefixであるようなprefixは全て無視する。

遅延された計算すなわちサンクが、作成された時にその時点のスタックを捕捉することは先に言及した。最上位のサンクについてはどうか?これらはプログラムがコンパイルされたときに「作成」されるのだから、どんなスタックを与えるべきか?最上位のサンクを指す述語はCAF(Constant Applicative Form; 定作用形)である。GHCはモジュール中の全てのCAFに単一のコスト集約点M.CAFを与える。ここでMはそのモジュールの名前である。それぞれのCAFに異なるスタックを与えることも可能であり、-fprof-cafsオプションを使う。

[10]

-fprof-autoは、GHC 7.4.1より前は-auto-allという名前だった。

[11]

この方針はGHC 7.4.1で微妙に変わり、これからさらに変わるかもしれないことに注意。意見歓迎。