PR

プロファイルを取得する

 では,GHCのプロファイル機能を使ってプログラムの性能を測定してみましょう。プログラムの中にプロファイルを取得する機能が組み込まれるよう,-profオプションをつけてプログラムをビルドします。

ghc -O2 -prof HashTable.hs -rtsopts

 プログラムが利用しているライブラリの中にプロファイル用ではないライブラリが含まれていれば,以下のようなエラー・メッセージが出力されます。

$ ghc -O2 -prof HashTable.hs -rtsopts

HashTable.hs:3:8:
    Could not find module `Data.Vector':
      Perhaps you haven't installed the profiling libraries for package `vector-0.7'?
      Use -v to see a list of the files searched for.

 詳細な情報を得るために,-vオプションを付けてみましょう。

$ ghc -O2 -prof -v HashTable.hs -rtsopts
Glasgow Haskell Compiler, Version 7.0.1.20101215, for Haskell 98, stage 2 booted by GHC version 7.0.1
Using binary package database: /Library/Frameworks/GHC.framework/Versions/7.0.1.20101215-i386/usr/lib/ghc-7.0.1.20101215/package.conf.d/package.cache
Using binary package database: /Users/shelarcy/.ghc/i386-darwin-7.0.1.20101215/package.conf.d/package.cache
~ 略 ~
*** Chasing dependencies:
Chasing modules from: *HashTable.hs

Recycling.hs:3:8:
    Could not find module `Data.Vector':
      Perhaps you haven't installed the profiling libraries for package `vector-0.7'?
      locations searched:
        Data/Vector.hs
        Data/Vector.lhs
        /Users/shelarcy/.cabal/lib/vector-0.7/ghc-7.0.1.20101215/Data/Vector.p_hi
~ 略 ~

 ghcは,HashTable.hsでインポートされているData.Vectorモジュールを使うために,vectorパッケージ内のファイルを参照します。ghcに-profオプションが渡されているので,参照するファイルはプロファイル版のライブラリである「Vector.p_hi」になります。ここでは,Vector.p_hiがインストールされていなかったため,エラーになっています。こうした場合には,プロファイル版のライブラリを含むようパッケージを入れ直してください。

 プログラムをビルドしたら,実行してプロファイルを取ってみましょう。-profオプションによって組み込まれた-pオプションをRTSに渡すことで,実行時に呼び出される処理の実行時間やメモリー使用量などの情報を出力できます(第9回ではメモリーの使用状況を見るために-hcオプションを使いましたが,今回は-hcオプションではなく-pオプションを使用します)。

$ ./HashTable +RTS -p

 プログラムの終了後に<実行コマンド名>.profという名前のファイルが生成されます。この場合はHashTable.profというファイル名になります。以下がそのファイルの内容です。

   Tue Jan 25 11:48 2011 Time and Allocation Profiling Report  (Final)

           HashTable +RTS -p -RTS

        total time  =        0.92 secs   (46 ticks @ 20 ms)
        total alloc = 864,569,908 bytes  (excludes profiling overheads)

COST CENTRE                    MODULE               %time %alloc

MAIN                           MAIN                 100.0  100.0


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

MAIN                     MAIN                                                   1           0 100.0  100.0   100.0  100.0
 CAF                     Main                                                 220           1   0.0    0.0     0.0    0.0
 CAF                     GHC.Show                                             214           1   0.0    0.0     0.0    0.0
 CAF                     Data.HashTable                                       168           1   0.0    0.0     0.0    0.0
 CAF                     GHC.IO.Handle.FD                                     150           2   0.0    0.0     0.0    0.0
 CAF                     System.Posix.Internals                               149           1   0.0    0.0     0.0    0.0
 CAF                     GHC.IO.Handle.Internals                              129           1   0.0    0.0     0.0    0.0
 CAF                     GHC.IO.Encoding.CodePage                             122           1   0.0    0.0     0.0    0.0

 プログラム全体の実行時間やメモリー使用量,プログラムの中で呼び出された変数や関数の実行時間やメモリー使用量,処理の呼び出し回数(2番目の表のentriesの列)といった詳細な情報が記録されています。二つの表のCOST CENTREの列には「MAIN」または「CAF」と表示されています。

 MAINはプログラム全体の実行を示します。MAINのentriesは0なので,MAINは実際には呼び出されず,MAINが呼ぶ変数や関数などが実際の処理を行っています(参考リンク)。

 CAFは「Constant Applicative Form(定作用形)」の略です。モジュールのトップレベル(大域)で定義される「12」「1+2」「*3」といった「引数を持たない式」(ラムダ抽象を除く)のことです。ここでのCAFは,定作用形に束縛された変数を示しています。

 Haskellでは遅延評価が行われるため,引数を持たない式に束縛された変数に対する評価は1回しか行われません。変数に対する2回目以降の呼び出しでは,必ずメモ化された値が使われます。したがって,CAFが複数回呼び出されていたとしても,この表にはメモ化される前の1回分の評価コストだけが表示されます(参考リンク1参考リンク2参考リンク3)。

 MAINが呼び出すそれぞれのCAFを提供しているモジュールが,MODULEの列に表示されています。しかし,モジュール名だけではどの関数を使った処理がボトルネックになっているのかがわかりません。

 そこで処理を行うのに使われた変数や関数の名前を表示させることにしましょう。-profオプションを使ったプログラム作成時に,-auto-allオプションを追加で指定することで,処理が呼び出す変数や関数の名前を表示できます。

$ ghc -O2 HashTable.hs -prof -auto-all -rtsopts
[1 of 1] Compiling Main             ( HashTable.hs, HashTable.o )
Linking HashTable ...

$ ./HashTable +RTS -p
Just 100

   Tue Jan 25 11:53 2011 Time and Allocation Profiling Report  (Final)

           HashTable +RTS -p -RTS

        total time  =        1.32 secs   (66 ticks @ 20 ms)
        total alloc = 1,184,569,936 bytes  (excludes profiling overheads)

COST CENTRE                    MODULE               %time %alloc

main                           Main                 100.0  100.0


                                                                                               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                                                 226           1  78.8   66.2    78.8   66.2
 CAF                     Main                                                 220           1   0.0    0.0    21.2   33.8
  main                   Main                                                 227           0  21.2   33.8    21.2   33.8
~ 略 ~

 Mainモジュール内で呼び出される処理として,main変数が表示されています。

 1番目の表は,HashTable.hsに定義したMainモジュールのmain変数を使った処理が,実行時間や使用メモリーのほぼ100%を占めていることを示しています。

 2番目の表には,プログラムを実行するために呼び出された変数や関数の情報が表示されています。COST CENTREの列には,「MAINからmain変数とCAFを呼び出し,CAFからmain変数を呼び出す」というコールグラフがインデントの形で示されています。また,individualの列には,呼び出された変数単独(individual)での実行時間とメモリー使用量の占める割合が表示されています。inheritedの列には,「変数から呼び出した処理での実行時間とメモリー使用量の割合」を引き継いだ(inherited),変数内の処理を行うのに必要な全実行時間と全メモリー使用量の割合が表示されています。

 この例では,MAINが直接呼び出しているmain変数内の処理が全体の実行時間の78.8%,CAFから参照されるmain変数内の処理が全体の実行時間の21.2%を占めています。CAFのinhereitendの列では,CAFから参照されるmain変数内での実行処理の割合である21.2%が,CAFを処理するのに必要な全実行時間としてそのまま示されています。MAINのinhereitendの列では,main変数とCAFでの実行時間の割合を合計した100.0%が,MAINを処理するのに必要な実行時間として示されています。