プロファイラ DProf

人の書いたプログラムがボトルネックになっていたので解析に
DProfを使ってみた。
以前使ったときはSEGVしてまともに動かなかったが、今回はperl5.8の
環境なので普通に動いた。

perl -d:DProf hoge.pl
とかやると tmon.out が実行したディレクトリに出力される。
結果のフォーマットにはdprofppを使う

dprofpp だけの場合はこんな感じ。
Totalの時間との差から、実際にCPUを喰われているのは極僅かだけど、
何かしらの要因で待たされているのが判る。

Total Elapsed Time = 126.9089 Seconds
  User+System Time = 1.080796 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 4.81   0.052  0.152    551   0.0001 0.0003  IO::Socket::INET::configure
 4.16   0.045  0.045    561   0.0001 0.0001  BerkeleyDB::Common::db_sync
 3.52   0.038  0.042   1118   0.0000 0.0000  BerkeleyDB::_tiedHash::EXISTS
 3.52   0.038  0.049   1124   0.0000 0.0000  IO::Handle::new

dprofpp -r の場合はこんな感じ。
消費した実時間での集計となるので、CPUは消費してないけど遅い
といった待ちが発生している現象の場合は-r付きでの集計が役立つ。

Total Elapsed Time = 127.0740 Seconds
         Real Time = 127.0740 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 94.4   120.0 120.01    278   0.4317 0.4317  IO::Handle::read
 3.85   4.898  4.897    149   0.0329 0.0329  IO::Select::select
 0.75   0.951  0.951    561   0.0017 0.0017  BerkeleyDB::Common::db_sync
 0.06   0.081  0.267    551   0.0001 0.0005  IO::Socket::INET::configure
 0.04   0.051  0.069    557   0.0001 0.0001  IO::Socket::connect