« 速度 | トップページ | 再び速度 »

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
の結果はどうなるでしょうか?
トップ5位の関数から攻めていくのが常道です。

イベントマスクはどうなっているのでしょうか?当該アプリケーションをビルドした時に-gを付けましたでしょうか?

ベンチマークはどんなプログラムでしょうか?実行時間が短すぎると十分なサンプリングができなかったりしますので、実行時間を長くしたり、イベントサンプリング間隔を小さくしたりします。

-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秒くらい).
次あたりもうちょいデカいのやってみますね.

kernel-debuginfoはインストールしていますか?

49404 79.5095 no-vmlinux (no symbols)
なので、多分インストールしていないかなと思います。

vmstatなどをとってみて、sys/usr/idleの比率はどうでしょう?CPUを使い切っていないのかな。

ノートPCだとタイマ割り込みでのサンプリングなのでキャッシュミス等は測定できないかと思います。

opcontrol -l で測定できるイベントが表示されます。

ご指摘いただいた通り,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%になったりならなかったりするのは,どっかのメモリアクセスかなんかでオーバーヘッドが大きいからでしょうか.

コメントを書く

コメントは記事投稿者が公開するまで表示されません。

(ウェブ上には掲載しません)

トラックバック

この記事のトラックバックURL:
http://app.f.cocolog-nifty.com/t/trackback/163977/3688976

この記事へのトラックバック一覧です: Oprofile:

« 速度 | トップページ | 再び速度 »