PR

並列プログラムに特化したプロファイラ

 ここまで見てきたように,マルチスレッド版RTSでは-sオプションを正常に利用できます。一方,第45回第46回で説明したGHCのプロファイル機能は,残念ながら並列プログラムの性能を分析するのには利用できません。実用上の理由から,GHCのプロファイル機能を使うための-profオプションと,プログラムを複数のCPUで動作させるための-threadedオプションを組み合わせてプログラムをビルドすること自体はできます。しかし,-profオプションが提供するプロファイル機能は,複数のCPUコアでの実行には対応していません(参考リンク)。

$ ParallelTest +RTS -N2 -p
ParallelTest: bad option -N2: only -N1 is supported with profiling
~ 略 ~
ParallelTest:

 -profオプションが提供するプロファイル機能では,コスト集約点を使って実行時間やメモリー使用量に関する情報を調べます。並列プログラムでは,コスト集約点が保持する情報が,複数のHECによって共有されるため,ロックなどを使って排他制御する必要があります。しかし,コスト集約点ごとに排他制御が存在すると,実行時の振る舞いに大きく影響します。この結果,プロファイルで得られた測定上の性能が,実際の性能とかけ離れてしまう可能性があります。また,-profオプションが提供するプロファイル機能では,処理のボトルネックを探すことはできても,並列プログラムの振る舞いを分析することはできません。

 そこでGHCでは,複数のCPUコアで動作する並列プログラムの性能を正しく分析するための並列プロファイラが別途用意されています。並列プロファイラは,-profオプションによるプロファイル機能とは異なり,どの式が実行されているかをいちいち追跡はしません。このためプロファイルにかかる負荷が比較的軽く,プロファイル用のライブラリを別途コンパイルする必要もありません。

 Haskellプログラムに並列プロファイラを組み込むには,-eventlogオプションを付けて並列プロファイラを持ったRTSとリンクするよう指定します(参考リンク)。

$ ghc -O2 -threaded -rtsopts ParallelTest.hs -eventlog

 こうして作成したプログラムに対し,並列プロファイラを実行するためのRTSオプションを与えることで,並列プログラムの振る舞いを分析するのに必要な情報が出力されます(参考リンク)。

$ ParallelTest +RTS -N -l

 組み込まれたRTSの-lオプションを使うことで,並列プロファイルの結果を「<実行コマンド名>.eventlog」という名前のファイルに出力できます。<実行コマンド名>.eventlogファイルはテキストではなくバイナリとして出力されるため,出力された情報をそのまま見ることはできません。ghc-eventsパッケージなどを利用してバイナリの中の情報を取り出す必要があります。

 ghc-eventsパッケージで提供されているghc-events-showコマンドを使うことで,バイナリの中身をテキスト形式で出力させることができます。

$ ghc-events-show ParallelTest.eventlog
Event Types:
   0: Create thread (size 4)
   1: Run thread (size 4)
   2: Stop thread (size 10)
   3: Thread runnable (size 4)
   4: Migrate thread (size 6)
   5: Run spark (size 4)
   6: Steal spark (size 6)
   7: Shutdown (size 0)
   8: Wakeup thread (size 6)
   9: Starting GC (size 0)
  10: Finished GC (size 0)
  11: Request sequential GC (size 0)
  12: Request parallel GC (size 0)
  15: Create spark thread (size 4)
  16: Log message (size variable)
  17: Startup (size 2)
  18: Block marker (size 14)
  19: User message (size variable)
  20: GC idle (size 0)
  21: GC working (size 0)
  22: GC done (size 0)
  25: Create capability set (size 6)
  26: Delete capability set (size 4)
  27: Add capability to capability set (size 6)
  28: Remove capability from capability set (size 6)
  29: RTS name and version (size variable)
  30: Program arguments (size variable)
  31: Program environment variables (size variable)
  32: Process ID (size 8)
  33: Parent process ID (size 8)

