cpp_ac_2012_4th の particle_system そのもののベンチマーク; time, gprof, oprofile
Related Entries
Introduction
さて、先日書いた particle_system について最適化を進めてみようと思います。その為には particle_system 自体について、どこが全体の動作に対してボトルネックとなっているのかなど知らないと闇雲で場合に寄っては無駄な最適化を試みてしまうかもしれません。そんな訳で、今回は particle_system のベンチマークを行います。用語としてはベンチマークというよりはプロファイリングですね。
Contents
- particle_system::updateをN回ループしてtimeで計る; 最も単純で簡単な性能評価
- 1.を gprof で計る; プロファイリングツールの活用
- OProfile で計る; 高機能プロファイリングツールを試す
1. particle_system::updateをN回ループしてtimeで計る; 最も簡単にできる単純な性能評価
source
何という事は無い、単に particle_system を生成し、 particle_system::update を コマンドライン引数で指示された回数だけ呼び付けるだけ。
工夫があるとすれば、コンソールが「今何回目」で溢れても面白く無いのでエスケープシーケンスを用いて、「今何回目を出力」、「改行＋フラッシュ」、「1つ上の行へ移動」とかstd::coutに流しているくらい。本題にはほぼ関係無い。ほぼ、と言うのは、標準出力への出力コストが厳密な particle_system それ自体のベンチマークに対しては余計なコストであり測定に厳密には誤差を生じる原因となる点だが、今回はそもそも明らかに particle_system::update の負荷の方が大きいので、視覚的な実行状況の分かりやすさの為に出力を設けた。
もののついで、 Makefile を用意したので、
% make ...
と、すれば o3 o2 o1 o0 の各実行ファイルが生成される。それぞれ -O3 -O2 -O1 -O0 最適化レベルの実行ファイルである。
time コマンド
GNU timeに任意のコマンドを指示すると、その実行結果について簡単なプロファイルを得られる。
実は time コマンドは2種類ある。正確に言えば/usr/bin/timeなるコマンドが1つ、もう1つは伝統的にシェルが内蔵するtime内部コマンド。シェル内蔵のtimeが普通は優先される。
- シェル内蔵版time
% time sleep 1 sleep 1 0.00s user 0.00s system 0% cpu 1.005 total
- /usr/bin/time
% /usr/bin/time sleep 1 0.00user 0.00system 0:01.00elapsed 0%CPU (0avgtext+0avgdata 3072maxresident)k 0inputs+0outputs (0major+239minor)pagefaults 0swaps
実は /usr/bin/time には --verbose オプションがあり、有効にするとこれだけでも優秀なプロファイラーを手に入れた気がしてくる。
% /usr/bin/time --verbose sleep 1 Command being timed: "sleep 1" User time (seconds): 0.00 System time (seconds): 0.00 Percent of CPU this job got: 0% Elapsed (wall clock) time (h:mm:ss or m:ss): 0:01.00 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 3072 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 0 Minor (reclaiming a frame) page faults: 240 Voluntary context switches: 2 Involuntary context switches: 2 Swaps: 0 File system inputs: 0 File system outputs: 0 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 4096 Exit status: 0
さて、紹介しておいて何だが、今回はシェル組み込み版のtimeで十分だったりする・ｘ・
/usr/bin/time が気に入った方があればaliasでも貼っておくと良いだろう。
result
% time ./o2 1000 ./o2 34.52s user 0.01s system 99% cpu 34.587 total
と、言う訳で 34.52 秒/update×1000回掛かったらしい。つまり、 34.52 ms/update 。勿論この数値は測定環境によって異なるので、正しくは単位系は ms/update-{the machine} という事になる。
particle_systemは開始から粒子数が particle_system::num_of_initial_particles 個になるまで particles::generator_timer_time 時間毎に粒子を1つ生成する。具体的な現在の実装から言えば、粒子数256個に至るまで25ms毎に1つ粒子を生成する。粒子数が最大となるのは6,400ms、6.4秒後となる。それまでは徐々に負荷が上昇し、それから計算コストは一定となる。実際、この particle_system_tester を実行すると開始直後のカウントアップの勢いが徐々に定常状態となる様を感じられると思う。
さて、残念ながら time で知る事ができるのはこの程度（全体のメモリー消費とかも分かるけど…）である。
とは言えこれだけでも考察してみると、1ループ辺りの平均計算時間が 34.52ms では 28.97 frames/sec と言う事になり、 particle_system は現状でも 60 FPS には遠いが、 30 FPS 程度の性能はこの計算機においては出せていた事は分かる。つまり、実際には 6.8 FPS 弱（≈ 147.1 ms/frame）に留まっていたボトルネックのうち、もしかしたら particle_system::updateの負荷は 34.52/147.1 ≈ 23.47% 程度なもので、残り76.53%は別の原因ではないかという推測はできる。
とは言え、この推測は Native-client と通常のPCとを比較しており、計算機が違い、naclのPCに対するオーバーヘッドがどれほどか正しく評価しなければ単純に次元を加減算して良いものではない。
…実際問題から言うと、恐らく nacl --(JSON)--> JS のインターフェースが激烈に重くなっている主因な気はするが…。何せ 160×90=1440 個のR8G8B8の文字列情報を投げ付けて、それをJS側でJSON.parseしてオブジェクトに復元している。更にその後にcanvasのcontextに矩形描画命令を160×90回発行するループがある。そこは今回は測っていないので現段階では直感でしか無いが、恐らく負荷の76.53%の4/5ほどJSONインターフェース、残りが描画処理ではないかと思う。次回はC++の記事の本論ではないが、JS側のプロファイリングも行いたい。
2. 1.を gprof で計る; プロファイリングツールの活用
さて、ゴチャゴチャ書いたものの、結局のところ、 particle_system の内部のボトルネックは time だけでは分からない。ここで少し前ならば バグベアード - extra - C++ - TrickLibrary を紹介したかったのだけど、C++11環境ではどうも上手く召喚できない。
1つの方法として、プロファイリング対象としたいスコープでロガーを仕掛ける事も考えられるが、ソースコード全体にロガーを仕掛けて回るのは面倒なのでBugbeardの様な悪魔が居なければちょっと自分でちまちまロガーを仕込むのは面倒。
と、言う訳で安直にGNU gprofする。g++のオプションに`-pg`を追加して、それを実行して出力される gmon.out を gprof に掛ければプロファイルが見れる…はずだった。
Makefileにgprof用のオプションも用意しておいたので、`make o2-gprof`とかするとプロファイル作成まで全自動という仕掛けはして置いた。Makefileには以下の様に o0-gprof ほか o1, o2, o3 について用意した。o0の場合のみ負荷が尋常じゃないのでループ回数は100回、他は1000回にしてある。
o0-pg: g++ -std=c++11 main.cpp -o o0-pg -pg -O0 o0-gprof: o0-pg ./o0-pg 100 && mv gmon.out o0-gmon.out && gprof ./o0-pg o0-gmon.out > o0-gprof.log
`make o2-gprof`でビルド、実行、gprofによるプロファイル作成まで行う。
% make o2-gprof
しかし、どうやら私の試す環境では、O2最適化した場合gprofではまともにプロファイリングできない様で、役に立つ結果がまるで出なかった。
% cumulative self self total time seconds seconds calls Ts/call Ts/call name 0.00 0.00 0.00 1 0.00 0.00 _GLOBAL__sub_I_main 0.00 0.00 0.00 1 0.00 0.00 std::vector<std::vector<WonderRabbitProject::particle_system_tester::particle_system::pixel, std::allocator<WonderRabbitProject::particle_system_tester::particle_system::pixel> >, std::allocator<std::vector<WonderRabbitProject::particle_system_tester::particle_system::pixel, std::allocator<WonderRabbitProject::particle_system_tester::particle_system::pixel> > > >::_M_default_append(unsigned long)
まるでプロファイリングできていない。この2件のエントリーしか取れていないので役に立たない。たぶん setitimer システムコールを使って簡単なプロファイラを作る - bkブログ に書いてあるタイマー都合なのかと思う。
ちなみにo0の場合はそれなりにプロファイルが取れる。
% cumulative self self total time seconds seconds calls ms/call ms/call name 6.73 2.85 2.85 100 28.50 422.60 WonderRabbitProject::particle_system_tester::particle_system::update_pixels() 5.84 5.32 2.47 218160202 0.00 0.00 WonderRabbitProject::particle_system_tester::particle_system::vector2::vector2(WonderRabbitProject::particle_system_tester::particle_system::vector2 const&) 5.69 7.73 2.41 290928961 0.00 0.00 boost::operators<WonderRabbitProject::particle_system_tester::particle_system::vector2, WonderRabbitProject::particle_system_tester::particle_system::vector2>::operators() 5.20 9.93 2.20 290928961 0.00 0.00 boost::totally_ordered<WonderRabbitProject::particle_system_tester::particle_system::vector2, boost::integer_arithmetic<WonderRabbitProject::particle_system_tester::particle_system::vector2, boost::bitwise<WonderRabbitProject::particle_system_tester::particle_system::vector2, boost::unit_steppable<WonderRabbitProject::particle_system_tester::particle_system::vector2, boost::detail::empty_base<WonderRabbitProject::particle_system_tester::particle_system::vector2> >, boost::detail::empty_base<WonderRabbitProject::particle_system_tester::particle_system::vector2>, boost::detail::true_t>, boost::detail::empty_base<WonderRabbitProject::particle_system_tester::particle_system::vector2>, boost::detail::true_t>, boost::detail::empty_base<WonderRabbitProject::particle_system_tester::particle_system::vector2>, boost::detail::true_t>::totally_ordered() 4.84 11.98 2.05 290928961 0.00 0.00 boost::totally_ordered1<WonderRabbitProject::particle_system_tester::particle_system::vector2, boost::integer_arithmetic<WonderRabbitProject::particle_system_tester::particle_system::vector2, boost::bitwise<WonderRabbitProject::particle_system_tester::particle_system::vector2, boost::unit_steppable<WonderRabbitProject::particle_system_tester::particle_system::vector2, boost::detail::empty_base<WonderRabbitProject::particle_system_tester::particle_system::vector2> >, boost::detail::empty_base<WonderRabbitProject::particle_system_tester::particle_system::vector2>, boost::detail::true_t>, boost::detail::empty_base<WonderRabbitProject::particle_system_tester::particle_system::vector2>, boost::detail::true_t> >::totally_ordered1() ...
それなりというか大量に取れている。とりあえず vector2::vector2(const vector2&) 呼び過ぎって事は確かな様だけど、実際それはコンパイラーの最適化で割と消えている気はする。しかし比較対象のプロファイルも取れていないので、なんとも。
3. OProfile で計る; 高機能プロファイリングツールを試す
と、言う訳で gprof ではまともにプロファイルを取れないので OProfile - A System Profiler for Linux (News) を試す事に。openSUSE-12.2のリポジトリーにもエントリーがあるので `zypper in oprofile` などしてさっくり入れる。
ちなみにOProfileについてはopenSUSEの日本語ドキュメントがあった。
さて、この手順も参考にしつつ、差し当たり`alias opcontrol="sudo opcontrol"`とかaliasも張りつつ、
% cp /boot/vmlinux-`uname -r`.gz /tmp % gunzip /tmp/vmlinux*.gz % opcontrol --vmlinux=/tmp/vmlinux*
これは問題なく出来た。続いてstartを試みるとエラーに遭遇してしまった。
% opcontrol --start Using default event: CPU_CLK_UNHALTED:100000:0:1:1 Error: counter 0 not available nmi_watchdog using this resource ? Try: opcontrol --deinit echo 0 > /proc/sys/kernel/nmi_watchdog
実はちょっと良く分かって居ないが、とりあえずエラーと共にお試しあれと表示のある通りにすると、
% sudo su % opcontrol --deinit % echo 0 > /proc/sys/kernel/nmi_watchdog % exit
以降は start 可能になった。
% opcontrol --start Using 2.6+ OProfile kernel interface. Reading module info. Using log file /var/lib/oprofile/samples/oprofiled.log Daemon started. Profiler running.
早速測る。
% opcontrol --reset && ./o2 1000 && opcontrol --stop Signalling daemon... done Stopping profiling.
dumpしてopreportを出力してshutdownしとく。
% opcontrol --dump
% opreport ./o2 > o2-op.profile
% opcontrol --shutdown
Killing daemon.
レポートを見る…(´・ω・｀)
% cat o2-op.profile CPU: AMD64 family10, speed 3e+06 MHz (estimated) Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000 CPU_CLK_UNHALT...| samples| %| ------------------ 1046820 100.000 o2 CPU_CLK_UNHALT...| samples| %| ------------------ 1046801 99.9982 o2 19 0.0018 [vdso] (tgid:7443 range:0x7ffff53ff000-0x7ffff5400000)
(´・ω・｀)
`opannotate`も試してみる。
% opannotate -s ./o2-g > o2-op.annotate % cat o2-op.annotate ...
こちらではソース中と対応付けてどこが何回呼ばれてどれほどのCPU時間を要したのか表示が出ていた。例えば、
: struct color_type{
: double r, g, b;
: public:
: color_type& operator+=(const color_type& t)
52615 5.0248 : { r += t.r; g += t.g; b += t.b; return *this; }
:
: color_type operator*(const double v)
86370 8.2485 : { return { r * v, g * v, b * v }; }とか。
oprofileについてもMakefileに仕込んで置きました。`make o2-op`とかすると、-g付きのビルド、oprofileを開始、実行、oprofileを停止、oprofileからdump、opreportとopannotateを実行、と一連の操作を自動的に行います。`make oprofile`とかすると -O3 -O2 -O1 -O0 について全自動で処理します。
o2-g: g++ -std=c++11 main.cpp -o o2-g -g -O2 o2-op: o2-g sudo opcontrol --start && sudo opcontrol --reset ./o2-g 1000 sudo opcontrol --stop sudo opcontrol --dump sudo opcontrol --shutdown opreport --demangle smart ./o2-g > o2-op.profile opannotate -s ./o2-g > o2-op.annotate
…と、本来であればプロファイリングからボトルネックをどうのこうの〜としようと思っていましたが、今日はもう遅いので、このプロファイルからどうのこうの〜はまた今度にして寝ます〜おやすみなさーいｚｚ
