【Haskell】Debug.Traceとプロファイリングで幸せなデバッグ生活

Haskell Hierarchical Librariesをぼんやりと眺めていたところ、Debug.Traceが目に止まった。効率の良いデバッグとかテストに憧れを持ち始めるお年頃なので、こういうパッケージ名に弱いのかもしれない。まあ実際、Haskellでコードを書いていると、printfデバッグができなくて悶々とする場面は結構あったので悪くはない。

以下で簡単な実行例を示していく。
また、traceStackのところでプロファイリングに関連した話が登場したので、そちらも簡単に調べてみた。

使うライブラリ

Debug.Trace

デバッグモニタリング以外では絶対に使うなよ、とアナウンスされている。unsafePerfomIO(IOを外してしまう黒魔術)とかを使っているのがチラッと見えたし、確かに危なそうだなぁという気はする。

下準備

プロファイリングを行うためには、haskell-platform-profが必要。
(※trace, traceShowのみを使うなら不要)

>> apt-get install haskell-platform-prof

trace

trace :: String -> a -> a
trace <string> <expr>

-- <string> が標準出力に投げられ、<expr>は素通りする
-- debugTest.hs
import Debug.Trace

main = do $ qsort [1..5]

qsort :: (Show a, Ord a) => [a] -> [a]
qsort [] = []
qsort (pivot:xs) = trace ("pivot : " ++ show pivot) $ (qsort small) ++ [pivot] ++ (qsort large)
    where small = [x | x <- xs, x <= pivot]
          large = [x | x <- xs, x >  pivot]


-- 実行結果
-- 常に先頭がピボットになるので正しい

> ./debugTest
pivot : 1
pivot : 2
pivot : 3
pivot : 4
pivot : 5
[1,2,3,4,5]

遅延評価の関係で式が評価されないと、当然ながらトレースも起らないので注意しないといけない。

traceShow

traceShow :: (Show a) -> a -> b -> b
traceShow <expr1> <expr2>

-- show <expr1> が標準出力に投げられ、<expr2>は素通りする
-- debugTest.hs
import Debug.Trace

main = do $ qsort [1..5]

qsort :: (Show a, Ord a) => [a] -> [a]
qsort [] = []
qsort (pivot:xs) = traceShow (small, large) $ (qsort small) ++ [pivot] ++ (qsort large)
    where small = [x | x <- xs, x <= pivot]
          large = [x | x <- xs, x >  pivot]


-- 実行結果
-- ピボットは常に最小なので正しい

> ./debugTest
([],[2,3,4,5])
([],[3,4,5])
([],[4,5])
([],[5])
([],[])
[1,2,3,4,5]

以上の二つの例だが、インタープリタ上で実行すると見るも無残な結果が表示されるので注意が必要だ。(具体的には、traceの表示が関数の再帰構造に対応した場所に差し込まれる。)インタープリタの評価方法とか知らないので、これを足がかりに見てみても良いかもしれない。

traceStack

使い方および基本機能はtraceと同じ。異なる点として、-profオプションをつけてコンパイルするとtraceStackのたびにコールスタックを表示してくれる機能がある。

-- debugTest.hs
import Debug.Trace

main = print qsort [1..5]

qsort :: (Show a, Ord a) => [a] -> [a]
qsort [] = []
qsort (pivot:xs) = traceStack ("pivot : " ++ show pivot) $ (qsort small) ++ [pivot] ++ (qsort large)
    where small = [x | x <- xs, x <= pivot]
          large = [x | x <- xs, x >  pivot]


-- 実行結果
> ghc -prof -fprof-auto debugTest.hs 
> ./debugTest
pivot : 1
Stack trace:
  Main.qsort (debugTest.hs:(6,1)-(9,43))
  Main.main (debugTest.hs:3:1-27)
  Main.CAF (<entire-module>)
pivot : 2
Stack trace:
  Main.qsort (debugTest.hs:(6,1)-(9,43))
  Main.main (debugTest.hs:3:1-27)
  Main.CAF (<entire-module>)
pivot : 3
Stack trace:
  Main.qsort (debugTest.hs:(6,1)-(9,43))
  Main.main (debugTest.hs:3:1-27)
  Main.CAF (<entire-module>)
[1,2,3]

-fprof-atuoは、関数にタグ付けをしてコールスタック機能に対応させてくれるオプションだと思えば良い。次項でもう少しちゃんと解説したい。

プロファイリング

Haskellで -prof -fprof-autoをつけてコンパイルして+RTS -p をつけて実行すると、hoge.profなるプロファイリング情報を吐いてくれる。
デフォルトで得られる情報は以下。

  • トータルのコスト(実行時間、使用メモリ)
  • コスト消費の多い関数のリスト
  • コスト情報付きのコールスタック
> ghc -prof -fprof-auto debugTest.hs
> ./debugTest +RTS -p
> cat debugTest.prof

-- main = print $ qsort [1..10000] の実行結果

	Thu Sep  4 10:32 2014 Time and Allocation Profiling Report  (Final)

	   debugTest +RTS -p -RTS

	total time  =        2.51 secs   (2510 ticks @ 1000 us, 1 processor)
	total alloc = 2,804,089,648 bytes  (excludes profiling overheads)

-- 最もコストがかかっている部分
COST CENTRE MODULE  %time %alloc

qsort.large Main     65.5   99.9
qsort.small Main     34.3    0.0


-- コールツリー
                                                          individual     inherited
COST CENTRE     MODULE                  no.     entries  %time %alloc   %time %alloc

MAIN            MAIN                     46           0    0.0    0.0   100.0  100.0
 CAF            Main                     91           0    0.0    0.0   100.0  100.0
  main          Main                     92           1    0.0    0.0   100.0  100.0
   qsort        Main                     93       20001    0.2    0.1   100.0  100.0
    qsort.large Main                     95       10000   65.5   99.9    65.5   99.9
    qsort.small Main                     94       10000   34.3    0.0    34.3    0.0
 CAF            GHC.Conc.Signal          88           0    0.0    0.0     0.0    0.0
 CAF            GHC.IO.Handle.FD         87           0    0.0    0.0     0.0    0.0
 CAF            GHC.IO.Encoding          75           0    0.0    0.0     0.0    0.0
 CAF            GHC.IO.Encoding.Iconv    61           0    0.0    0.0     0.0    0.0

分割後のためのリスト走査にもっとも時間を使う点など、直感に反しない結果が出たのでなるほどという感じ。

プロファイリングの簡単な仕組み

GHCのプロファイリングでは、コストをコストセンターなるものに割り当てている。コストセンターというのは、式に付随した単なるプログラムのメタデータのようなものである。GHCはこのコストセンターのスタックを保持していて、コールツリーやコスト情報を生成することができる。

-fprof-autoオプションをつけてコンパイルすることで、あらゆる式にコストセンターのメタデータを挿入する。よって、ユーザーが書いたプログラムに対しても上記のようなプロファイリングを行うことができる。

また

{-# SCC "name" #-} <expression>

という表記を行うことで、式に対して明示的にコストセンターをつけることができる。

あとの詳しいところが気になる方は、以下の公式ドキュメントを参照して欲しい。
https://www.haskell.org/ghc/docs/latest/html/users_guide/profiling.html

まとめ