euc-jpNAME

perlperf - Perl の性能と最適化のテクニック

DESCRIPTION

これは、perl プログラムへの個々の参考として使える性能と最適化のテクニックの使用の紹介です。多くの perl 開発者は他の言語から来ていて、適切な場所では以前の知識を使えますが、いくつかの perl 特有の点から利益を得られるかもしれない多くの人もいます。要約版がほしいなら、おそらく最良のアドバイスは、有名な日本の侍である宮本武蔵の言葉でしょう:

    「役に立たないことをしないこと」

と 1645 年に記しています。

概観

おそらくプログラマが犯す最もよくある間違いは、プログラムが実際に有用なものになる前にコードを最適化しようとすることです - これは悪い考えです。うまく動かないすごく高速なプログラムには意味がありません。最初の仕事はプログラムが 正しく 何か 有用なこと をするようにして (テストスイートが完全に機能することを保証するという意味ではありません)、それからそれを最適化することだけを考えます。既に動作するコードを最適化すると決めたら、あらゆる最適化プロセスに内在すると考えられる、いくつかの単純だけれども本質的なステップがあります。

一歩横に

まず、既にあるコードの基準になる時間を決定する必要があります; ここで時間は信頼性があって再現可能であるものです。おそらく Benchmark または Devel::NYTProf モジュールやあるいは似たようなものか、またはおそらく Unix システムの time ユーティリティのような、適切なものを使いたいでしょう。ベンチマークとプロファイルのモジュールのより長い一覧および、さらに読むためのお勧めについてはこの文書の末尾を見てください。

一歩前に

次に、プログラムの中の ホットスポット (コード中で実行が遅くなっているらしい場所) を調べ、より早く実行できるようにコードを変更します。 subversion のようなバージョンコントロールソフトを使って、全ての変更を差し戻せるようにします。あちこちをいじるのはとても簡単です - 一度にたくさん変更しないようにします; さもないとどこコードが 本当に 遅かったのかが分からなくなるかもしれません。

もう一歩横に

次のように言うだけでは不十分です: 「これでもっと速く動作する」; これをチェックする必要があります。上述の最初のステップから、ベンチマークやプロファイリングのモジュールの制御下でコードを再実行して、新しいコードが より短い時間 で、 同じ処理 を実行したことをチェックします。作業を保存して、繰り返します…。

一般的なガイドライン

性能について考えるときに重要なことは、金の弾丸 のようなものはないということを忘れないことです; それがなぜここにルールがなく、ガイドラインだけがある理由です。

オーバーヘッドが少ないので、インラインコードはサブルーチンやメソッドの呼び出しより早いのは明らかですが、この手法は保守性が悪くなってメモリ消費が大きくなると言う欠点があります - フリーランチのようなものはありません。一覧の要素を探すとき、例えば配列全体を grep() を使ってループをするのではなく、データをハッシュ構造に保管して、キーがあるかどうかを調べる方がより効率的です。 substr() は grep() (とても)早くなりますが、それほど柔軟ではないので、アクセスするのにもう一つのトレードオフがあります。例えば中くらいのサイズのファイルをパースするような、1,000 回呼び出される 0.01 秒かかる行が単一の行ですでに 10 秒の遅延があるかもしれませんし、その行が 100,000 回呼び出されるなら、プログラム全体が耐えられないぐらい遅くなります。

ソートの一部としてサブルーチンを使うことは、したいことを正確にするための強力な方法ですが、普通は組み込みの 文字比較 の cmp および 数値比較 の <=> ソート演算子よりも遅いです。データに対して複数パスを行って、ソートをより効率的にするためのインデックスを構築し、予めソートキーをキャッシュするために OM (Orcish Maneuver) として知られてるものを使うことができます。キャッシュの検索は、いい考えですが、それ自身データに対する 2 重パスを強制することでスローダウンの元となり得ます - キャッシュの設定で一度、データのソートでもう一度です。必要なソートキーを永続的な文字列に展開するために pack() を使うのは、複数のソートキーを使わずに比較するための単一の文字列を構築する効率的な方法になり得ます; これにより出力に標準で c で書かれていて高速な Perl の sort() 関数を使えるようになり、GRT (Guttman Rossler Transform) の基礎となります。一部の文字列比較は、単に複雑すぎるので GRT を低下させます。

データベースバックエンドを使うアプリケーションで、標準の DBIx 名前空間は物事をぴりっとしたものにし続けるように助けようとします; 特に可能な限り遅くまでデータベースに問い合わせ しない ようにしますが、常に選択したライブラリに付属している文書を読んでください。データベースを扱う開発者が直面する多くの問題で気にするべきことは、常に SQL プレースホルダを使うことと、利点がある分かるときにはデータ集合のプリフェッチを考慮することです。大きなファイルを、POE, threads, fork と言ったものを使って単一のファイルをパースする複数のプロセスに割り当てることで分割することも、利用可能な CPU リソースの仕様を最適化する有用な方法になり得ますが、このテクニックは並列性の問題に直面し、詳細に関して高い注目を必要とします。

それぞれのケースには特定のアプリケーションと一つまたは複数の例外があり、いくつかテストを実行して、特定の環境にとってどの手法が最良かを見つけることに代わるものはありません; これは、最適なコードを書くことが正確な科学ではない理由であり、我々が Perl を使うのをとても愛している理由です - TMTOWTDI。

ベンチマーク

以下は、Perl のベンチマークツールの使い方を説明するいくつかの例です。

変数への代入とデリファレンス

