viewprofでGHCの.profファイルを見やすくする
GHCの時間・メモリ割当プロファイリングは、Haskellプログラムがどこで時間を使っているか、またどこでメモリ割当をたくさんしているのかを、コスト集約点（cost center）をノードとする木構造で表示してくれる。
このプロファイラが生成するレポートは、プログラムの規模に応じて大きくなるため、大きなプロジェクトではボトルネックがどこにあるのか一瞥しただけでは分かりにくくなる。
この問題を解決するためにviewprofというテキストベースのビューアを作っている。まだ作りかけで表示があまりに素っ気なかったり、必要な機能が足りないのだけど、試すことはできる。
使い方
maoe/viewprofをcloneしてstack installでviewprofコマンドがインストールされる。例えばghc-prof-flamegraphの紹介記事に出てくるこのhoogleのプロファイル結果をviewprofで見てみる。
% wget https://s3.amazonaws.com/download.fpcomplete.com/francesco/hoogle.prof
% viewprof hoogle.prof
このビューで表示されているのは、元のレポートの木構造をコスト集約点ごとにまとめて時間コストの高い順に並べたもので、元のレポートでいうところの
COST CENTRE MODULE %time %alloc
myParseDecl Input.Type 29.3 21.8
writeItems.\.\.bs Output.Items 22.9 21.9
pretty General.Util 13.5 15.4
rnf Input.Type 3.6 3.9
generate.f Action.Generate 3.1 7.9
stringShare Input.Hoogle 2.9 0.1
tarballReadFiles General.Util 2.1 2.6
parseHoogle Input.Hoogle 2.1 3.8
parseHoogle.f Input.Hoogle 2.0 0.5
downloadFile.\ Input.Download 2.0 0.3
gfoldl Input.Type 1.8 0.7
outputItem Output.Items 1.2 2.1
heirarchy.other Input.Hoogle 0.6 1.3
encodeBS General.Store 0.3 7.0ここの部分を木構造から再計算したものといってもいい。キーバインドは次の通り。
- 上下またはj/kでカーソル移動
- tで時間コスト順、aで空間コスト順にソート
- enterでカーソル下のコスト集約点の呼び出し元ごとのブレイクダウンを表示
- xで現在のビューを閉じる
- qまたはescapeでアプリケーションを終了する
キーバインドは今後変わる可能性がある。あとビューポートの実装をしていないのでスクロールはまだ出来ないことに注意。Ctrl-Cのハンドリングなどもまだしていない。
特徴
.profファイルを可視化するツールはすでにいくつか存在している。
最初の3つは木構造をいかに可視化するかに注力している。viewprofは木構造をそのまま表示するのではなく、コスト集約点ごとにまとめてフラットにする。これはなぜか。例えば先のhoogleのプロファイル結果で、General.Util.prettyというコスト集約点は複数箇所から呼び出されていて、それぞれの呼び出しでの時間コストを合計すると上の13.5%となる。最適化の際にボトルネックを探しているときに木構造だけを見ていると、それぞれの呼び出しでの時間コストは小さいが、広く使われているために合計の時間コストが大きくなるようなコスト集約点を見つけるのが難しい。コスト集約点ごとにまとめれば真にボトルネックとなっている箇所を特定しやすい。
上のツールの中ではmkotha/viewprofは異色でテキストベースであることに加えて、コスト集約点上でrを押すと、そのコスト集約点の呼び出しグラフ一覧を表示できるボトムアップモードがある。これはとても便利で、例えば先のhoogleのプロファイル結果でいうと、General.Util.prettyどこから呼ばれたときに最も時間が掛かっているかが一目でわかる。問題はこのツールがCommon Lispで実装されていて、門外漢にはインストールが難しい。今回作っているviewprofは元々mkotha/viewprofをHaskellに移植しようと思ったのが発端で、名前やボトムアップ機能はここから影響を受けている。
viewprofで実際にボトムアップモードを使ってみよう。hoogle.profを開いて、カーソルをGeneral.Util.prettyまで移動する。ここでenterを押すとこのように表示される。
このビューから次のことがわかる。
- Genreal.Util.prettyはプログラム全体の時間コストのうち13.5%、空間コストの内15.4%を占めている
- この関数は4箇所から呼ばれていて、特に85.2%がInput.Type.showItemからの呼び出しに費やされいる。これはプログラム全体でいうと11.5%に相当する。
- 同様に空間コストは81.2%がshowItemからの呼び出しで、これはプログラム全体の12.5%に相当する。
- 以下同様
つまりGenral.Util.prettyを最適化するならばInput.Type.showItemでの使われ方を見れば良いことがわかる。
今後
ひとまず動くまでは作ったので、今後はスクロールの対応、呼び出しスタックの表示、簡単なグラフ機能の追加、細かいビューの改善などを予定している。あと表示が遅いのも直す。
手元に環境がないのでWindowsで動くかはわからない。おそらくviewprofが使っているbrickが依存しているvtyはWindowsに対応していないようなので動かないと思われる。
実際にHaskellでプロファイルを取った際には是非試してフィードバックをしてもらえると嬉しい。
