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 | このブログの読者になる | 更新情報をチェックする

SNES9X/1.52.81 for PSP WIP-1 リリース

そんな訳で、とりあえず画面が出るようになったので、SNES9X/1.52.81 for PSP WIP-1をリリースします。

ROMはhoge.smcという名前にしてEBOOT.PBPと同じディレクトリに置いておくと起動します。
GUI?なんですかそれは。
とりあえず遅いです。2fpsぐらいです。
せっかくなので、ソースも置いておきますね。

画面写真は後でひっそりぃ.comに載せておきます。色がちょっと変です。シレンの顔が青いです。

SNES9X/1.52.81 for PSP WIP-1 バイナリ
SNES9X/1.52.81 for PSP WIP-1 ソース
posted by ひっそりぃ at 2011/04/07 00:08 | Comment(3) | TrackBack(0) | SNES9X for PSP | このブログの読者になる | 更新情報をチェックする

2011年04月06日


SNES9X最新版をPSPに移植してみる(7) gdbでソースコードデバッグ

そんな訳で、前回のメモリ不足エラーは、malloc()に失敗しまくっていた様であり、unix.cppに以下を追加することで回避できた。

PSP_HEAP_SIZE_KB(-1024);

コンパイルし直して、再度チャレンジ。

host0:/> ./snes9x15281.prx
Load/Start host0:/snes9x15281.prx UID: 0x04BA5F5D Name: "snes9x/1.52.81 for PSP"
host0:/> Sound buffer size: 12800 (3200 samples)
Port 1: Pad #1. Port 2: .
Error opening the ROM file.

host0:/>

あー、ROMファイルを用意していませんでした。hissoriiはシレンジャーなので風来のシレンのROMファイルを、ホストPCの開発ディレクトリ(EBOOT.PBPが生成されるディレクトリ)に、hoge.smcとして保存します。今のところROMファイル名はhoge.smc決め打ちです。
ちなみにhissoriiはROMの吸いだしにホンコンを使用しています。楽しいホンコン愉快なホンコンホンコンホンコーン。
今度は、ROMの読み込みはパスしましたが、exceptionが発生して止まりました。

host0:/> ./snes9x15281.prx
Load/Start host0:/snes9x15281.prx UID: 0x04BA5F79 Name: "snes9x/1.52.81 for PSP"
host0:/> Sound buffer size: 12800 (3200 samples)
Port 1: Pad #1. Port 2: .
Found ROM file header (and ignored it).
Map_HiROMMap
"FURAI NO SIREN" [checksum ok] HiROM, 32Mbits, ROM+RAM+BAT, NTSC, SRAM:256Kbits, ID:AAXJ, CRC32:AF5703EE
Exception - Address load/inst fetch
Thread ID - 0x04B9D305
Th Name - user_main
Module ID - 0x04BA5F79
Mod Name - "snes9x/1.52.81 for PSP"
EPC - 0x0884B658
Cause - 0x10000010
BadVAddr - 0x08D31296
Status - 0x20088613
zr:0x00000000 at:0x08CD0000 v0:0x08D31296 v1:0x00000010
a0:0x00000008 a1:0x00008006 a2:0x00000120 a3:0x00000000
t0:0x00000000 t1:0x00000120 t2:0x08AFB150 t3:0x08BC4B45
t4:0x0BABE9D0 t5:0x08BC4B2C t6:0x00010000 t7:0x01000000
s0:0x08B2F800 s1:0x08B0E21C s2:0x08B2F868 s3:0x08B2F868
s4:0x08B00000 s5:0x08B31408 s6:0x08B2F84C s7:0x08B2F87C
t8:0xDEADBEEF t9:0xDEADBEEF k0:0x0BABFF00 k1:0x00000000
gp:0x08B27230 sp:0x0BABE9B0 fp:0x08B30000 ra:0x08832598
0x0884B658: 0x8C450000 '..E.' - lw $a1, 0($v0)

host0:/>

lw $a1, 0($v0)というアセンブリ命令の箇所でexceptionが発生したことが分かります。命令の意味は、v0レジスタ、index 0に格納されたワード(4byte)データをa1レジスタにロードする、なのですが、MIPS CPUではワードデータの読み込みは最下位バイトが、0, 4, 8, 0xcの様に4の倍数である必要があります。上記を見るとv0レジスタの最下位バイトが6なので、4の倍数ではないため例外が発生しています。
では、ここからgdbを用いて、ソースのどの部分でエラーになっているのかを調査します。
続きを読む
タグ:SNES9X PSP
posted by ひっそりぃ at 2011/04/06 00:34 | Comment(0) | TrackBack(0) | SNES9X for PSP | このブログの読者になる | 更新情報をチェックする
×

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