Events:
   915000: startup: 3 capabilities
   936000: created capset 0 of type CapsetOsProcess
   939000: assigned cap 0 to capset 0
   940000: assigned cap 1 to capset 0
   941000: assigned cap 2 to capset 0
  1142000: capset 0: pid 808
  1151000: capset 0: RTS version GHC-7.2.1 rts_thr_l
  1151000: capset 0: args: [".\\ParallelTest.exe","+RTS","-N3","-s","-l"]
  1197000: capset 0: env: ["=::=::\\","=C:=C:\\Doc\\realfunctional\\examples","=
~ 略 ~
elarcy","windir=C:\\Windows"]
24799897000: removed cap 0 from capset 0
24799900000: removed cap 1 from capset 0
24799901000: removed cap 2 from capset 0
24799901000: deleted capset 0

 先に述べたように,この結果にはHaskellプログラム内の各式の評価・実行は含まれていません。「スレッドの生成(Create thread)」や「GCの実行(GC working)」といった,Haskellプログラムの実行よりも低レベルの,Haskellプログラムを実際に実行するためにRTSが行った処理やRTS内で発生したイベントが出力されます。

 並列プロファイルの結果は,-lオプションを修飾するフラグを付けることで細かく制御できます。ただし,2011年8月時点での現行バージョンであるGHC7.2.1と近くリリースされる予定のGHC 7.4.1では出力結果が異なります(GHC 7.4.1の基になるGHC HEADのスナップショット版は,GHCのサイトのDownloadページから入手できます)。

●GHC 7.2.1まで

 -lオプションをsで修飾することで,並列プロファイラは「RTSのスケジューラの実行時に発生する各イベント」を追跡し,その結果を情報として出力します(参考リンク)。

修飾なし
RTSの初期化イベントを出力
s
スケジューラのイベントを出力

●GHC 7.4.1

 -lオプションに修飾フラグを付けることで,出力させる追跡情報を細かく制御できます(参考リンク)。

修飾なし
各イベントを出力(-lsgpと同等)
a
全イベントを出力(-lsgpfと同等)
s
スケジューラのイベントを出力(スレッドの作成・終了を含む)
g
GCのイベントを出力
p
sparkのイベントを一定間隔でサンプリングして出力
f
各sparkのイベントを厳密に区別して出力(その分,実行時の負荷が発生)
-
フラグを無効化
例:-l-apの場合,まずaを無効化することで全てのイベントに対する出力を無効化し,その後のpでsparkイベントだけを出力する

 なお,「並列プロファイラによって出力された追跡情報が,プログラム中のどの部分にあたるか」を判別するための手段として,GHC.ExtsモジュールでtraceEvent関数が提供されています。traceEvent関数を使うことで,追跡情報を調べるためのラベルとして任意のメッセージを追加できます。

import GHC.Exts (traceEvent)

main = do
    traceEvent "test"
    ~ 略 ~

$ ./ParalelTest +RTS -N -l

$ ghc-events-show ParallelTest.eventlog
~ 略 ~
  1615000: cap 3: test
  1676000: cap 3: stopping thread 3 (thread yielding)
  1677000: cap 3: thread 3 is runnable
  1687000: cap 3: running thread 3
  1688000: cap 0: creating thread 4
~ 略 ~

 traceEventに与えたtestというメッセージが,<実行コマンド名>.eventlogファイル内に出力されているのがわかります。

 ここまで<実行コマンド名>.eventlogファイルの出力方法について説明してきました。<実行コマンド名>.eventlogファイルの中身はRTS内でどのような処理が実行されたかを示す生データです。このような生データをghc-events-showで単純に出力しても,デバッグ以外の目的にはあまり有用ではありません。そこでghc-eventsパッケージには,<実行コマンド名>.eventlog内の情報をグラフィカルに表示するThreadScopeというツールが提供されています。ThreadScopeを使えば,並列プロファイラの出力結果をわかりやすい形で見ることができます。