にゃごすwiki

DS開発/2008-5-13

 DevKitArm r23

入れてみたところ、rename関数でコンパイルエラーが出る様になってしまった。_rename_r関数がないのが原因みたい。自分では使っていないつもりでも、luaライブラリを使うとエラーが発生します。どのみち、rename関数は動作しないっぽいので(未確認)、luaライブラリをr23で使う場合はrename関数をコメントアウトしてリコンパイルしてください。
ライブラリ更新しろって?

 プロファイリング

プロファイリングを簡単にできないかなーってネタです。
そんなの計測するソース書くだけだろ、とか思われた方には以下は読む必要ありませんが、暇なら間違いさがしでもしてみてくだされ。

いつもの様にgbadev.orgのforumを検索してみたところ、発見しました。

http://forum.gbadev.org/viewtopic.php?t=15120

ココを読めばできます。以上。
で終わりでもいいけど、おいらがたどり着いたところまで書いておきます。

用意するもの

・対象となるソース(無論、ndsファイルが作成できるもの)
・forumスレッド内にある以下のファイルをダウンロードします。
http://quake.drunkencoders.com/profiler/cyg-profile.c
http://quake.drunkencoders.com/profiler/cyg-profile.h
http://quake.drunkencoders.com/profiler/resolve
・後これ
cyg-profile-Sys.c(314)

最後のサンプルに上記のすべては含まれています。

cyg-profile.cとcyg-profile.hがプロファイラのソースとヘッダになります。
cyg-profile-Sys.cにはファイルアクセスのサブルーチンが定義してあります。
これらのソースをプロファイリングしたいプログラムと同じフォルダにおきます。
(というか、一緒にリンクされればどこにおいてあってもいいです。)

・perlが使えること

プロファイラの関数

このプロファイラから提供される関数は4つです。

プロファイラの初期化 ソースの最初に追加。

cygprofile_begin();

プロファイリング開始

cygprofile_enable();

プロファイリング中断

cygprofile_disable();

プロファイラの終了 結果をファイル(CYGLOG.TXT)に保存します。

cygprofile_end();

ソース、makefile編集

とりあえず、プロファイルしたいソースの最初にcygprofile_begin();とcygprofile_enable();を記述。
最後に、 cygprofile_disable(); cygprofile_end();を記述しておけばオッケー。
enableからdisableの間で呼び出された関数の実行時間が計測されます。

実行時間をはかるためにHBLANKをカウントする必要があるので、HBlank割り込みを定義
します。割り込み関数はcyg-profile_sys.cに定義してあります。すでに割り込みを使用している場合は、適宜修正してください。
ファイルに書き込みを行うので、libfatの初期化が必須となります。

main関数

irqSet(IRQ_HBLANK, HblankHandler);
irqEnable( IRQ_HBLANK );

int ret = fatInitDefault();

cygprofile_begin();
cygprofile_enable();
 :
計測する関数
 : 
cygprofile_disable();
cygprofile_end();

後は、Makefileやバッチファイル等を変更してコンパイルスイッチに以下のスイッチを追加します。

-finstrument-functions -mpoke-function-name 

サンプルのMakefileを使用している場合はこんな感じ。
CFLAGSの定義指定ある最後に追加します。

CFLAGSN := $(CFLAGS)
CFLAGS += -finstrument-functions -mpoke-function-name 

HBlank割り込み関数がプロファイル対象になっていると、すべての時間が割り込み関数に加算されてしまう様なので、(HBlank割り込み関数が定義されている)cyg-profile-Sys.cはプロファイリングの対象から外します。
同じくMakefileであれば、こんな感じ。

cyg-profile-Sys.o : cyg-profile-Sys.c
	echo $(notdir $<)
	$(CC) -MM $(CFLAGSN) -o $*.d $<
	$(CC)  $(CFLAGSN) -c $< -o$@

(この辺、かなりあやふやです。正しい方法を知っていたらこっそり教えてくだされ。)

ndsファイルをmakeします。

実行、整形

実機なり、エミュなりで実行します。
うまくいけば、rootにCYGLOG.TXTが作成されているはずです。
こんな感じ。

320967 02000ec8 1279 15504 15504
0 02000e78 1279 15476 15476
0 02000d8c 1279 15480 15480
5116 02000cfc 1279 15496 15496
5116 02000c6c 1279 15464 15464
5116 02000be0 1279 15432 15432
  :
  :

CYGLOG.TXTはダンプなので、見やすい形に整形します。
ダウンロードしたresolve.plはperlのスクリプトです。
以下の様なコマンドラインで実行します。
(もちろん、perlがインストールされている必要があります。WindowsならActivePerlでよいかと)

>perl resolve.pl  elfファイル  CYGLOG.TXT  > CYG.LOG

elfファイルはnds作成途中のファイルで、拡張子がelfのファイルです。
サンプルのMakefileであれば、buildフォルダに保存されています。
CYG.LOGファイルに、整形されたプロファイルデータが保存されます。
こんな感じ

starting up
Loading symbols from ..\arm9\build\fmsxDS.elf ... OK
Seen 1941 symbols, stored 1489 function offsets
	address	calls	ms	ms/call	ms/frame	lowest stack	highest stack	function name

	0x2020140	     1	    0.0636	0.064	0.000	15272	15272	InitMachine
	0x201f76c	     2	    0.7634	0.382	0.001	14104	15240	createTouchMap
	0x2007fa4	     1	    1.1450	1.145	0.002	15264	15264	InitMSX
	0x20203b0	    97	   19.0840	0.197	0.032	13648	14920	LOG
	   :
	   :
	0x2022efc	   100	    6.5522	0.066	0.011	13592	14864	copyGraph
	0x2022e80	  2400	  224.3639	0.093	0.374	13560	14832	memcpy16
	0x2022a80	  2137	   98.6005	0.046	0.164	13584	14856	fill
	0x2022958	 44712	  569.9746	0.013	0.950	13528	14800	line
	0x202265c	   672	   10.3053	0.015	0.017	13584	14856	drawText
total time 57.98, 96.64 ms per frame, 10.35 fps
done

タブで区切られているので、Excelなんかで見るとソートとかできてちょっと幸せ。
見方は、こんな感じ。(かなり適当)

address       ... 関数の定義アドレス
calls         ... 関数が呼び出された回数
ms            ... 関数が呼び出された時間(ms)
ms/call       ... 関数1回の時間(ms)
ms/frame      ... 1フレームの関数の実行時間?
lowest stack  ... スタック(謎)
highest stack ... スタック(謎)
function name ... 関数名

結局、何がわかるのか

・必要以上に関数が呼び出されていないか?(calls)
・1回の呼び出しに時間がかかりすぎていないか?(ms/call)
・どの関数に時間を多くとられているか?(ms/frame)
てなことが、わかると思います。
lowest stack、highest stackは謎ですが、スタックって言うとローカル変数(使用しているサイズとか)かな?

とりあえず、ココまで

今のところは、ココまでです。
プロファイラのソースを見た限りでは、関数のネストを処理しているっぽいんだけど、ネスト元の実行時間に反映されてないような。
もしかすると、最適化のせいかな?

間違い等あればご指摘ください。

サンプルプログラム

test_profile.zip(220)
※このサンプルプログラムは、2008年5月5日ごろにcvsから拾ったlibnds仕様になっています。古いlibndsではコンパイルエラーになると思われます。