前回説明した，並列プログラムを高速化するための原則は，あくまで基本方針にすぎません。実際には，並列プログラムの動作を確認し，効率的な処理を行っているかどうかを調べる必要があります。効率的でないなら，どこに問題があるのかを調べて改良しなければなりません。
そこで今回は，GHCの性能測定機能や並列プロファイラなどを使って，並列プログラムの振る舞いに関する情報を得る方法を説明します。
ランタイム・システムの機能を使う
第45回で説明したランタイム・システム（RTS）では，-threadedオプションを付けてマルチスレッド版RTSを利用するプログラムをビルドすると，並列プログラムの振る舞いを示す追加情報を提供してくれるようになります。
どのような情報が出力されるかを確かめてみましょう。ここでは，並列プログラムの例として，前回定義したqsortPar関数を実行するプログラムを使用します。
import QSortPar main = do let xs = [0..1700000] print $ qsortPar 100 (xs::[Int])
$ ghc -O2 -threaded -rtsopts ParallelTest.hs [1 of 2] Compiling QSortPar ( QSortPar.hs, QSortPar.o ) [2 of 2] Compiling Main ( ParallelTest.hs, ParallelTest.o ) Linking ParallelTest ...
マルチスレッド版RTSでは，-sオプションを指定することで，並列プログラムの振る舞いを示す情報が表示されます。
$ ParallelTest +RTS -N -s
～ 略 ～
Tot time (elapsed) Avg pause Max pause
Gen 0 2054 colls, 2053 par 2.98s 1.05s 0.0005s 0.0025s
Gen 1 15 colls, 15 par 5.19s 1.75s 0.1167s 0.2525s
～ 以下略 ～第45回ではGCの「* par(parallel)」という項目が0になっていましたが，今回はGCが並列処理を行った回数が示されています。第45回の出力とは異なり，GCの内容を示す出力に，平均停止時間（Avg pause）および最大停止時間（Max Pause）という新しい項目が加わっています。これらはGHC 7.2.1で追加されたもので，マルチスレッド版RTSに特有の項目ではありません。
並列GCの全体的なワーク・バランス（work balance）を示す「Parallel GC work balance」という項目も追加されています。
Parallel GC work balance: 1.68 (236100711 / 140340686, ideal 4)
これは，「GC時に一番活発に動作していたGCスレッドでコピーされたメモリーの総量」を「GC時にコピーされたメモリーの最大量」で割った値です。並列GCの実行がどの程度並列化されているかを示しています。この値が1に近ければ，逐次実行に近いということです。逆に，十分に並列化されていれば，RTSの-N<x>オプションなどで指定したCPUコアの数に近づきます。
カッコの中の最初の数字は「GC_par_avg_copied」で，GC時に最も活発に動作していたGCスレッドでコピーされたメモリーの総量です。次の数字は「GC_par_max_copied」で，GC時にコピーされたメモリーの最大量です（参考リンク1，参考リンク2）。
「ideal *」の部分にCPUコアの数が示されています（参考リンク1，参考リンク2。
マルチスレッド版RTSで新しく提供される情報は，並列GCに関するものだけではありません。Taskという項目では，並列化されたHaskellプログラムを評価・実行するために，マルチスレッド版RTSが複数のCPUコア上の「Haskellプログラムの実行コンテキスト（HEC：Haskell Execution Context）」で実行した各処理（タスク）の情報が表示されます。
MUT time (elapsed) GC time (elapsed) Task 0 (worker) : 0.37s ( 24.29s) 0.69s ( 0.87s) Task 1 (worker) : 0.95s ( 22.20s) 2.17s ( 2.97s) Task 2 (bound) : 1.19s ( 23.05s) 1.56s ( 2.12s) Task 3 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 4 (worker) : 0.90s ( 22.11s) 2.40s ( 3.06s) Task 5 (worker) : 0.94s ( 22.06s) 2.14s ( 3.11s)
workerは，HECで実行されるネイティブ・スレッドを使った処理のうち，特定のネイティブ・スレッドと結合される必要がないものです。ユーザー・スレッドの実行やpar関数を使った並列評価などが含まれます。つまり，並列Haskellプログラムを評価・実行する「ワーカー・スレッド（worker thread）」の実行を示しています。
boundは，HECで実行される処理のうち，特定のネイティブ・スレッドと結びついて実行される必要があるタスクです。このようなタスクには，第24回で説明した結合スレッドがあります。ここでは，main関数の実行を行うmainスレッドが結合スレッドとしてboundで示されています。
forkOS関数を使用して結合スレッドを作成すれば，boundで示されるタスクを増やすことができます。
import Control.Concurrent (forkOS) import Control.Monad (replicateM) main = do forkOS $ return () -- replicateM 3 $ forkOS $ return () return ()
MUT time (elapsed) GC time (elapsed) Task 0 (bound) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 1 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 2 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 3 (bound) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 4 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 5 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s) Task 6 (worker) : 0.00s ( 0.00s) 0.00s ( 0.00s)
またマルチスレッド版RTSでは，SPARKSという項目も新しく加わっています。
SPARKS: 1716223 (66518 converted, 0 overflowed, 0 dud, 1649705 GC'd, 0 fizzled )
SPARKSでは，並列Haskellでpar関数を使って並列処理を行う場合に作成される「spark」という名前の並列化タスクに関する情報が表示されます。SPARKSは，並列Haskellを使ったプログラムで処理がどの程度並列化されているかを示す重要な項目です。ただし，SPARKSで提供されるのは並列Haskellに関する情報だけです。並行Haskellの機能であるスレッドに関する情報やデータ並列Haskellでの並列処理に関する情報は表示されません。
SPARKSで示される情報について細かく見てみましょう。SPARKSでは，並列Haskellを利用したプログラムが実際に並列で処理されたのか，それとも何らかの理由で並列化されなかったのかが表示されます。
SPARKS: 1716223 (66518 converted, 0 overflowed, 0 dud, 1649705 GC'd, 0 fizzled )
SPARKSの最初に示されている数字は，値を評価するために作成された並列タスク（spark）の総数です。続く部分は，個々のsparkがどう処理されたかを示しています。convertedは「sparkのうち実際に並列評価されたもの」，overflowedは「sparkが過剰に作られた結果，プールからあふれて並列評価されなかったもの」，dudは「sparkが作成された時点ですでに評価されていたもの」，GC'dは「利用されないため捨てられたもの」，fizzledは「すでに別のHECによって評価されたもの」の数を示しています。なお，GHC 7.0.4までは，dud，GC'd，fizzledの3項目は，prunedという項目でまとめて表示されていました。overflowedはGHC 7.4.1で追加される予定の項目です。
convertedの数が多いほど，並列プログラムとして優れています。並列Haskellを利用したプログラムを改良する際には，この値が指標になります。
なお，プログラム終了時まで残ったsparkは最後に捨てられるため，それぞれの項目の合計がSPARKSに示されるspark総数と一致しないことがあります。そこでGHC 7.4.1からは，最後に捨てられるsparkをGC'dとしてカウントすることで，spark総数と各項目の合計が一致するようになりました（参考リンク1，参考リンク2）。
sparkが，それぞれの項目に該当する場合の簡単な例を挙げましょう。
●convertedになる例
import Control.Parallel (par, pseq) main = print $ [11..15] `par` [12,13] `pseq` [365,366]
SPARKS: 1 (1 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)
[11..15]の評価が並列に行われるので，結果はconvertedになっています。
●overflowedになる例
import Control.Parallel.Strategies (parTraversable, rdeepseq, using)
main = let xs = map (+1) [0..(maxBound::Int)]
`using` parTraversable rdeepseq
in print xs作成されるsparkが必ずプールからあふれるよう，RTSの-e<N>オプションを使ってプール内の最大spark数をわざと小さくします（参考リンク）。
$ ./ParallelTest2 +RTS -N -s -e1000 ～ 略 ～ SPARKS: 1016297 (1005526 converted, 10771 overflowed, 0 dud, 0 GC'd, 0 fizzled ～ 略 ～
parTraversableを使い「map (+1) [0..(maxBound::Int)]」を並列に評価しようとすると，「Int型の最大値」個のsparkが作られます。RTSではこのように大量のsparkの作成と評価をさばき切れず，多くのsparkがプールからあふれてしまいます。この結果，プールからあふれて並列評価されなかったsparkがoverflowedとして表示されています。
●dudになる例
import Control.Parallel (par, pseq) main = print $ 11 `par` 12 `pseq` 365
import Control.Parallel (par, pseq) main = print $ [11,12] `par` 12 `pseq` 365
SPARKS: 1 (0 converted, 0 overflowed, 1 dud, 0 GC'd, 0 fizzled)
11や[11,12]は，parに渡す時点ですでに完全な形で評価されています。つまりpar関数がsparkを作成する時点ですでに評価されているので，結果はdudになります。
●GC'dになる例
import Control.Parallel.Strategies (parTraversable, rdeepseq, using)
main = let xs = map (+1) [0..(50000::Int)]
`using` parTraversable rdeepseq
in print $ head xsSPARKS: 50001 (47990 converted, 0 overflowed, 0 dud, 2011 GC'd, 0 fizzled)
parTravesableを使い「map (+1) [0..(maxBound::Int)]」を並列評価していますが，実際の処理ではリストの先頭しか要求されず，残りの要素は捨てられます。この結果，プログラムを終了するまでに実際には並列評価されなかったsparkがGC'dとして表示されています（プログラムを実行するタイミングによっては，すべての値がきちんと並列評価され，GC'dに該当するsparkが発生しないこともあります）。
●fizzledになる例
import Control.Parallel.Strategies (parTuple2, rdeepseq, using)
main = do
let xs = [0..(17000::Int)]
ys = drop 300 xs
strategy = parTuple2 rdeepseq rdeepseq
answer = (xs, ys) `using` strategy
print answerSPARKS: 2 (1 converted, 0 overflowed, 0 dud, 0 GC'd, 1 fizzled)
この例では，parTuple関数を使ってxsとysを並列に評価しています。ysの定義は「drop 200 xs」であるため，xsとysはどちらもxsの値の評価結果を必要とします。parallelパッケージでは，-feager-blackholingオプションを使って並列処理下での値の重複評価を防ぐようになっているので，xsとysのそれそれでxsの値が重複して評価されることはありません（参考リンク1，参考リンク2）。並列に評価されるxsとysのうち，一方がxsの値の評価を始めていれば，もう一方はxsの値が評価されるのを待ってその結果を利用します。xsの値の評価結果を待つ側にとっては，xsの値は別のHECによって評価されたものなので，そのxsのsparkはfizzledとして表示されます。
-sオプションの出力の末尾には，GCで実行されたスピンロックに関する情報が表示されます。
gc_alloc_block_sync: 133729 whitehole_spin: 0 gen[0].sync: 24 gen[1].sync: 78
この項目の情報は他の項目ほど整理された形にはなっていません。現状ではプログラマ向けではなく，GHCの開発者向けの情報として提供されていると考えられます。
並列プログラムのプロファイル結果では，CPU時間よりもelapsedで示される実経過時間の方が短く表示されることがあります。例えば，冒頭で見たGCの実行時間の表示がそうなっています。
Tot time (elapsed) Avg pause Max pause Gen 0 2054 colls, 2053 par 2.98s 1.05s 0.0005s 0.0025s Gen 1 15 colls, 15 par 5.19s 1.75s 0.1167s 0.2525s
並列プログラムでは，CPU時間として各CPUでの総実行時間が示されます。そのため，並列化によって性能が向上していれば，各CPUでの総実行時間よりも，実経過時間の方が短くなるのです。
ちなみに，マルチスレッド版RTSで-tオプションを使った場合には，今のところ並列プログラムに有用な情報は特に出力されません。
