Oprofile
いつも参考にさせていただいているこちらの方でOprofileによるrubyのハックをやっていまして,おもしろそうなのでfridgeにも試してみます.
はずかしながらOprofileを使うのはじめてなんですが,だいたいこんな感じでしょうか.
---------------------------
0804e505 480 2.0655 fgraph.c:0 fridge cmapFind
0804fc7c 107 0.4604 (no location information) fridge fgGetObj
0804f42e 96 0.4131 fgraph.c:0 fridge fgMapStrCnd
0804f3ee 96 0.4131 fgraph.c:0 fridge fgMapStrKey
0804f46c 61 0.2625 fgraph.c:0 fridge fgMapIntCnd
08050915 46 0.1979 fgsysobj.c:0 fridge cmapFind
0804f462 40 0.1721 fgraph.c:0 fridge fgMapIntKey
08059f0a 34 0.1463 fgsysobj.c:0 fridge fgSysObjDfMeth
0805248c 29 0.1248 fgsysobj.c:0 fridge fgSysObjArginiMeth
0804f8b2 27 0.1162 (no location information) fridge fgMakeObj
0804fda2 27 0.1162 (no location information) fridge fgMethod
0804fbc9 23 0.0990 (no location information) fridge fgSetObj
0804f7cf 20 0.0861 (no location information) fridge fgGraphGetName
08048ba8 19 0.0818 (no location information) fridge .plt
08051ce7 18 0.0775 fgsysobj.c:0 fridge fgSysObjMethIf
0805a25f 17 0.0732 fgsysobj.c:0 fridge fgSysObjArryInt
0805a3c5 15 0.0645 fgsysobj.c:0 fridge fgSysObjArryMeth
0804e598 10 0.0430 fgraph.c:0 fridge cmapUpdate
08056cf4 9 0.0387 fgsysobj.c:0 fridge gSysObjAddeMeth
08051870 8 0.0344 fgsysobj.c:0 fridge fgSysObjMethDef
0804fd55 7 0.0301 (no location information) fridge fgMethDef
0805aaae 7 0.0301 (no location information) fridge fgSysCast
0805a368 7 0.0301 fgsysobj.c:0 fridge fgSysObjArryObj
0805a9c7 6 0.0258 fgsysobj.c:0 fridge fgSysCastObjInt
08055958 5 0.0215 fgsysobj.c:0 fridge fgSysObjLeseMeth
0805a00c 4 0.0172 (no location information) fridge fgSysObjDotMeth
0804fe3a 3 0.0129 (no location information) fridge fgSetMeth
0805acc4 3 0.0129 fgsysobj.c:0 fridge fgSetValTypeObj
08052d25 3 0.0129 fgsysobj.c:0 fridge fgSysObjConstMeth
08057626 3 0.0129 fgsysobj.c:0 fridge fgSysObjSubMeth
0805a834 2 0.0086 fgsysobj.c:0 fridge fgSysCastDef
08056b37 2 0.0086 fgsysobj.c:0 fridge fgSysObjAddeInt
080557d3 2 0.0086 fgsysobj.c:0 fridge fgSysObjLeseInt
080558fb 2 0.0086 fgsysobj.c:0 fridge fgSysObjLeseObj
08051a8a 2 0.0086 fgsysobj.c:0 fridge fgSysObjMethReturn
080574b6 2 0.0086 fgsysobj.c:0 fridge fgSysObjSubInt
0804e700 1 0.0043 fgraph.c:0 fridge cmapDes
0804e0cd 1 0.0043 fgraph.c:0 fridge cmapMakeBuffer
08056ca5 1 0.0043 fgsysobj.c:0 fridge fgSysObjAddeObj
---------------------------
...なんで行番号でないんだろ.
一番たくさん文句をタレてるcmapFindという関数はハッシュ表を探査する関数なんですが,
ちょうど今やっているチューニングもこの関数をできる限り減らすというモノです.
いまやってるチューニングが終わるとようやくプログラミング言語として人並な速度になりそうな感じなんですが,
ガーベージコレクションなんかの処理を適切にやっていないので(なんて言語だ)
次はそっちの実装がいそがしくなりそうです.いつになったらβ版卒業できるんだか.うひょひょ.
わざわざoprofileによる実行ありがとうございます。
opreport -l | head
の結果はどうなるでしょうか？
トップ５位の関数から攻めていくのが常道です。
イベントマスクはどうなっているのでしょうか？当該アプリケーションをビルドした時に-gを付けましたでしょうか？
ベンチマークはどんなプログラムでしょうか？実行時間が短すぎると十分なサンプリングができなかったりしますので、実行時間を長くしたり、イベントサンプリング間隔を小さくしたりします。
投稿： hyoshiok | 2006年10月 5日 (木) 20時05分
-gオプション付けてるんですが,どうやら最適化フラグ(-O3)がついてたためいろいろデバッグ情報が消えてたみたいです.なんて間抜けな.プロセッサがtimerに設定されているのはノートPCだからでしょうか.サンプリングレートはとりあえずデフォルトでやってみました.
# opreport -l | head
samples % app name symbol name
49404 79.5095 no-vmlinux (no symbols)
3636 5.8517 fridge cmapFind
872 1.4034 libc.so.6 __GI_strcmp
725 1.1668 fridge fgGetObj
670 1.0783 fridge fgMapStrCnd
612 0.9849 libc.so.6 _IO_vfprintf_internal
611 0.9833 fridge fgMapStrKey
上位の関数はやっぱり全部ハッシュ関連ですね.cmapFindは探査関数,fgGetObjはそのラッパー,fgMapStrCndはハッシュのノードの比較関数でfgMapStrKeyはキーを返す関数...
でも5%っていうのが一番多いっていうのはあんまりサンプリングできなかったっていうことでしょうか.
今回試したのはこんなソースです
1 #!/usr/bin/fridge
2 #factorial
3
4 if arg.size<2 :
5 echo ,usage : fridge fact.fg [number]
6 return _1
7 ...
8
9 def fact1 :
10 if arg[0]<=0 return 0
11 y+=arg[0]
12 super.fact1 arg[0]-1
13 return y
14 ...
15 val=0+arg[1]
16 echo (fact1 val)
このサンプルを百万くらいまわしました(14秒くらい).
次あたりもうちょいデカいのやってみますね.
投稿： K.Tsuchiya | 2006年10月 5日 (木) 23時18分
kernel-debuginfoはインストールしていますか？
49404 79.5095 no-vmlinux (no symbols)
なので、多分インストールしていないかなと思います。
vmstatなどをとってみて、sys/usr/idleの比率はどうでしょう？CPUを使い切っていないのかな。
ノートPCだとタイマ割り込みでのサンプリングなのでキャッシュミス等は測定できないかと思います。
opcontrol -l で測定できるイベントが表示されます。
投稿： hyoshiok | 2006年10月 6日 (金) 08時13分
ご指摘いただいた通り,kernel-debuginfo入っていませんでした.これからインストールしますね.(vmlinuzとvmlinuxの違いもさっきはじめて知りました.ギャー.)
fridgeでてきとうなプログラムをまわした時のvmstatの結果です.
#vmstat 1
2 ----cpu----
3 us sy id wa
4 2 0 96 1
5 97 3 0 0
6 95 5 0 0
7 95 5 0 0
8 97 3 0 0
9 95 5 0 0
プログラムによってusrが100%になったりならなかったりするのは,どっかのメモリアクセスかなんかでオーバーヘッドが大きいからでしょうか.
投稿： K.Tsuchiya | 2006年10月 6日 (金) 20時25分