perlperf - Perl の性能と最適化のテクニック
これは、perl プログラムへの個々の参考として使える性能と最適化の テクニックの使用の紹介です。 多くの perl 開発者は他の言語から来ていて、適切な場所では以前の知識を 使えますが、いくつかの perl 特有の点から利益を得られるかもしれない多くの 人もいます。 要約版がほしいなら、おそらく最良のアドバイスは、有名な日本の侍である 宮本武蔵の言葉でしょう:
「役に立たないことをしないこと」と 1645 年に記しています。
おそらくプログラマが犯す最もよくある間違いは、プログラムが実際に有用な ものになる前にコードを最適化しようとすることです - これは悪い考えです。 うまく動かないすごく高速なプログラムには意味がありません。 最初の仕事はプログラムが 正しく 何か 有用なこと をするようにして (テストスイートが完全に機能することを保証するという意味ではありません)、 それからそれを最適化することだけを考えます。 既に動作するコードを最適化すると決めたら、あらゆる最適化プロセスに内在すると 考えられる、いくつかの単純だけれども本質的なステップがあります。
まず、既にあるコードの基準になる時間を決定する必要があります; ここで 時間は信頼性があって再現可能であるものです。 おそらく Benchmark または Devel::DProf モジュールやあるいは 似たようなものか、またはおそらく 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 も依然有用です。 一つのシナリオとしては、全ての母音を他の文字に置換するというものです。 正規表現による解放は以下のようなものになるでしょう:
$str =~ s/[aeiou]/x/gtr による代替案は以下のようになります:
$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;この由緒あるモジュールは 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: 1701Devel::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::gensymdprofpp は wordmatch プログラムの活動のかなり詳細な報告を出力します。 壁時計時間、ユーザーとシステム時間が分析の先頭にあり、その後は報告を 定義する定義で主な列です。 対応している多くのオプションの詳細については dprofpp の文書を チェックしてください。
Devel::DProf を mod_perl にフックする Apache::DProf も 参照してください。
同じプログラムの他のプロファイラによる結果も見てみましょう: 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: 1701Devel::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 プロファイラは 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: 1701Devel::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 はもう一つの 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: 1701Devel::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::Profiler も参照してください。
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: 1701NYTProf はデフォルトではファイル 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 が呼び出されてからそれが終了するまでの間の全体的な、あるいは 壁時計の、時間です。 経過時間にはユーザー時間とシステム時間、およびシステム上の他のユーザーや プロセスを待つために費やされた時間を含みます。 必然的に、これは与えられたものに最も近い時間です。
ユーザー時間はこのシステムでこのプログラムを実行することで消費された 全体のプロセス時間です。
システム時間はこのプロセスユーザーのためにカーネルが実行したルーチンや システムコールの時間です。
同じ処理を シュワルツ変換 (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 定数を使うことで、前述のアイデアをさらに少し 進めることも可能です。
# 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 の仕事です。
さらなる読み物は以下のモジュールとリンクを使って得られます。
例えば: perldoc -f sort
perlfork, perlfunc, perlretut, perlthrtut.
time.
当然ながら、Perl で性能に関するコードを全て陳列することは不可能ですが、 以下は CPAN の中からさらなる注目を受けるに値するモジュールの短いリストです。
Apache::DProf
Apache::SmallProf
Benchmark
DBIx::Profiler
Devel::AutoProfiler
Devel::DProf
Devel::DProfLB
Devel::FastProf
Devel::GraphVizProf
Devel::NYTProf
Devel::NYTProf::Apache
Devel::Profiler
Devel::Profile
Devel::Profit
Devel::SmallProf
Devel::WxProf
POE::Devel::Profiler
Sort::Key
Sort::Makerとても有用なオンラインリファレンス:
http://www.ccl4.org/~nick/P/Fast_Enough/
http://www-128.ibm.com/developerworks/library/l-optperl.html
http://perlbuzz.com/2007/11/bind-output-variables-in-dbi-for-speed-and-safety.html
http://en.wikipedia.org/wiki/Performance_analysis
http://apache.perl.org/docs/1.0/guide/performance.html
http://perlgolf.sourceforge.net/
http://www.sysarch.com/Perl/sort_paper.htmlRichard Foley <richard.foley@rfi.net> Copyright (c) 2008