プログラムの性能を効率化するために最も大切なことは，ボトルネックになっている部分を見つけ出すことです。ボトルネックを考慮せずに闇雲に効率化しても，労力に見合った成果は得られません。処理全体のうち1％の実行時間しか占めていない部分を1000倍速くしたところで，効果は些細なものです。
残念ながら，第43回で説明したcriterionや第44回で説明したprogressionでは，Haskellプログラムのボトルネックを探し出す機能は提供されていません。
一方GHCでは，プログラムを実行する際のボトルネックを探せるように，実行時の様々な情報を出力する機能が提供されています。今回は，GHCの機能を利用してボトルネックを探し出す方法を紹介します。
実行時の性能を大まかに知る
GHCのRTS（ランタイム・システム）オプションを使えば，Haskellプログラムの性能についての大まかな統計情報を得られます（参考リンク）。
ただし，注意点があります。GHC 7.0.1以降では，プロファイル関連のRTSオプションはデフォルトでは無効になりました。このため，性能についての統計情報を得るには，-rtsoptsオプションを使ってRTSオプションを有効にするか，-with-rtsopts=*オプションなどを利用してリンク時にRTSオプションを与える必要があります（詳しく知りたい方は，第43回のコラムを参照してください）。
では，RTSオプションを使って性能を測定してみましょう。性能の測定には，Data.HashTableモジュールのハッシュ・テーブルを使うプログラムを利用します（参考リンク）。
import Control.Monad (forM_)
import Prelude hiding (lookup)
import Data.HashTable (new, newHint, hashInt, insert, lookup)
main = do
m <- new (==) hashInt
forM_ [1..10000000] $ \n -> insert m n n
v <- lookup m 100
print vnewはハッシュ・テーブルを作成する関数です。new関数に対して，キー同士を比較する関数と，キーからハッシュ値を作成するハッシュ関数を与えることで，空のハッシュ・テーブルが作成されます。
Prelude Data.HashTable> :t new
new
:: (key -> key -> Bool)
-> (key -> GHC.Int.Int32)
-> IO (HashTable key val)
Prelude Data.HashTable> :t hashInt
hashInt :: Int -> GHC.Int.Int32このプログラムでは，キー同士を比較する関数として==演算子，ハッシュ関数としてhashInt関数を渡しています。hashIntは，Int型のキーを基にハッシュ値を作成する関数です。作成したハッシュ・テーブルに1から10000000までの値を順番に格納し，100番目の値を参照しています。
プログラムをコンパイルし，RTSの-t<file>オプションを与えて実行してみましょう。<file>にはファイル名または標準エラーを示すstderrを指定します。ファイル名を省略した場合にはstderrを指定したとみなされます。
$ ghc -O2 HashTable.hs -rtsopts [1 of 1] Compiling Main ( HashTable.hs, HashTable.o ) Linking HashTable ... $ ./HashTable +RTS -t ./HashTable +RTS -t Just 100 <<ghc: 888370616 bytes, 1655 GCs, 49152668/219639220 avg/max bytes residency (9 samples), 423M in use, 0.00 INIT (0.00 elapsed), 0.67 MUT (0.67 elapsed), 3.14 G C (3.26 elapsed) :ghc>>
プログラムの実行後，「<<」と「>>」に囲まれた形で，様々な情報が出力されます。それぞれの意味は以下のとおりです。
- ghc: ... bytes
- プログラムの実行中に使われたメモリーの総量
- ... GCs
- GCの回数
- ... avg/max bytes residency (... samples)
- 常駐メモリ（GC時に生存しているデータ）の平均量/最大量
- ... in use
- プログラム実行のためにOSから確保したメモリーの総量
- 処理ごとの実行時間
（CPU時間と実経過時間（(... elasped)の部分）の組として出力） - ... INIT (... elapsed)
- ランタイムの初期化に要した時間
- ... MUT (... elapsed)
- ランタイムの初期化やGCなどを除いた，処理の実行時間
- ... GC (... elapsed)
- GCに使用した時間
メモリーの総量には，GCによって再利用されたメモリーが含まれるため，確保したメモリーよりも値が大きくなります。
-t<file>オプションでは，--machine-readableオプションを追加することで，「<<」と「>>」に囲まれた平文の代わりに，以下のように詳細な情報を出力できます。
$ ./HashTable +RTS -t --machine-readable
./HashTable +RTS -t --machine-readable
Just 100
[("bytes allocated", "888370616")
,("num_GCs", "1655")
,("average_bytes_used", "49152668")
,("max_bytes_used", "219639220")
,("num_byte_usage_samples", "9")
,("peak_megabytes_allocated", "423")
,("init_cpu_seconds", "0.00")
,("init_wall_seconds", "0.01")
,("mutator_cpu_seconds", "0.64")
,("mutator_wall_seconds", "0.66")
,("GC_cpu_seconds", "3.10")
,("GC_wall_seconds", "3.24")
]第10回で説明した-s<file>オプションを使えば，より詳細な情報を出力させることができます。<file>には，-t<file>オプションと同様に，ファイル名またはstderrを指定します。ファイル名を省略した場合にはstderrを指定したとみなされます（第10回では「ファイル名を省略した場合には，<実行コマンド名>.statsというファイルが生成される」と説明しましたが，これはGHC 6.6.1の挙動です。現在は変わっているので注意してください）。
$./HashTable +RTS -s
./HashTable +RTS -s
Just 100
1,618,042,192 bytes allocated in the heap
1,685,287,488 bytes copied during GC
358,235,076 bytes maximum residency (11 sample(s))
2,541,008 bytes maximum slop
704 MB total memory in use (0 MB lost due to fragmentation)
Generation 0: 3036 collections, 0 parallel, 2.31s, 2.26s elapsed
Generation 1: 11 collections, 0 parallel, 2.14s, 2.31s elapsed
INIT time 0.00s ( 0.01s elapsed)
MUT time 0.90s ( 0.96s elapsed)
GC time 4.45s ( 4.57s elapsed)
EXIT time 0.00s ( 0.00s elapsed)
Total time 5.35s ( 5.54s elapsed)
%GC time 83.1% (82.5% elapsed)
Alloc rate 1,788,275,267 bytes per MUT second
Productivity 16.9% of total user, 16.3% of total elapsed
世代別でのGCの実行回数（Generation 0: ...とGeneration 1: ...），終了処理にかかる時間（EXIT time），全実行時間（Total time）などを含む詳細な情報が出力されています。
-s<file>オプションで出力した情報の中で，まず注目すべきなのはProductivityの部分です。Productivityは，実行時間のうち何％が実際の処理の実行に使われたかを示しています。この値が小さければ，実際の処理以外の要因で実行が遅くなっている可能性があります。
次に注目するべきなのが%GCの部分です。%GCは，実行時間のうち何％がGCに使われたかを示しています。この値が大きければ，メモリー周りに処理のボトルネックがあるといるということです。ここに示した結果では，GCの実行時間が83%と処理の大半を占めていることから，間違いなくメモリー周りに処理のボトルネックがあることが読み取れます。
ハッシュテーブルに要素を格納する際には，空きメモリーを確保するためにGCが実行されることがあります。ハッシュテーブルを使ったプログラムでは，この部分がボトルネックになることがよく知られています（詳しく知りたい方は第35回を参照してください）。
ちなみに，-S<file>オプションを使うことで，-s<file>オプションの出力に加え，GCが行われるたびにGCについての情報が出力されます。
$ ./HashTable +RTS -S
./HashTable +RTS -S
Alloc Copied Live GC GC TOT TOT Page Flts
bytes bytes bytes user elap user elap
532476 249544 253660 0.00 0.00 0.00 0.02 0 0 (Gen: 1)
536560 502148 510372 0.00 0.00 0.00 0.03 0 0 (Gen: 0)
544752 512116 778036 0.00 0.00 0.00 0.04 0 0 (Gen: 0)
～ 略 ～
524272 491572 432670916 0.00 0.00 4.52 19.08 0 0 (Gen: 0)
524272 491572 432916676 0.00 0.00 4.52 19.09 0 0 (Gen: 0)
524272 491572 433162436 0.00 0.00 4.52 19.10 0 0 (Gen: 0)
Just 100
253064 358420 433281816 0.00 0.00 4.52 19.12 0 0 (Gen: 0)
0 0.00 0.00
888,370,616 bytes allocated in the heap
1,271,109,700 bytes copied during GC
219,639,220 bytes maximum residency (9 sample(s))
2,512,700 bytes maximum slop
423 MB total memory in use (0 MB lost due to fragmentation)
Generation 0: 1646 collections, 0 parallel, 2.09s, 2.33s elapsed
Generation 1: 9 collections, 0 parallel, 1.12s, 1.33s elapsed
～ 略 ～