私たちのほとんどは、以下のような(あるいはもっとひどい)コードを見たことがあるはずです:

    if ( $obj->{_ref}->{_myscore} >= $obj->{_ref}->{_yourscore} ) {
        ...

この種類のコードは読むと目が疲れ、タイプミスに弱く、変数を明示的にデリファレンスすることで遥かに明確になります。変数アクセスをメソッド経由でカプセル化して、オブジェクトを通してのみアクセス可能にすると言うオブジェクト指向プログラミングのテクニックを使う問題を横に避けておきます。ここでは単に選択する技術実装に関して、そしてこれが性能が向上するかどうかを議論しています。このデリファレンス操作がかなりのコードをファイルに置くことによるオーバーヘッドがあるのかを Benchmark テストで見てみます。

# デリファレンス

    #!/usr/bin/perl

    use strict;
    use warnings;

    use Benchmark;

    my $ref = {
            'ref'   => {
                _myscore    => '100 + 1',
                _yourscore  => '102 - 1',
            },
    };

    timethese(1000000, {
            'direct'       => sub {
                my $x = $ref->{ref}->{_myscore} . $ref->{ref}->{_yourscore} ;
            },
            'dereference'  => sub {
                my $ref  = $ref->{ref};
                my $myscore = $ref->{_myscore};
                my $yourscore = $ref->{_yourscore};
                my $x = $myscore . $yourscore;
            },
    });

時間計測は、平均を安定させるために十分な回数行うことが重要です; さもなければそれぞれの実行は、例えば CPU リソースの競合の効果やネットワーク帯域のような環境の変化によって自然に変動します。どの手法が最も効果的を見るために、上述のコードを 100 万回繰り返して、 Benchmark モジュールによって出力された報告を見てみます。

    $> perl dereference

    Benchmark: timing 1000000 iterations of dereference, direct...
    dereference:  2 wallclock secs ( 1.59 usr +  0.00 sys =  1.59 CPU) @ 628930.82/s (n=1000000)
        direct:  1 wallclock secs ( 1.20 usr +  0.00 sys =  1.20 CPU) @ 833333.33/s (n=1000000)

違いははっきりと見え、デリファレンスの手法はより遅いです。これはテスト中 1 秒間に平均して 628,930 回実行しましたが、直接手法は残念ながらさらに 204,403 回実行しています。残念ながら、複数層の直接変数アクセスを使ったコード例がたくさんあるので、これは普通は恐ろしいものです。しかし、これはほんの少し速いです。問題は、ほんの少しの向上が疲れ目と保守性の喪失の価値があるかです。

検索と置換または tr

変更する必要がある文字列がある場合、正規表現はほとんど常により柔軟性がありますが、活用されていない tr も依然有用です。一つのシナリオとしては、全ての母音を他の文字に置換するというものです。正規表現による解放は以下のようなものになるでしょう:

    $str =~ s/[aeiou]/x/g

tr による代替案は以下のようになります:

    $str =~ tr/aeiou/xxxxx/

どの手法が一番早いかをチェックするために、実行するテストファイルにこれを置きます; perl が一度しか代入されないことを気付くことで処理しないように最適化しようとすることを避けるために、my $str 変数へ代入するためにグローバルな $STR 変数を使います。

# 正規表現-文字変換

    #!/usr/bin/perl

    use strict;
    use warnings;

    use Benchmark;

    my $STR = "$$-this and that";

    timethese( 1000000, {
            'sr'  => sub { my $str = $STR; $str =~ s/[aeiou]/x/g; return $str; },
            'tr'  => sub { my $str = $STR; $str =~ tr/aeiou/xxxxx/; return $str; },
    });

コードを実行することで結果が得られます:

    $> perl regex-transliterate

    Benchmark: timing 1000000 iterations of sr, tr...
            sr:  2 wallclock secs ( 1.19 usr +  0.00 sys =  1.19 CPU) @ 840336.13/s (n=1000000)
            tr:  0 wallclock secs ( 0.49 usr +  0.00 sys =  0.49 CPU) @ 2040816.33/s (n=1000000)

tr 版が明らかな勝者です。ある解決法は柔軟性があり、他の解決法は高速です - そして適切にどちらを使うかはプログラマの選択です。

さらなる有用なテクニックについては Benchmark の文書を参照してください。

プロファイリングツール

やや大きめのコードではプロファイラが生成するより大規模な状況報告が何かを提供するでしょう。この例は、与えられた入力ファイルをパースして、内容の短いレポートを出力する単純な wordmatch プログラムを使います。

# 単語マッチング

    #!/usr/bin/perl

    use strict;
    use warnings;

    =head1 NAME

    filewords - word analysis of input file

    =head1 SYNOPSIS

        filewords -f inputfilename [-d]

    =head1 DESCRIPTION

    This program parses the given filename, specified with C<-f>, and displays a
    simple analysis of the words found therein.  Use the C<-d> switch to enable
    debugging messages.

    =cut

    use FileHandle;
    use Getopt::Long;

    my $debug   =  0;
    my $file    = '';

    my $result = GetOptions (
        'debug'         => \$debug,
        'file=s'        => \$file,
    );
    die("invalid args") unless $result;

    unless ( -f $file ) {
        die("Usage: $0 -f filename [-d]");
    }
    my $FH = FileHandle->new("< $file") or die("unable to open file($file): $!");

    my $i_LINES = 0;
    my $i_WORDS = 0;
    my %count   = ();

    my @lines = <$FH>;
    foreach my $line ( @lines ) {
        $i_LINES++;
        $line =~ s/\n//;
        my @words = split(/ +/, $line);
        my $i_words = scalar(@words);
        $i_WORDS = $i_WORDS + $i_words;
        debug("line: $i_LINES supplying $i_words words: @words");
        my $i_word = 0;
        foreach my $word ( @words ) {
            $i_word++;
            $count{$i_LINES}{spec} += matches($i_word, $word, '[^a-zA-Z0-9]');
            $count{$i_LINES}{only} += matches($i_word, $word, '^[^a-zA-Z0-9]+$');
            $count{$i_LINES}{cons} += matches($i_word, $word, '^[(?i:bcdfghjklmnpqrstvwxyz)]+$');
            $count{$i_LINES}{vows} += matches($i_word, $word, '^[(?i:aeiou)]+$');
            $count{$i_LINES}{caps} += matches($i_word, $word, '^[(A-Z)]+$');
        }
    }

    print report( %count );

    sub matches {
        my $i_wd  = shift;
        my $word  = shift;
        my $regex = shift;
        my $has = 0;

        if ( $word =~ /($regex)/ ) {
            $has++ if $1;
        }

        debug("word: $i_wd ".($has ? 'matches' : 'does not match')." chars: /$regex/");

        return $has;
    }

    sub report {
        my %report = @_;
        my %rep;

        foreach my $line ( keys %report ) {
            foreach my $key ( keys %{ $report{$line} } ) {
                $rep{$key} += $report{$line}{$key};
            }
        }

        my $report = qq|
    $0 report for $file:
    lines in file: $i_LINES
    words in file: $i_WORDS
    words with special (non-word) characters: $i_spec
    words with only special (non-word) characters: $i_only
    words with only consonants: $i_cons
    words with only capital letters: $i_caps
    words with only vowels: $i_vows
    |;

        return $report;
    }

    sub debug {
        my $message = shift;

        if ( $debug ) {
            print STDERR "DBG: $message\n";
        }
    }

    exit 0;

Devel::DProf

この由緒あるモジュールは 10 年以上 Perl コードプロファイリングのデファクトスタンダードでしたが、21 世紀になって色々なその他のモジュールに置き換えられています。いくつかここで言及されたり、この文書の基礎となる CPAN リストからツールを評価することを勧められていますが、(そして現在のところ Devel::NYTProf が選択する武器のようですが - 後述します)、Perl プロファイリングツールの基本となる Devel::DProf からの出力をまず簡単に見てみます。コマンドラインで -d オプションを使うことで Devel::DProf の制御下でプログラムを実行します。

    $> perl -d:DProf wordmatch -f perl5db.pl

    <...multiple lines snipped...>

    wordmatch report for perl5db.pl:
    lines in file: 9428
    words in file: 50243
    words with special (non-word) characters: 20480
    words with only special (non-word) characters: 7790
    words with only consonants: 4801
    words with only capital letters: 1316
    words with only vowels: 1701

Devel::DProf は、デフォルトでは tmon.out という名前の特殊なファイルを出力し、このファイルは Devel::DProf ディストリビューションの一部として既にインストールされている dprofpp プログラムによって読み込まれます。オプションなしで dprofpp を呼び出すと、カレントディレクトリの tmon.out ファイルを読み込んで、あなたのプログラムの実行に関する人間が読める形での統計情報を出力します。これには少し時間がかかるかもしれないことに注意してください。

    $> dprofpp

    Total Elapsed Time = 2.951677 Seconds
      User+System Time = 2.871677 Seconds
    Exclusive Times
    %Time ExclSec CumulS #Calls sec/call Csec/c  Name
     102.   2.945  3.003 251215   0.0000 0.0000  main::matches
     2.40   0.069  0.069 260643   0.0000 0.0000  main::debug
     1.74   0.050  0.050      1   0.0500 0.0500  main::report
     1.04   0.030  0.049      4   0.0075 0.0123  main::BEGIN
     0.35   0.010  0.010      3   0.0033 0.0033  Exporter::as_heavy
     0.35   0.010  0.010      7   0.0014 0.0014  IO::File::BEGIN
     0.00       - -0.000      1        -      -  Getopt::Long::FindOption
     0.00       - -0.000      1        -      -  Symbol::BEGIN
     0.00       - -0.000      1        -      -  Fcntl::BEGIN
     0.00       - -0.000      1        -      -  Fcntl::bootstrap
     0.00       - -0.000      1        -      -  warnings::BEGIN
     0.00       - -0.000      1        -      -  IO::bootstrap
     0.00       - -0.000      1        -      -  Getopt::Long::ConfigDefaults
     0.00       - -0.000      1        -      -  Getopt::Long::Configure
     0.00       - -0.000      1        -      -  Symbol::gensym

dprofpp は wordmatch プログラムの活動のかなり詳細な報告を出力します。壁時計時間、ユーザーとシステム時間が分析の先頭にあり、その後は報告を定義する定義で主な列です。対応している多くのオプションの詳細については dprofpp の文書をチェックしてください。

Devel::DProf を mod_perl にフックする Apache::DProf も参照してください。

Devel::Profiler

同じプログラムの他のプロファイラによる結果も見てみましょう: Devel::Profiler は Devel::DProf の Perl 専用のドロップインです。使用法は特殊な -d: フラグを使うのとはほんの少し違って、 Devel::Profiler を -M を使ってモジュールとして直接読み込みます。

    $> perl -MDevel::Profiler wordmatch -f perl5db.pl

    <...multiple lines snipped...>

    wordmatch report for perl5db.pl:
    lines in file: 9428
    words in file: 50243
    words with special (non-word) characters: 20480
    words with only special (non-word) characters: 7790
    words with only consonants: 4801
    words with only capital letters: 1316
    words with only vowels: 1701

Devel::Profiler は dprofpp プログラムと互換性のある tmon.out ファイルを生成するので、専用の統計読み込みプログラムの構築を省略できます。従って dprofpp の使用法は上述の例と同じです。

    $> dprofpp

    Total Elapsed Time =   20.984 Seconds
      User+System Time =   19.981 Seconds
    Exclusive Times
    %Time ExclSec CumulS #Calls sec/call Csec/c  Name
     49.0   9.792 14.509 251215   0.0000 0.0001  main::matches
     24.4   4.887  4.887 260643   0.0000 0.0000  main::debug
     0.25   0.049  0.049      1   0.0490 0.0490  main::report
     0.00   0.000  0.000      1   0.0000 0.0000  Getopt::Long::GetOptions
     0.00   0.000  0.000      2   0.0000 0.0000  Getopt::Long::ParseOptionSpec
     0.00   0.000  0.000      1   0.0000 0.0000  Getopt::Long::FindOption
     0.00   0.000  0.000      1   0.0000 0.0000  IO::File::new
     0.00   0.000  0.000      1   0.0000 0.0000  IO::Handle::new
     0.00   0.000  0.000      1   0.0000 0.0000  Symbol::gensym
     0.00   0.000  0.000      1   0.0000 0.0000  IO::File::open

興味深いことに少し異なった結果が得られました; その理由のほとんどは、出力ファイル形式は同一とされているにも関わらず、報告を生成するアルゴリズムが異なることです。経過時間とユーザー+システム時間は明らかに Devel::Profiler が自身の実行でかかった時間を表示してますが、列一覧は先に Devel::DProf で得られたものよりいくらかより正確なものに感じられます。例えば、102% の図は消えました。これが、ツールを使ってみて、それらを使う前にそれらの利点と欠点を認識する必要があるところです。興味深いことに、それぞれのサブルーチンの呼び出し回数は二つの報告で同じですが、百分率は異なっています。 Devel::Proviler の作者が書いているように:

    ...running HTML::Template's test suite under Devel::DProf shows output()
    taking NO time but Devel::Profiler shows around 10% of the time is in output().
    I don't know which to trust but my gut tells me something is wrong with
    Devel::DProf.  HTML::Template::output() is a big routine that's called for
    every test. Either way, something needs fixing.

あなたの意見は違うかもしれません。

mod_perl に Devel::Profiler フックを付ける Devel::Apache::Profiler も参照してください。

Devel::SmallProf

Devel::SmallProf プロファイラは Perl プログラムの実行時間を調べて、それぞれの行が何回呼び出されたかをしめす行単位の一覧を出力します。これは実行時に Perl に親しんだ -d フラグを指定することで呼び出されます。

    $> perl -d:SmallProf wordmatch -f perl5db.pl

    <...multiple lines snipped...>

    wordmatch report for perl5db.pl:
    lines in file: 9428
    words in file: 50243
    words with special (non-word) characters: 20480
    words with only special (non-word) characters: 7790
    words with only consonants: 4801
    words with only capital letters: 1316
    words with only vowels: 1701

Devel::SmallProf は出力を、デフォルトでは smallprof.out と呼ばれるファイルに書き込みます。ファイルの形式は以下のようなものです:

    <num> <time> <ctime> <line>:<text>

プログラムが終了したとき、出力は任意の標準テキストフィルタリングユーティリティを使って検査とソートが行われます。以下のようなもので十分でしょう:

    $> cat smallprof.out | grep \d*: | sort -k3 | tac | head -n20

    251215   1.65674   7.68000    75: if ( $word =~ /($regex)/ ) {
    251215   0.03264   4.40000    79: debug("word: $i_wd ".($has ? 'matches' :
    251215   0.02693   4.10000    81: return $has;
    260643   0.02841   4.07000   128: if ( $debug ) {
    260643   0.02601   4.04000   126: my $message = shift;
    251215   0.02641   3.91000    73: my $has = 0;
    251215   0.03311   3.71000    70: my $i_wd  = shift;
    251215   0.02699   3.69000    72: my $regex = shift;
    251215   0.02766   3.68000    71: my $word  = shift;
     50243   0.59726   1.00000    59:  $count{$i_LINES}{cons} =
     50243   0.48175   0.92000    61:  $count{$i_LINES}{spec} =
     50243   0.00644   0.89000    56:  my $i_cons = matches($i_word, $word,
     50243   0.48837   0.88000    63:  $count{$i_LINES}{caps} =
     50243   0.00516   0.88000    58:  my $i_caps = matches($i_word, $word, '^[(A-
     50243   0.00631   0.81000    54:  my $i_spec = matches($i_word, $word, '[^a-
     50243   0.00496   0.80000    57:  my $i_vows = matches($i_word, $word,
     50243   0.00688   0.80000    53:  $i_word++;
     50243   0.48469   0.79000    62:  $count{$i_LINES}{only} =
     50243   0.48928   0.77000    60:  $count{$i_LINES}{vows} =
     50243   0.00683   0.75000    55:  my $i_only = matches($i_word, $word, '^[^a-

サブルーチンプロファイリングモジュールとは少し異なったフォーカスであることがすぐに分かります; そして正確にコードのどの行が一番時間がかかるかを見始めます。例えば、正規表現行は少し疑わしく見えます。これらのツールは互いに使われることを想定されていて、コードをプロファイリングする単一の最良の方法というのはなく、仕事によって最良のツールを使う必要があると言うことを忘れないでください。

mod_perl に Devel::SmallProf フックを付ける Apache::SmallProf も参照してください。

Devel::FastProf

Devel::FastProf はもう一つの Perl 行プロファイラです。これは、例えば Devel::SmallProf などよりも速い行プロファイラとして C で書かれました。 Devel::FastProf を使うには、Perl に -d オプションを指定します:

    $> perl -d:FastProf wordmatch -f perl5db.pl

    <...multiple lines snipped...>

    wordmatch report for perl5db.pl:
    lines in file: 9428
    words in file: 50243
    words with special (non-word) characters: 20480
    words with only special (non-word) characters: 7790
    words with only consonants: 4801
    words with only capital letters: 1316
    words with only vowels: 1701

Devel::FastProf は現在のディレクトリのファイル fastprof.out に統計情報を書き込みます。指定可能な出力ファイルは fprofpp コマンドラインプログラムを使って解釈されます。

    $> fprofpp | head -n20

    # fprofpp output format is:
    # filename:line time count: source
    wordmatch:75 3.93338 251215: if ( $word =~ /($regex)/ ) {
    wordmatch:79 1.77774 251215: debug("word: $i_wd ".($has ? 'matches' : 'does not match')." chars: /$regex/");
    wordmatch:81 1.47604 251215: return $has;
    wordmatch:126 1.43441 260643: my $message = shift;
    wordmatch:128 1.42156 260643: if ( $debug ) {
    wordmatch:70 1.36824 251215: my $i_wd  = shift;
    wordmatch:71 1.36739 251215: my $word  = shift;
    wordmatch:72 1.35939 251215: my $regex = shift;

直ちに、各行が呼び出された回数が Devel::SmallProf の出力と同じで、並びは各行の実行時間順を基にしてほんの少しだけ異なる(例えば if ( $debug ) { と my $message = shift;) ことがわかります。実際に記録されている時間の違いは内部で使われているアルゴリズムかもしれませんし、システムリソースの制限や衝突によるかもしれません。

DBIx::* 名前空間で実行されるデータベース問い合わせをプロファイルする DBIx::Profile も参照してください。

Devel::NYTProf

Devel::NYTProf は 新世代 Perl コードプロファイラで、他のツールの多くの欠点を修正し、多くのクールな機能を実装しています。まず、これは行プロファイラと ブロック または サブルーチン プロファイラとして一度に使えます。また、clock_gettime() を提供しているシステムではマイクロ秒未満 (100ns) の解像度を使えます。プログラムがプロファイルからでも開始終了できます。これは mod_perl アプリケーションをプロファイルする一行エントリです。これは c で書かれていて、おそらく Perl で利用可能な最速のプロファイラです。素晴らしさの一覧はまだ続きます。これで十分でしょうから、どのように動作するかを見てみましょう - 単に親しんだ -d スイッチを使って、コードを実行します。

    $> perl -d:NYTProf wordmatch -f perl5db.pl

    wordmatch report for perl5db.pl:
    lines in file: 9427
    words in file: 50243
    words with special (non-word) characters: 20480
    words with only special (non-word) characters: 7790
    words with only consonants: 4801
    words with only capital letters: 1316
    words with only vowels: 1701

NYTProf はデフォルトではファイル nytprof.out にレポートデータベースを生成します。人間が読める報告は、提供される nytprofhtml (HTML 出力) または nytprofcsv (CSV 出力) プログラムを使うことでここから生成されます。 nytprof/index.html ファイルをここで便利なように変換するために Unix システムの html2text ユーティリティを使っています。

    $> html2text nytprof/index.html

    Performance Profile Index
    For wordmatch
      Run on Fri Sep 26 13:46:39 2008
    Reported on Fri Sep 26 13:47:23 2008

             Top 15 Subroutines -- ordered by exclusive time
    |Calls |P |F |Inclusive|Exclusive|Subroutine                          |
    |      |  |  |Time     |Time     |                                    |
    |251215|5 |1 |13.09263 |10.47692 |main::              |matches        |
    |260642|2 |1 |2.71199  |2.71199  |main::              |debug          |
    |1     |1 |1 |0.21404  |0.21404  |main::              |report         |
    |2     |2 |2 |0.00511  |0.00511  |XSLoader::          |load (xsub)    |
    |14    |14|7 |0.00304  |0.00298  |Exporter::          |import         |
    |3     |1 |1 |0.00265  |0.00254  |Exporter::          |as_heavy       |
    |10    |10|4 |0.00140  |0.00140  |vars::              |import         |
    |13    |13|1 |0.00129  |0.00109  |constant::          |import         |
    |1     |1 |1 |0.00360  |0.00096  |FileHandle::        |import         |
    |3     |3 |3 |0.00086  |0.00074  |warnings::register::|import         |
    |9     |3 |1 |0.00036  |0.00036  |strict::            |bits           |
    |13    |13|13|0.00032  |0.00029  |strict::            |import         |
    |2     |2 |2 |0.00020  |0.00020  |warnings::          |import         |
    |2     |1 |1 |0.00020  |0.00020  |Getopt::Long::      |ParseOptionSpec|
    |7     |7 |6 |0.00043  |0.00020  |strict::            |unimport       |

    For more information see the full list of 189 subroutines.

報告の最初の部分は既に、どのサブルーチンが一番時間がかかっているかという重要な情報を表示しています。以下はプロファイリングしたソースファイルに関するいくつかの統計情報です。

            Source Code Files -- ordered by exclusive time then name
    |Stmts  |Exclusive|Avg.   |Reports                     |Source File         |
    |       |Time     |       |                            |                    |
    |2699761|15.66654 |6e-06  |line   .    block   .    sub|wordmatch           |
    |35     |0.02187  |0.00062|line   .    block   .    sub|IO/Handle.pm        |
    |274    |0.01525  |0.00006|line   .    block   .    sub|Getopt/Long.pm      |
    |20     |0.00585  |0.00029|line   .    block   .    sub|Fcntl.pm            |
    |128    |0.00340  |0.00003|line   .    block   .    sub|Exporter/Heavy.pm   |
    |42     |0.00332  |0.00008|line   .    block   .    sub|IO/File.pm          |
    |261    |0.00308  |0.00001|line   .    block   .    sub|Exporter.pm         |
    |323    |0.00248  |8e-06  |line   .    block   .    sub|constant.pm         |
    |12     |0.00246  |0.00021|line   .    block   .    sub|File/Spec/Unix.pm   |
    |191    |0.00240  |0.00001|line   .    block   .    sub|vars.pm             |
    |77     |0.00201  |0.00003|line   .    block   .    sub|FileHandle.pm       |
    |12     |0.00198  |0.00016|line   .    block   .    sub|Carp.pm             |
    |14     |0.00175  |0.00013|line   .    block   .    sub|Symbol.pm           |
    |15     |0.00130  |0.00009|line   .    block   .    sub|IO.pm               |
    |22     |0.00120  |0.00005|line   .    block   .    sub|IO/Seekable.pm      |
    |198    |0.00085  |4e-06  |line   .    block   .    sub|warnings/register.pm|
    |114    |0.00080  |7e-06  |line   .    block   .    sub|strict.pm           |
    |47     |0.00068  |0.00001|line   .    block   .    sub|warnings.pm         |
    |27     |0.00054  |0.00002|line   .    block   .    sub|overload.pm         |
    |9      |0.00047  |0.00005|line   .    block   .    sub|SelectSaver.pm      |
    |13     |0.00045  |0.00003|line   .    block   .    sub|File/Spec.pm        |
    |2701595|15.73869 |       |Total                       |
    |128647 |0.74946  |       |Average                     |
    |       |0.00201  |0.00003|Median                      |
    |       |0.00121  |0.00003|Deviation                   |

    Report produced by the NYTProf 2.03 Perl profiler, developed by Tim Bunce and
    Adam Kaplan.

この点で、html レポートを使っているなら、サブルーチン単位と行単位の詳細への様々なリンクをクリックできます。ここではテキストレポートを使っていて、それぞれのソースファイルに対してビルドされたレポートファイルがディレクトリにたくさんあるので、対応する wordmatch-line.html ファイルの一部だけを表示します; この素晴らしいツールでどのような出力が得られるかの考えを与えるには十分です。

    $> html2text nytprof/wordmatch-line.html

    Performance Profile -- -block view-.-line view-.-sub view-
    For wordmatch
    Run on Fri Sep 26 13:46:39 2008
    Reported on Fri Sep 26 13:47:22 2008

    File wordmatch

     Subroutines -- ordered by exclusive time
    |Calls |P|F|Inclusive|Exclusive|Subroutine    |
    |      | | |Time     |Time     |              |
    |251215|5|1|13.09263 |10.47692 |main::|matches|
    |260642|2|1|2.71199  |2.71199  |main::|debug  |
    |1     |1|1|0.21404  |0.21404  |main::|report |
    |0     |0|0|0        |0        |main::|BEGIN  |

    |Line|Stmts.|Exclusive|Avg.   |Code                                           |
    |    |      |Time     |       |                                               |
    |1   |      |         |       |#!/usr/bin/perl                                |
    |2   |      |         |       |                                               |
    |    |      |         |       |use strict;                                    |
    |3   |3     |0.00086  |0.00029|# spent 0.00003s making 1 calls to strict::    |
    |    |      |         |       |import                                         |
    |    |      |         |       |use warnings;                                  |
    |4   |3     |0.01563  |0.00521|# spent 0.00012s making 1 calls to warnings::  |
    |    |      |         |       |import                                         |
    |5   |      |         |       |                                               |
    |6   |      |         |       |=head1 NAME                                    |
    |7   |      |         |       |                                               |
    |8   |      |         |       |filewords - word analysis of input file        |
    <...snip...>
    |62  |1     |0.00445  |0.00445|print report( %count );                        |
    |    |      |         |       |# spent 0.21404s making 1 calls to main::report|
    |63  |      |         |       |                                               |
    |    |      |         |       |# spent 23.56955s (10.47692+2.61571) within    |
    |    |      |         |       |main::matches which was called 251215 times,   |
    |    |      |         |       |avg 0.00005s/call: # 50243 times               |
    |    |      |         |       |(2.12134+0.51939s) at line 57 of wordmatch, avg|
    |    |      |         |       |0.00005s/call # 50243 times (2.17735+0.54550s) |
    |64  |      |         |       |at line 56 of wordmatch, avg 0.00005s/call #   |
    |    |      |         |       |50243 times (2.10992+0.51797s) at line 58 of   |
    |    |      |         |       |wordmatch, avg 0.00005s/call # 50243 times     |
    |    |      |         |       |(2.12696+0.51598s) at line 55 of wordmatch, avg|
    |    |      |         |       |0.00005s/call # 50243 times (1.94134+0.51687s) |
    |    |      |         |       |at line 54 of wordmatch, avg 0.00005s/call     |
    |    |      |         |       |sub matches {                                  |
    <...snip...>
    |102 |      |         |       |                                               |
    |    |      |         |       |# spent 2.71199s within main::debug which was  |
    |    |      |         |       |called 260642 times, avg 0.00001s/call: #      |
    |    |      |         |       |251215 times (2.61571+0s) by main::matches at  |
    |103 |      |         |       |line 74 of wordmatch, avg 0.00001s/call # 9427 |
    |    |      |         |       |times (0.09628+0s) at line 50 of wordmatch, avg|
    |    |      |         |       |0.00001s/call                                  |
    |    |      |         |       |sub debug {                                    |
    |104 |260642|0.58496  |2e-06  |my $message = shift;                           |
    |105 |      |         |       |                                               |
    |106 |260642|1.09917  |4e-06  |if ( $debug ) {                                |
    |107 |      |         |       |print STDERR "DBG: $message\n";                |
    |108 |      |         |       |}                                              |
    |109 |      |         |       |}                                              |
    |110 |      |         |       |                                               |
    |111 |1     |0.01501  |0.01501|exit 0;                                        |
    |112 |      |         |       |                                               |

大量のとても有用な情報がここにあります - これは前進する道のように思えます。

mod_perl に Devel::NYTProf フックを付ける Devel::NYTProf::Apache も参照してください。

ソート

Perl モジュールは性能分析者が持っている唯一の道具というわけではなく、ソートについて軽く見てみる次の例のように、time のようなシステムツールも見落とすべきではありません。効率的なソートアルゴリズムについて書かれている多くの多くの本、論文、記事があり、ここはそのようなことを繰り返す場所ではありません; 調べてみる価値のあるいくつかのよいソートモジュールもあります: Sort::Maker, Sort::Key が思い浮かびます。しかし、まだデータ集合のソートに関連する問題の Perl 特有の解釈に関していくつか観測できる可能性があるので、大量のデータがどのように性能に影響するかに関する例をいくつか示します。最初に、大量のデータをソートするときにしばしば見落とされる点は、扱うデータ集合を減らそうと出来ることと、多くの場合 grep() が単純なフィルタとしてかなり有用であるということです:

    @data = sort grep { /$filter/ } @incoming

このようなコマンドは最初に実際にソートする量をとても減らすことが出来、単純性の原則だけであまり簡単に無視するべきではありません。 KISS 原則はあまりにも見逃されています - 次の例はデモに単純なシステム time ユーティリティを使います。大きなファイルの内容をソートするという実際の例を見てみましょう; apache のログファイルを使ってみます。これは 25 万行 50M バイトを超えますが、その一部は以下のようなものです:

# ログファイル

    188.209-65-87.adsl-dyn.isp.belgacom.be - - [08/Feb/2007:12:57:16 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
    188.209-65-87.adsl-dyn.isp.belgacom.be - - [08/Feb/2007:12:57:16 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
    151.56.71.198 - - [08/Feb/2007:12:57:41 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1"
    151.56.71.198 - - [08/Feb/2007:12:57:42 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1"
    151.56.71.198 - - [08/Feb/2007:12:57:43 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.2; en-US; rv:1.8.1.1) Gecko/20061204 Firefox/2.0.0.1"
    217.113.68.60 - - [08/Feb/2007:13:02:15 +0000] "GET / HTTP/1.1" 304 - "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
    217.113.68.60 - - [08/Feb/2007:13:02:16 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
    debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)"
    debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)"
    debora.to.isac.cnr.it - - [08/Feb/2007:13:03:58 +0000] "GET /favicon.ico HTTP/1.1" 404 209 "-" "Mozilla/5.0 (compatible; Konqueror/3.4; Linux) KHTML/3.4.0 (like Gecko)"
    195.24.196.99 - - [08/Feb/2007:13:26:48 +0000] "GET / HTTP/1.0" 200 3309 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9"
    195.24.196.99 - - [08/Feb/2007:13:26:58 +0000] "GET /data/css HTTP/1.0" 404 206 "http://www.rfi.net/" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9"
    195.24.196.99 - - [08/Feb/2007:13:26:59 +0000] "GET /favicon.ico HTTP/1.0" 404 209 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.8.0.9) Gecko/20061206 Firefox/1.5.0.9"
    crawl1.cosmixcorp.com - - [08/Feb/2007:13:27:57 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "voyager/1.0"
    crawl1.cosmixcorp.com - - [08/Feb/2007:13:28:25 +0000] "GET /links.html HTTP/1.0" 200 3413 "-" "voyager/1.0"
    fhm226.internetdsl.tpnet.pl - - [08/Feb/2007:13:37:32 +0000] "GET /suse-on-vaio.html HTTP/1.1" 200 2858 "http://www.linux-on-laptops.com/sony.html" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
    fhm226.internetdsl.tpnet.pl - - [08/Feb/2007:13:37:34 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net/suse-on-vaio.html" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
    80.247.140.134 - - [08/Feb/2007:13:57:35 +0000] "GET / HTTP/1.1" 200 3309 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)"
    80.247.140.134 - - [08/Feb/2007:13:57:37 +0000] "GET /data/css HTTP/1.1" 404 206 "http://www.rfi.net" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)"
    pop.compuscan.co.za - - [08/Feb/2007:14:10:43 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net"
    livebot-207-46-98-57.search.live.com - - [08/Feb/2007:14:12:04 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "msnbot/1.0 (+http://search.msn.com/msnbot.htm)"
    livebot-207-46-98-57.search.live.com - - [08/Feb/2007:14:12:04 +0000] "GET /html/oracle.html HTTP/1.0" 404 214 "-" "msnbot/1.0 (+http://search.msn.com/msnbot.htm)"
    dslb-088-064-005-154.pools.arcor-ip.net - - [08/Feb/2007:14:12:15 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net"
    196.201.92.41 - - [08/Feb/2007:14:15:01 +0000] "GET / HTTP/1.1" 200 3309 "-" "MOT-L7/08.B7.DCR MIB/2.2.1 Profile/MIDP-2.0 Configuration/CLDC-1.1"

ここでのタスクは Response Code, Query, Browser, Referring Url, lastly Date からなる 286,525 行のファイルをソートすることです。一つの解決法は、以下のコードのようにコマンドラインで指定されたファイルを反復する方法かもしれません。

# apache のログのソート

    #!/usr/bin/perl -n

    use strict;
    use warnings;

    my @data;

    LINE:
    while ( <> ) {
        my $line = $_;
        if (
            $line =~ m/^(
                ([\w\.\-]+)             # client
                \s*-\s*-\s*\[
                ([^]]+)                 # date
                \]\s*"\w+\s*
                (\S+)                   # query
                [^"]+"\s*
                (\d+)                   # status
                \s+\S+\s+"[^"]*"\s+"
                ([^"]*)                 # browser
                "
                .*
            )$/x
        ) {
            my @chunks = split(/ +/, $line);
            my $ip      = $1;
            my $date    = $2;
            my $query   = $3;
            my $status  = $4;
            my $browser = $5;

            push(@data, [$ip, $date, $query, $status, $browser, $line]);
        }
    }

    my @sorted = sort {
        $a->[3] cmp $b->[3]
                ||
        $a->[2] cmp $b->[2]
                ||
        $a->[0] cmp $b->[0]
                ||
        $a->[1] cmp $b->[1]
                ||
        $a->[4] cmp $b->[4]
    } @data;

    foreach my $data ( @sorted ) {
        print $data->[5];
    }

    exit 0;

このプログラムを実行するとき、以後のテストで出力が正しいかチェックできるように STDOUT をリダイレクトして、全体の実行時間をチェックするためにシステムの time ユーティリティを使います。

    $> time ./sort-apache-log logfile > out-sort

    real    0m17.371s
    user    0m15.757s
    sys     0m0.592s

プログラムは実行にちょうど 17 壁時計秒ほどかかりました。 time 出力の異なった値に注意して、いつも同じものを使い、それぞれの値の意味を混乱しないことが重要です。

実経過時間: time が呼び出されてからそれが終了するまでの間の全体的な、あるいは壁時計の、時間です。経過時間にはユーザー時間とシステム時間、およびシステム上の他のユーザーやプロセスを待つために費やされた時間を含みます。必然的に、これは与えられたものに最も近い時間です。
ユーザー CPU 時間: ユーザー時間はこのシステムでこのプログラムを実行することで消費された全体のプロセス時間です。
システム CPU 時間: システム時間はこのプロセスユーザーのためにカーネルが実行したルーチンやシステムコールの時間です。

同じ処理を シュワルツ変換 (Schwarzian Transform) として実行すると、全てのデータを補完するための配列の入出力を除去することができ、入力を直接届いてすぐに処理します。さもなければ、コードはほぼ似て見えます:

# apache のログをシュワルツ変換ソート

    #!/usr/bin/perl -n

    use strict;
    use warnings;

    print

        map $_->[0] =>

        sort {
            $a->[4] cmp $b->[4]
                    ||
            $a->[3] cmp $b->[3]
                    ||
            $a->[1] cmp $b->[1]
                    ||
            $a->[2] cmp $b->[2]
                    ||
            $a->[5] cmp $b->[5]
        }
        map  [ $_, m/^(
            ([\w\.\-]+)             # client
            \s*-\s*-\s*\[
            ([^]]+)                 # date
            \]\s*"\w+\s*
            (\S+)                   # query
            [^"]+"\s*
            (\d+)                   # status
            \s+\S+\s+"[^"]*"\s+"
            ([^"]*)                 # browser
            "
            .*
        )$/xo ]

        => <>;

    exit 0;

新しい時間をチェックするために上述のように同じログファイルに対して新しいコードを実行します。

    $> time ./sort-apache-log-schwarzian logfile > out-schwarz

    real    0m9.664s
    user    0m8.873s
    sys     0m0.704s

時間は半分になりました; これはあらゆる面で立派な速度改善です。当然ながら、出力が最初のプログラムの実行と一貫性があることをチェックするのは重要です; ここは Unix システム cksum ユーティリティの出番です。

    $> cksum out-sort out-schwarz
    3044173777 52029194 out-sort
    3044173777 52029194 out-schwarz

ところで。あなたが一度実行時間を 50% 高速化したのを見た管理者が喜びすぎて、一ヶ月後にもう一度同じことを要求してくることに注意してください(実話) - 例えあなたが Perl プログラマでもあなたがただの人間であることを指摘する必要があり、何ができるかを見てみましょう…

ロギング

良い開発プロセスの本質的な部分は、適切に情報があるメッセージによる適切なエラー処理ですが、プログラムの生存を確実にするための壊れない出力のチェーンのように、ログファイルは おしゃべり であるべきという考え方があります。速度が問題なら、この手法は間違っています。

よく見かけるのは以下のような感じのコードです:

    logger->debug( "A logging message via process-id: $$ INC: " . Dumper(\%INC) )

問題は、例えログ設定ファイルのデバッグレベルがゼロでも、このコードは常にパースされて実行されることです。例えば、一度 debug() サブルーチンに入って、内部の $debug 変数がゼロであることを確認すると、送られたメッセージは捨てられてプログラムは続行します。しかし、上述の例では、\%INC はすでにダンプされていて、メッセージ文字列は構築されていて、このような作業の全ては以下のような文レベルのデバッグ変数によって回避されるかもしれません:

    logger->debug( "A logging message via process-id: $$ INC: " . Dumper(\%INC) ) if $DEBUG;

この効果は、両方の形式で設定したテストスクリプトで図示します; これには典型的な logger() 機能をエミュレートするための debug() サブルーチンです。

# ifdebug

    #!/usr/bin/perl

    use strict;
    use warnings;

    use Benchmark;
    use Data::Dumper;
    my $DEBUG = 0;

    sub debug {
        my $msg = shift;

        if ( $DEBUG ) {
            print "DEBUG: $msg\n";
        }
    };

    timethese(100000, {
            'debug'       => sub {
                debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) )
            },
            'ifdebug'  => sub {
                debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if $DEBUG
            },
    });

これによって Benchmark がすることを見てみましょう:

    $> perl ifdebug
    Benchmark: timing 100000 iterations of constant, sub...
       ifdebug:  0 wallclock secs ( 0.01 usr +  0.00 sys =  0.01 CPU) @ 10000000.00/s (n=100000)
                (warning: too few iterations for a reliable count)
         debug: 14 wallclock secs (13.18 usr +  0.04 sys = 13.22 CPU) @ 7564.30/s (n=100000)

ある場合では、デバッグ情報を出力するのと全く同じ、言い換えると何もしないコードが 14 秒掛かっています; 他の場合ではコードは 0.01 秒掛かっています。かなり明確に見えます。内部のスマートな機能に依存するのではなく、サブルーチンを呼び出す前に $DEBUG 変数を使ってください。

DEBUG (定数) によるロギング

コンパイル時 DEBUG 定数を使うことで、前述のアイデアをさらに少し進めることも可能です。

# ifdebug-定数

    #!/usr/bin/perl

    use strict;
    use warnings;

    use Benchmark;
    use Data::Dumper;
    use constant
        DEBUG => 0
    ;

    sub debug {
        if ( DEBUG ) {
            my $msg = shift;
            print "DEBUG: $msg\n";
        }
    };

    timethese(100000, {
            'debug'       => sub {
                debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) )
            },
            'constant'  => sub {
                debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if DEBUG
            },
    });

このプログラムを実行すると以下の出力が得られます:

    $> perl ifdebug-constant
    Benchmark: timing 100000 iterations of constant, sub...
      constant:  0 wallclock secs (-0.00 usr +  0.00 sys = -0.00 CPU) @ -7205759403792793600000.00/s (n=100000)
                (warning: too few iterations for a reliable count)
           sub: 14 wallclock secs (13.09 usr +  0.00 sys = 13.09 CPU) @ 7639.42/s (n=100000)

DEBUG 定数は $debug 変数に対してでも床掃除をして、マイナスゼロ秒として記録しています; さらに "warning: too few iterations for a reliable count" メッセージを生成します。何が本当に起きているか、そしてなぜ 100000 を聞いたときに反復が少なすぎるのかを見るために、新しいコードを調べるためにとても有用な B::Deparse を使えます:

    $> perl -MO=Deparse ifdebug-constant

    use Benchmark;
    use Data::Dumper;
    use constant ('DEBUG', 0);
    sub debug {
        use warnings;
        use strict 'refs';
        0;
    }
    use warnings;
    use strict 'refs';
    timethese(100000, {'sub', sub {
        debug "A $0 logging message via process-id: $$" . Dumper(\%INC);
    }
    , 'constant', sub {
        0;
    }
    });
    ifdebug-constant syntax OK

出力は、テストしている constant() サブルーチンが DEBUG 定数の値: ゼロに置き換えられていることを示しています。テストしたラインは完全に最適化されていて、これ以上すごく効率的にすることはできません。

あとがき

この文書は、ホットスポットの識別と、どの修正がコードの実行時間を改善するかのチェックに関するいくつかの方法を提供しました。

最後の考慮点として、(これを書いている時点では) ゼロまたは負の時間で実行できる有用なプログラムを作成することは不可能であることを忘れないでください; そしてこの基本原則は次のように書けます: 定義により、有用なプログラムは遅い。もちろんほぼ瞬間的に動作するプログラムを書くことは可能ですが、とても多くのことをすることは出来ません; 以下はとても効率的なものです:

    $> perl -e 0

これ以上の最適化は p5p の仕事です。