PR

 プログラムの性能を効率化するために最も大切なことは,ボトルネックになっている部分を見つけ出すことです。ボトルネックを考慮せずに闇雲に効率化しても,労力に見合った成果は得られません。処理全体のうち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 v

 newはハッシュ・テーブルを作成する関数です。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

~ 略 ~