2011年04月07日


広告


SNES9X最新版をPSPに移植してみる(8) gprofでプロファイリング

そんな訳でrukaさんのページのコード実験室にならって、うちのsnes9x君の戦闘能力を調べてみました。

Demo1.16の222MHzですね、これをフルフレーム(FrameSkip 0)で20秒間に何フレーム書き換えるのかを計ってみましたが、270ぐらい...
まだサウンドもならしていないのに、実験室のベース(SNES9X 1.43+uoSNES9X0.02y28ノーマル)の696の半分もいかへん...
fps換算で13.5fpsですね。ちなみにAutoskipだと、ものすごい勢いでスキップされまくりで2fps。「2fpsで十分ですよ、勘弁してくださいよ。」な感じです。

とりあえずどこがどれだけ遅いのか気になるところでありますので、gprof(GNUプロファイラ)でプロファイリングしてみました。

一つはまったのは、Makefileに以下があるとこのスレのtheHobbitさんのように sceKernelRegisterExitCallbackだけの寂しいプロファイリング結果に終わります。

BUILD_PRX = 1

psplink経由で起動させるために、prxの生成が必要ですが、gprofを使うときは止めるしかなさそうです。そもそもprxってなんやねん。

そんな訳で、以下の様なプロファイリング結果になりました。
gmon.out.txt

最初に関数名がずらずらと並んでいるのが、遅いやつワースト10です。10以上余裕でありますけど。
こんなやつですね。

Each sample counts as 0.001 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
32.54 22.59 22.59 13685895 0.00 0.00 _ZL18S9xCheckInterruptsv
8.91 28.78 6.19 5988990 0.00 0.00 _ZL10Immediate810AccessMode
7.71 34.14 5.36 7265918 0.00 0.00 _ZL6Op80E0v
6.01 38.31 4.17 6 0.70 0.70 _makepath(char*, char const*, char const*, char const*, char const*)
5.00 41.78 3.47 2912934 0.00 0.00 SPC_DSP::voice_V4(SPC_DSP::voice_t*)
4.70 45.05 3.27 3137005 0.00 0.00 SPC_DSP::voice_V3c(SPC_DSP::voice_t*)

最初のEach % timeが全体の何%をしめているか。一行目のS9xCheckInterruptsさんは全体の32%も占めています。self secondsは何秒かかっているか。cumulative secondsは累積秒です。selfcallsは何回呼ばれたかです。こいつが大きいやつを高速化すると効果絶大です。

その次がコールグラフで、こんなやつです。

Call graph (explanation follows)


granularity: each sample hit covers 2 byte(s) for 0.00% of 69.44 seconds

index % time self children called name
0.04 38.31 1/1 _main [2]
[1] 55.2 0.04 38.31 1 main [1]
0.00 36.40 419/419 S9xMainLoop() [3]
0.05 1.24 1/1 CMemory::LoadROM(char const*) [38]
0.00 0.50 2/2 S9xGraphicsInit() [52]
0.07 0.00 1/1 CMemory::Init() [109]
0.02 0.03 5016/5016 S9xReportButton(unsigned int, bool) [130]
0.00 0.00 1/1 CMemory::LoadSRAM(char const*) [279]
0.00 0.00 1/1 S9xInitSound(int, int) [288]
0.00 0.00 1/1 S9xInitAPU() [289]
0.00 0.00 1/2 S9xLoadCheatFile(char const*) [277]
0.00 0.00 1/1 _ZL13InitJoysticksv [309]
0.00 0.00 2/8 S9xExit() [312]
0.00 0.00 420/420 S9xSetSoundMute(unsigned char) [643]
0.00 0.00 419/462 S9xStringInput(char const*) [642]
0.00 0.00 4/10 S9xReRefresh() [658]
0.00 0.00 1/1 CallbackThread(unsigned int, void*) [673]
0.00 0.00 1/2 S9xSetRenderPixelFormat(int) [662]
-----------------------------------------------

[2] 55.2 0.00 38.35 _main [2]
0.04 38.31 1/1 main [1]
-----------------------------------------------
0.00 36.40 419/419 main [1]
[3] 52.4 0.00 36.40 419 S9xMainLoop() [3]
5.36 30.95 7265918/7265918 _ZL6Op80E0v [4]
0.05 0.00 418/418 S9xSyncSpeed() [123]
0.04 0.00 804/1601 S9xSetPCBase(unsigned int) [99]
-----------------------------------------------
5.36 30.95 7265918/7265918 S9xMainLoop() [3]
[4] 52.3 5.36 30.95 7265918 _ZL6Op80E0v [4]

これは、どの関数から別の関数が呼ばれていって、どれくらい時間をくっているかを示しているのですが、説明が面倒というか見ればわかるぢゃん?とかここまで書いて

うわーすげー揺れた。みなさん大丈夫でしょうか。

失礼しました。
とかここまで書いて説明が面倒になってくるわけで、なんかうまい説明ないかとググっていたらこんなのを見つけました。
大元はこれですね。

gprofの出力結果を食わせて、グラフ化してくれるpythonスクリプトなんてものがありました。早速試してみました。
output.png
うわーすげー。

これを見れば、どんな流れのところが遅いかよくわかります。
_main->main->S9xMainLoopという流れが時間食っている流れですね。関数名のすぐ下が自分の先でどれだけ時間をくっているか、その下のカッコつきの%はその関数自身がどれだけ時間をくっているか、その下の数字xはその関数が何回呼ばれたか、ですね。

そんな訳で、プロファイラを使うとある程度目安をつけて高速化作業を行うことができます。(いや、実際にはそう簡単にはいかない訳ですが...)




タグ:SNES9X PSP
posted by ひっそりぃ at 2011/04/07 23:57 | Comment(0) | TrackBack(0) | SNES9X for PSP | このブログの読者になる | 更新情報をチェックする
この記事へのコメント
コメントを書く
お名前:

メールアドレス:

ホームページアドレス:

コメント:


この記事へのトラックバック
×

この広告は180日以上新しい記事の投稿がないブログに表示されております。