目次
GHCには時間及び空間のプロファイルをとるためのシステムが付属している。このシステムの目的は、「なぜ私のプログラムはこんなに遅いのか」「なぜ私のプログラムはこんなに沢山のメモリを使うのか」といった疑問に答えられるようにすることである。
プログラムのプロファイルをとるのは三つの段階からなる。
プログラムをプロファイル用にコンパイルする。これには、-profオプションと、多くの場合、自動注釈を付けるオプションの一つを付ける。-fprof-autoが最も一般的である[10]。
cabalで外部ライブラリを使っているなら、それらのライブラリをプロファイル対応付きで再インストールする必要があるかもしれない。これは典型的にはcabal install -p とする。package --reinstall
プログラムをプロファイル用にコンパイルしたら、次はプロファイルを生成するためにそれを走らせる必要がある。例えば、単純な時間プロファイルはプログラムを+RTS -p付きで走らせることによって生成できる。これはprog.profprogはあなたのプログラムの名前である(Windows上なら.exe拡張子を除いたもの)。
生成できるプロファイルには沢山の種類があり、異なるRTSオプションによって選択できる。この章の残りの部分ではこの色々な種類のプロファイルを記述する。プロファイルの中には、プログラムを実行した後にさらに別のツールで処理することを必要とするものもある。
生成されたプロファイル情報を調べ、その情報を使ってプログラムを最適化し、必要に応じて繰り返す。
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経由の呼び出しだということが明らかだ。mainのwhere節で定義されている関数fとgは、それぞれmain.fとmain.gという固有のコスト集約点を与えられている。
出力の各列の実際の意味は以下の通りである。
呼び出し木のこの場所に入った回数。
呼び出し木中のこの場所で消費された時間の、総時間に対する割合。
この呼び出しでなされたメモリ確保量(プロファイルによる余分は除く)の全体に占める割合。
呼び出し木中のこの点以下で消費された時間の、プログラムの総実行時間に占める割合。
この呼び出しとその部分呼び出しでなされたメモリ確保量(プロファイルによる余分は除く)の全体に占める割合。
加えて、RTSオプション-Pを使うと、下記の情報が追加される。
ticks
この集約点に割り当てられた生の時刻信号(tick)の数。上記の%timeはこの値から得られている。
bytes
この集約点の支配下でヒープ中に確保されたバイト数。これは上記の%allocの数値の元となるものである。
再帰的関数や相互に再帰的な一群の関数についてはどうだろうか。コストはどこに割り当てられるのか。答えはこうである。GHCは一群の関数が互いに再帰的に呼び合ったという情報は保持するが、時刻と確保の基本プロファイルにおいてはこの情報は表示されず、呼び出しグラフはある方法で平坦化されて木として表示される。すなわち、現在の呼び出しスタックの別の場所に出現する関数を呼び出してもスタックに項目は追加されず、その呼び出しのコストは呼び出し元に集積される。[11]
コスト集約点は、単なるプログラム上の注釈である。コンパイラに-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
プロファイルを有効にしてプログラムを実行している間、GHCは舞台裏でコスト集約点スタックを管理し、発生したあらゆるコスト(メモリ確保量と時間)をその時点でのコスト集約点に配分する。
機構は単純である。プログラムがSCC注釈の付いた式{-# SCC c -#} Eを評価するときはいつも、cがその時点のスタックにプッシュされ、このスタックへの進入回数に1が加算される。このスタックを保存したり復元したりする必要があることもある。特に、プログラムがサンク(lazyな中断)を作るとき、現在のコスト集約点スタックがサンクに保存され、そのサンクが評価されるときに復元される。こうすることで、コスト集約点スタックはGHCが実行時に実際に使う評価の順番とは独立になる。
関数呼び出しに際しては、GHCは呼ばれる関数に保存されているスタック(これは最上位の関数については空)を取り出し、それをその時点のスタックの後ろに連結する。このとき、その時点のスタックのprefixであるようなprefixは全て無視する。
遅延された計算すなわちサンクが、作成された時にその時点のスタックを捕捉することは先に言及した。最上位のサンクについてはどうか？これらはプログラムがコンパイルされたときに「作成」されるのだから、どんなスタックを与えるべきか？最上位のサンクを指す述語はCAF(Constant Applicative Form; 定作用形)である。GHCはモジュール中の全てのCAFに単一のコスト集約点M.CAFを与える。ここでMはそのモジュールの名前である。それぞれのCAFに異なるスタックを与えることも可能であり、-fprof-cafsオプションを使う。-ffull-laziness(-O以上でデフォルトである)を使ってコンパイルする場合、関数本体にある定数が最上位へと持ち上げられてCAFになるので、これが特に便利である。これらのCAFが何に対応するかを知るには、おそらくCore(-ddump-simpl)を参照する必要があるだろう。