Devel::DProf

perlスクリプトの実行速度を分析するプロファイラ。

プロファイラとは

CGIを作っていて、もう少し早くならんかなと思うことは良くあります。そんな時、やたらめったら適当にいじくっていても、それが実際スピードアップに貢献しているとは限りません。そういう時はプロファイラを使ってどの部分が遅いのか、どこを改良すればいいのかを分析するべきです。 Perlにもプロファイラが用意されています。しかし、残念ながら標準ではなくて自分でCPANからインストールしなくてはいけません。

Devel::DProf の構成

Devel::DProf には二つの部品があります。プログラム実行中にデータを収集する為のPerl モジュールである Devel::DProf と、集めたデータを整形して見やすく表示するコマンドの dprofpp です。作業の手順としては、スクリプトに組み込んだ Devel::DProf でデータを収集し、後で dproff を実行して結果を検討するという順序になります。

データを集める

マニュアルによると、プロファイラの為に次のコマンドを実行するとあります。

$ perl -d:DProf [テストしたいプログラム]

実行すると、作業ディレクトリに tmon.out というファイルが勝手に出来ているはずです。中を見ると、サブルーチンの名前のようなものが沢山並んでいます。ただ、僕のようにPerlを使う目的がほとんどCGIの人は、このやり方はちょっと使いづらいです。欲しいのはCGIとして動作した時の実行データなので、ただプロンプトから実行しても意味なしです。

そこで、仕方が無いので作業中だけ、スクリプト自身にプロファイラを組み込んでしまうことにします。分析したいCGIのきっちり一行目に、perl を呼ぶための指示があると思いますので、そこを変更します。

#!/usr/local/bin/perl -d:DProf

変更前の、#!/usr/local/bin/perl に、-d:DProf をつけるだけです。

解析結果を見る

$ dprofpp
Total Elapsed Time = 0.340252 Seconds
  User+System Time = 0.277596 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 24.5   0.068  0.094      1   0.0682 0.0936  main::customer_table
 5.76   0.016  0.015     28   0.0006 0.0005  main::get_img
 2.88   0.008  0.008      1   0.0078 0.0078  DynaLoader::dl_find_symbol
 2.88   0.008  0.008      6   0.0013 0.0013  vars::import
 2.88   0.008  0.007     15   0.0005 0.0005  main::readfile
 2.88   0.008  0.007     45   0.0002 0.0001  main::form_rate
 0.00   0.000  0.007      1   0.0000 0.0075  DynaLoader::bootstrap
 0.00   0.000 -0.000      1   0.0000      -  DynaLoader::dl_load_flags
 0.00   0.000 -0.000      1   0.0000      -  DynaLoader::dl_load_file
 0.00   0.000 -0.000      1   0.0000      -  DynaLoader::dl_undef_symbols
 0.00   0.000 -0.000      1   0.0000      -  DynaLoader::dl_install_xsub
 0.00   0.000 -0.000      1   0.0000      -  Fcntl::bootstrap
 0.00   0.000 -0.000      1   0.0000      -  Exporter::import
 0.00   0.000 -0.000      1   0.0000      -  Exporter::export
 0.00   0.000 -0.000      1   0.0000      -  main::decode

と言う風に、tmon.out あるディレクトリで dprofpp コマンドを実行すると解析結果が表示されます。この例では、main::customer_table が遅いんだなと言うことが判ります。また、表示が細かすぎてよくわからないときは、 -I オプションをつけると、子ルーチンも含めた時間が表示されるので、まだ判りやすいかもしれません。

プログラムの世界では、よく、20%の努力で80%の目標が達成されると言います。また、推測するな、計測すべしといいます。うまくツールを使って楽に仕事が進めばいいですね。

$Id: Devel_DProf.html 880 2004-11-24 06:43:26Z propella $