名前¶

Devel::Profile - なぜ自分のプログラムがとても遅いのか教えてくれます。

概要¶

    perl -d:Profile program.pl
    less prof.out

説明¶

Devel::Profileパッケージは、Perl用のコードプロファイラです。これは、Perlスクリプトおよび、そのスクリプトのサブルーチンの実行時間に関する情報を集めます。この情報から、どのサブルーチンが最も多くの時間を使っているか、そして、どのサブルーチンが最も頻繁に呼ばれているか調査するのに使用することができます。

Perlスクリプトのプロファイルを行うには、-d スイッチを使用してperlインタプリタを実行します。プロファイラは、デバッグ用のフックを使っています。 test.plのプロファイルを行う場合以下のようなコマンドになります。

    perl -d:Profile test.pl

スクリプトが終了時（または、実行中の一定周期的に ENVIRONMENT章を参照）、プロファイラはprof.outと言う名前のファイルに、プロファイル情報を出力します。出力されたファイルはテキストファイルで、そのまま読むことが出来ます。別のツールなどを使って読む必要はありません。

備考：統計はサブルーチン単位に行われます。コード単位ではありません。

環境変数¶

PERL_PROFILE_SAVETIME: 実行中に何秒ごとにプロファイルを出力するかを指定します。 0を指定すると終了時のみに出力します。デフォルトは二分毎です。
PERL_PROFILE_FILENAME: プロファイルを出力するファイル名を指定します。デフォルトはカレントディレクトリの prof.out です。
PERL_PROFILE_DONT_OTHER: 場合によっては、サブルーチン以外で実行されるコードの時間（例えばmainスコープの裸のコード）を集計したくないかもしれません。デフォルトでは、この部分は '<other>' という名前で集計されますがこの変数に何かの値をセットすると、集計を行いません。これは、プログラムの実行時間として集計される時間がその分少なくなる為、(訳注:実行時間の比率などに)影響を与えることに注意してください。

出力形式¶

    出力例:
    
    time elapsed (wall):   86.8212
    time running program:  65.7657  (75.75%)
    time profiling (est.): 21.0556  (24.25%)
    number of calls:       647248
    
    %Time    Sec.     #calls   sec/call  F  name
    31.74   20.8770     2306   0.009053     Configable::init_from_config
    20.09   13.2116   144638   0.000091     Configable::init_field_from_config
    17.49   11.5043   297997   0.000039     Configable::has_attr
     8.22    5.4028      312   0.017317     MonEl::recycle
     7.54    4.9570    64239   0.000077     Configable::inherit
     5.02    3.3042   101289   0.000033     MonEl::unique
    [...]

簡単な概要の後につづいて、サブルーチン毎に１行のデータがあります。

time elapsed (wall): トータル実行時間(プロファイラとプログラム)
time running program: プログラム実行時間とトータルとの比率
time profiling: プロファイラ実行時間とトータルとの比率
number of calls: プログラム内でサブルーチンがコールされた総数

サブルーチン毎の行データは以下です。

name

サブルーチンの名前

%Time

サブルーチン実行時間の全体との比率

Sec.

サブルーチン実行時間の合計

#calls

サブルーチン呼出回数

sec/call

サブルーチン一回あたりの実行時間平均

F

フラグ

*: 原文まま pseudo-function to account for otherwise unacounted for time. (訳注:意味理解できなかったのですが、<other>等のサブルーチンでないと表現しているのでは？と思います。)
?: このサブルーチンを呼び出したあと、returnせず終了しました。 (例えば、die や exit で終了するなど。) (訳注:sec/callの)集計に若干の誤差が出ている場合があります。
x: このサブルーチンを呼び出したあと例外発生で終了しました。 (訳注:sec/callの)集計に若干の誤差が出ている場合があります。

実行時間の長いプログラム¶

このモジュールは長時間実行される(デーモン)プログラムでもプロファイリング出来るように書かれています。通常はこのようなプログラムは終わることが無くプロファイルの出力が終了時に限られてしまうのは面白くない選択です。このモジュールは定期的に$PERL_PROFILE_SAVETIMEに基づく間隔でプロファイル出力が可能ですし、DB::save()を呼び出して、コードの任意の位置でプロファイル出力させることも可能です。ですからプログラムを実行していても、プロファイルを参照することが出来ます。

上記の様なプログラムで、非常に時間がかかる初期化処理(設定ファイルの読み込みやデータ構造の初期化など)があるのなら、初期化処理と処理本体を分けてプロファイリングしたいと思うでしょう。その場合は、一旦プロファイルを保存した後に、DB::reset()を呼び出して、それまでの統計をリセットすることが出来ます。リセットを行うと、その時点からの統計がプロファイルに出力されます。

デフォルトではリセットを行う為のシグナルをSIGUSR2で受け取るようになっています。シグナルが安全に取り扱える、perl5.8.0以降を使用すると、プロファイル出力の為のシグナルのコントロールが安全に行えるでしょう。

バグ¶

既知のバグはありません。

参考資料¶

    イエローストーン国立公園

作者¶

Jeff Weisberg - http://www.tcp4me.com/