パフォーマンス解析に関するまとめ
ここ２日ぐらい調べたパフォーマンス解析に関する調査をまとめる. 推測も含まれているので注意.
まず, 当初の目的は「Boost.Pythonを用いて作った共有ライブラリをPythonから呼び出した際のボトルネック(hot spot)を発見したい」だった.
パフォーマンス解析ツールをいくつか調べたところ, 次のような候補が考えられた.
求める条件は「共有ライブラリの解析ができること」と「call graphをvisualizeするkcachegrind形式のデータを出力できること」の2点である.
結局は, google-perftoolsを使ってめでたしめでたしなのだが, その過程で調べたことをまとめる.
sprof
この記事によるとgprofはshared libraryの解析には使えないらしいので, sprofの使用を検討した. ところが, ぱっと見まっとうなドキュメントが見当たらない.
おそらくgprofと似たような形式のデータを吐くのだろうと推測し, Profiling shared library on Linux using sprofに沿って試してみたが, Segmentation Faultが出てしまい使用できなかった. 環境によってはうまくいくのかもしれない.
oprofile
oprofileはハードウェアカウンタを利用してシステムの様々な情報を取れるらしい(キャッシュミスどれぐらいしたかとか). この辺の性質はperfと一致するのでperfの項で詳しく述べる.
oprofileは, どの関数で時間をつぶしたかの出力や, call graphの出力にも対応している. しかし, 現在Ubuntuのaptからoprofileは入れられない. その理由として, 「メンテナンスが十分にされていない(現在はされている？)」「Perfで代替がきく」などがこちらで挙げられている.
それを無視してソースをコンパイルして使ってみたのだが, どうも正常にコールグラフが出力されない. 全ての関数について[self] 100%, つまり, どこからも呼び出されていないかのような出力をしてしまう. これは推測だがFAQに「starting with OProfile 0.8. You need to be on x86 or ARM, and run a recent 2.6 kernel」とあるため, oprofile0.9.8 では正常に動作しないのではないか(本当か？). 一応, ドキュメントにあるように-fno-omit-frame-pointerフラグをひっつけてコンパイルしてもダメだった.
perf
こちらもoprofileと同様にハードウェアカウンタを利用しており, aptから入るのがうれしい.
日本語での説明や動作原理がこちらのページにまとまっており, 非常にわかりやすく勉強になる.
call graphを出力する以外のシーンで大きな力を発揮するツールだが, 今回はcall graphに関して考える. 基本的な使い方は
perf record -g コマンド名
でコマンドを実行して, パフォーマンスを記録し,
perf report --sort dso,comm -g fractal,0.5,caller | cat | less
でcall graphを観察する. こうすることでコマンドがmain.pyで, そこからmylib.soを読み込んでいるようなケースでも, mylib.so内のどの関数で時間を使っているかが計測できる. mylib.soのコンパイラオプションとして-fno-omit-frame-pointerは不要っぽい. -O3などをつけるとインライン化等の影響で結果がわかりづらくなる点には注意が必要である.
ややこしいのは perf reportにわたす引数である. これはrecordで得たperf.dataを読める形に変換するコマンドだが, これに関するドキュメントが見当たらない.
\--sortに渡しているdsoはバイナリ単位で結果をソートして表示, commはコマンド単位でソートして表示, を意味するのだが, 両方つけない場合は, 何故かツリー状になっていない結果が出力される.
\-g はcall graphを出力させるオプションで, fractalはツリー状にcall graphを出力させることを意味する. 0.5は0.5%以下の比重のものはフィルターすることを意味し, callerは(なんか表示ずれてる・・・)
--99.97%-- main --70.50%-- funcA --89.88%-- funcB
とあった場合, funcAがfuncBを呼び出していることを意味する. calleeはその逆を意味する.
なお, この出力は変な癖があるらしく「funcA -> funcB -> funcC」と呼び出していて, funcAの処理のほぼ100%がfuncBの場合
--99.97%-- funcA funcB --70.50%-- funcC
という風に%表示が省略される. このような省略はいくつかの場所で確認できる.
なお, 一度catしてからlessしているのは, ターミナルでperf reportを実行した場合, インタラクティブに結果を表示できるのだが, そのインターフェイスが使いづらいためである. 人によっては使いやすいかもしれない. その場合, Shift+Eでツリーを展開できることを忘れずに.
このように, perfの出力するcall graphは使用可能なのだが, kcachegrindに対応していなかったり, -fomit-frame-pointer環境下で動作しないため諦めた. frame-pointerについて少しだけ補足する.
frame-pointer
うーん, 正確なことを書けないので概要とリンク集を書く. 以下はさまざまな資料からの推測である.
perfなどのパフォーマンス解析ツールは定期的にプログラムカウンタをサンプリング(保存)することでパフォーマンスを解析している.
10回サンプリングしたうちの5回でプログラムカウンタがfuncAの内部を指していれば, funcAの時間使用量が50%ということだ.
perf recordに-gオプションをつけるとプログラムカウンタと同時にスタックも定期的にサンプリングするようになる. スタックを解析することで現在の関数がどこから呼ばれたか(stack trace)がわかるようになる. その方法として最も簡単なのがスタックに積まれたframe-pointerを辿っていくことだ. 詳細はこのページが非常にわかりやすい. これを使ってパフォーマンス解析ツールはコールグラフを構築する.
しかし, 最適化オプションの一つとして-fomit-frame-pointerが存在する. これはフレームポインタを利用しないことでレジスタを一つあける手法だ. 一応, このページにあるように, その状況でもstack traceが取れるようだが, perfなどはこれに対応していない. そのためcall graphに断絶が生じるようになる(funcA->funcB->funcCと呼び出されているのにfuncBが消えたりする).
じゃあ-fno-omit-frame-pointerつければいいじゃんとなるのだが, 依存しているライブラリが-fomit-frame-pointerを使ってコンパイルされている場合, 正しく動作しなくなってしまう. (そのライブラリで消費された時間は呼び出し元に加算されない？)
google-perftools
そこで今回使ったのがgoogle-perftoolsである. これはどうやら-fomit-frame-pointer環境下でも動くっぽい.
計測
export CPUPROFILE=`pwd`/blog.prof env LD_PRELOAD=/usr/lib/libprofiler.so.0 ./main.py(コマンド)
まず, CPUPROFILEでログの出力先を設定する.そしてLD_PRELOADにprofilerのライブラリファイルを指定した環境下でコマンドを実行する. こうすることで計測用のフックを仕込んでいるのだろう. フックの仕込み方はプログラム内で特定関数を呼び出したり静的ライブラリをリンクしたりと色々あるが, 今回は動的ライブラリをプロファイリングしたいのでこの手段を取った.
表示
google-pprof --callgrind /usr/bin/python blog.prof > blog.callgrind kcachegrind blog.callgrind
まず, google-pprofコマンドでkcachegrind形式にログを変換している. 「google-pprof --callgrind 解析対象のコマンド ログ」という形式で, 解析対象のコマンドが./main.pyで無いのは実際はpythonが走っているからである.
最後にkcachegrindで非常に見やすいcall graphを得ることが出来る. Googleさんありがとう！
