argra****@users*****
argra****@users*****
2012年 10月 3日 (水) 03:34:01 JST
Index: docs/perl/5.14.1/perlperf.pod diff -u /dev/null docs/perl/5.14.1/perlperf.pod:1.1 --- /dev/null Wed Oct 3 03:34:01 2012 +++ docs/perl/5.14.1/perlperf.pod Wed Oct 3 03:34:01 2012 @@ -0,0 +1,2004 @@ + +=encoding euc-jp + +=head1 NAME + +=begin original + +perlperf - Perl Performance and Optimization Techniques + +=end original + +perlperf - Perl の性能と最適化のテクニック + +=head1 DESCRIPTION + +=begin original + +This is an introduction to the use of performance and optimization techniques +which can be used with particular reference to perl programs. While many perl +developers have come from other languages, and can use their prior knowledge +where appropriate, there are many other people who might benefit from a few +perl specific pointers. If you want the condensed version, perhaps the best +advice comes from the renowned Japanese Samurai, Miyamoto Musashi, who said: + +=end original + +これは、perl プログラムへの個々の参考として使える性能と最適化の +テクニックの使用の紹介です。 +多くの perl 開発者は他の言語から来ていて、適切な場所では以前の知識を +使えますが、いくつかの perl 特有の点から利益を得られるかもしれない多くの +人もいます。 +要約版がほしいなら、おそらく最良のアドバイスは、有名な日本の侍である +宮本武蔵の言葉でしょう: + +=begin original + + "Do Not Engage in Useless Activity" + +=end original + + 「役に立たないことをしないこと」 + +=begin original + +in 1645. + +=end original + +と 1645 年に記しています。 + +=head1 OVERVIEW + +(概観) + +=begin original + +Perhaps the most common mistake programmers make is to attempt to optimize +their code before a program actually does anything useful - this is a bad idea. +There's no point in having an extremely fast program that doesn't work. The +first job is to get a program to I<correctly> do something B<useful>, (not to +mention ensuring the test suite is fully functional), and only then to consider +optimizing it. Having decided to optimize existing working code, there are +several simple but essential steps to consider which are intrinsic to any +optimization process. + +=end original + +おそらくプログラマが犯す最もよくある間違いは、プログラムが実際に有用な +ものになる前にコードを最適化しようとすることです - これは悪い考えです。 +うまく動かないすごく高速なプログラムには意味がありません。 +最初の仕事はプログラムが I<正しく> 何か B<有用なこと> をするようにして +(テストスイートが完全に機能することを保証するという意味ではありません)、 +それからそれを最適化することだけを考えます。 +既に動作するコードを最適化すると決めたら、あらゆる最適化プロセスに内在すると +考えられる、いくつかの単純だけれども本質的なステップがあります。 + +=head2 ONE STEP SIDEWAYS + +(一歩横に) + +=begin original + +Firstly, you need to establish a baseline time for the existing code, which +timing needs to be reliable and repeatable. You'll probably want to use the +C<Benchmark> or C<Devel::DProf> modules, or something similar, for this step, +or perhaps the Unix system C<time> utility, whichever is appropriate. See the +base of this document for a longer list of benchmarking and profiling modules, +and recommended further reading. + +=end original + +まず、既にあるコードの基準になる時間を決定する必要があります; ここで +時間は信頼性があって再現可能であるものです。 +おそらく C<Benchmark> または C<Devel::DProf> モジュールやあるいは +似たようなものか、またはおそらく Unix システムの +C<time> ユーティリティのような、適切なものを使いたいでしょう。 +ベンチマークとプロファイルのモジュールのより長い一覧および、さらに読むための +お勧めについてはこの文書の末尾を見てください。 + +=head2 ONE STEP FORWARD + +(一歩前に) + +=begin original + +Next, having examined the program for I<hot spots>, (places where the code +seems to run slowly), change the code with the intention of making it run +faster. Using version control software, like C<subversion>, will ensure no +changes are irreversible. It's too easy to fiddle here and fiddle there - +don't change too much at any one time or you might not discover which piece of +code B<really> was the slow bit. + +=end original + +次に、プログラムの中の I<ホットスポット> (コード中で実行が遅くなっているらしい +場所) を調べ、より早く実行できるようにコードを変更します。 +C<subversion> のようなバージョンコントロールソフトを使って、全ての変更を +差し戻せるようにします。 +あちこちをいじるのはとても簡単です - 一度にたくさん変更しないようにします; +さもないとどこコードが B<本当に> 遅かったのかが分からなくなるかもしれません。 + +=head2 ANOTHER STEP SIDEWAYS + +(もう一歩横に) + +=begin original + +It's not enough to say: "that will make it run faster", you have to check it. +Rerun the code under control of the benchmarking or profiling modules, from the +first step above, and check that the new code executed the B<same task> in +I<less time>. Save your work and repeat... + +=end original + +次のように言うだけでは不十分です: 「これでもっと速く動作する」; +これをチェックする必要があります。 +上述の最初のステップから、ベンチマークやプロファイリングのモジュールの +制御下でコードを再実行して、新しいコードが I<より短い時間> で、 +B<同じ処理> を実行したことをチェックします。 +作業を保存して、繰り返します…。 + +=head1 GENERAL GUIDELINES + +(一般的なガイドライン) + +=begin original + +The critical thing when considering performance is to remember there is no such +thing as a C<Golden Bullet>, which is why there are no rules, only guidelines. + +=end original + +性能について考えるときに重要なことは、C<金の弾丸> のようなものは +ないということを忘れないことです; それがなぜここにルールがなく、 +ガイドラインだけがある理由です。 + +=begin original + +It is clear that inline code is going to be faster than subroutine or method +calls, because there is less overhead, but this approach has the disadvantage +of being less maintainable and comes at the cost of greater memory usage - +there is no such thing as a free lunch. If you are searching for an element in +a list, it can be more efficient to store the data in a hash structure, and +then simply look to see whether the key is defined, rather than to loop through +the entire array using grep() for instance. substr() may be (a lot) faster +than grep() but not as flexible, so you have another trade-off to access. Your +code may contain a line which takes 0.01 of a second to execute which if you +call it 1,000 times, quite likely in a program parsing even medium sized files +for instance, you already have a 10 second delay, in just one single code +location, and if you call that line 100,000 times, your entire program will +slow down to an unbearable crawl. + +=end original + +オーバーヘッドが少ないので、インラインコードはサブルーチンやメソッドの +呼び出しより早いのは明らかですが、この手法は保守性が悪くなってメモリ消費が +大きくなると言う欠点があります - フリーランチのようなものはありません。 +一覧の要素を探すとき、例えば配列全体を grep() を使ってループを +するのではなく、データをハッシュ構造に保管して、キーがあるかどうかを調べる +方がより効率的です。 +substr() は grep() (とても)早くなりますが、それほど柔軟ではないので、 +アクセスするのにもう一つのトレードオフがあります。 +例えば中くらいのサイズのファイルをパースするような、1,000 回呼び出される +0.01 秒かかる行が単一の行ですでに 10 秒の遅延があるかもしれませんし、 +その行が 100,000 回呼び出されるなら、プログラム全体が耐えられないぐらい +遅くなります。 + +=begin original + +Using a subroutine as part of your sort is a powerful way to get exactly what +you want, but will usually be slower than the built-in I<alphabetic> C<cmp> and +I<numeric> C<E<lt>=E<gt>> sort operators. It is possible to make multiple +passes over your data, building indices to make the upcoming sort more +efficient, and to use what is known as the C<OM> (Orcish Maneuver) to cache the +sort keys in advance. The cache lookup, while a good idea, can itself be a +source of slowdown by enforcing a double pass over the data - once to setup the +cache, and once to sort the data. Using C<pack()> to extract the required sort +key into a consistent string can be an efficient way to build a single string +to compare, instead of using multiple sort keys, which makes it possible to use +the standard, written in C<c> and fast, perl C<sort()> function on the output, +and is the basis of the C<GRT> (Guttman Rossler Transform). Some string +combinations can slow the C<GRT> down, by just being too plain complex for it's +own good. + +=end original + +ソートの一部としてサブルーチンを使うことは、したいことを正確にするための +強力な方法ですが、普通は組み込みの I<文字比較> の C<cmp> および +I<数値比較> の C<E<lt>=E<gt>> ソート演算子よりも遅いです。 +データに対して複数パスを行って、ソートをより効率的にするためのインデックスを +構築し、予めソートキーをキャッシュするために C<OM> (Orcish Maneuver) として +知られてるものを使うことができます。 +キャッシュの検索は、いい考えですが、それ自身データに対する 2 重パスを +強制することでスローダウンの元となり得ます - キャッシュの設定で一度、 +データのソートでもう一度です。 +必要なソートキーを永続的な文字列に展開するために C<pack()> を使うのは、 +複数のソートキーを使わずに比較するための単一の文字列を構築する効率的な +方法になり得ます; これにより出力に標準で C<c> で書かれていて高速な +Perl の C<sort()> 関数を使えるようになり、C<GRT> (Guttman Rossler Transform) +の基礎となります。 +一部の文字列比較は、単に複雑すぎるので C<GRT> を低下させます。 + +=begin original + +For applications using database backends, the standard C<DBIx> namespace has +tries to help with keeping things nippy, not least because it tries to I<not> +query the database until the latest possible moment, but always read the docs +which come with your choice of libraries. Among the many issues facing +developers dealing with databases should remain aware of is to always use +C<SQL> placeholders and to consider pre-fetching data sets when this might +prove advantageous. Splitting up a large file by assigning multiple processes +to parsing a single file, using say C<POE>, C<threads> or C<fork> can also be a +useful way of optimizing your usage of the available C<CPU> resources, though +this technique is fraught with concurrency issues and demands high attention to +detail. + +=end original + +データベースバックエンドを使うアプリケーションで、標準の +C<DBIx> 名前空間は物事をぴりっとしたものにし続けるように助けようとします; +特に可能な限り遅くまでデータベースに問い合わせ I<しない> ようにしますが、 +常に選択したライブラリに付属している文書を読んでください。 +データベースを扱う開発者が直面する多くの問題で気にするべきことは、 +常に C<SQL> プレースホルダを使うことと、利点がある分かるときにはデータ集合の +プリフェッチを考慮することです。 +大きなファイルを、C<POE>, C<threads>, C<fork> と言ったものを使って +単一のファイルをパースする複数のプロセスに割り当てることで分割することも、 +利用可能な C<CPU> リソースの仕様を最適化する有用な方法になり得ますが、 +このテクニックは並列性の問題に直面し、詳細に関して高い注目を必要とします。 + +=begin original + +Every case has a specific application and one or more exceptions, and there is +no replacement for running a few tests and finding out which method works best +for your particular environment, this is why writing optimal code is not an +exact science, and why we love using Perl so much - TMTOWTDI. + +=end original + +それぞれのケースには特定のアプリケーションと一つまたは複数の例外があり、 +いくつかテストを実行して、特定の環境にとってどの手法が最良かを見つけることに +代わるものはありません; これは、最適なコードを書くことが正確な科学ではない +理由であり、我々が Perl を使うのをとても愛している理由です - TMTOWTDI。 + +=head1 BENCHMARKS + +(ベンチマーク) + +=begin original + +Here are a few examples to demonstrate usage of Perl's benchmarking tools. + +=end original + +以下は、Perl のベンチマークツールの使い方を説明するいくつかの例です。 + +=head2 Assigning and Dereferencing Variables. + +(変数への代入とデリファレンス) + +=begin original + +I'm sure most of us have seen code which looks like, (or worse than), this: + +=end original + +私たちのほとんどは、以下のような(あるいはもっとひどい)コードを見たことが +あるはずです: + + if ( $obj->{_ref}->{_myscore} >= $obj->{_ref}->{_yourscore} ) { + ... + +=begin original + +This sort of code can be a real eyesore to read, as well as being very +sensitive to typos, and it's much clearer to dereference the variable +explicitly. We're side-stepping the issue of working with object-oriented +programming techniques to encapsulate variable access via methods, only +accessible through an object. Here we're just discussing the technical +implementation of choice, and whether this has an effect on performance. We +can see whether this dereferencing operation, has any overhead by putting +comparative code in a file and running a C<Benchmark> test. + +=end original + +この種類のコードは読むと目が疲れ、タイプミスに弱く、変数を明示的に +デリファレンスすることで遥かに明確になります。 +変数アクセスをメソッド経由でカプセル化して、オブジェクトを通してのみ +アクセス可能にすると言うオブジェクト指向プログラミングのテクニックを +使う問題を横に避けておきます。 +ここでは単に選択する技術実装に関して、そしてこれが性能が向上するかどうかを +議論しています。 +このデリファレンス操作がかなりのコードをファイルに置くことによる +オーバーヘッドがあるのかを C<Benchmark> テストで見てみます。 + +=begin original + +# dereference + +=end original + +# デリファレンス + + #!/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; + }, + }); + +=begin original + +It's essential to run any timing measurements a sufficient number of times so +the numbers settle on a numerical average, otherwise each run will naturally +fluctuate due to variations in the environment, to reduce the effect of +contention for C<CPU> resources and network bandwidth for instance. Running +the above code for one million iterations, we can take a look at the report +output by the C<Benchmark> module, to see which approach is the most effective. + +=end original + +時間計測は、平均を安定させるために十分な回数行うことが重要です; +さもなければそれぞれの実行は、例えば C<CPU> リソースの競合の効果や +ネットワーク帯域のような環境の変化によって自然に変動します。 +どの手法が最も効果的を見るために、上述のコードを 100 万回繰り返して、 +C<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) + +=begin original + +The difference is clear to see and the dereferencing approach is slower. While +it managed to execute an average of 628,930 times a second during our test, the +direct approach managed to run an additional 204,403 times, unfortunately. +Unfortunately, because there are many examples of code written using the +multiple layer direct variable access, and it's usually horrible. It is, +however, minusculy faster. The question remains whether the minute gain is +actually worth the eyestrain, or the loss of maintainability. + +=end original + +違いははっきりと見え、デリファレンスの手法はより遅いです。 +これはテスト中 1 秒間に平均して 628,930 回実行しましたが、直接手法は +残念ながらさらに 204,403 回実行しています。 +残念ながら、複数層の直接変数アクセスを使ったコード例がたくさんあるので、 +これは普通は恐ろしいものです。 +しかし、これはほんの少し速いです。 +問題は、ほんの少しの向上が疲れ目と保守性の喪失の価値があるかです。 + +=head2 Search and replace or tr + +(検索と置換または tr) + +=begin original + +If we have a string which needs to be modified, while a regex will almost +always be much more flexible, C<tr>, an oft underused tool, can still be a +useful. One scenario might be replace all vowels with another character. The +regex solution might look like this: + +=end original + +変更する必要がある文字列がある場合、正規表現はほとんど常により柔軟性が +ありますが、活用されていない C<tr> も依然有用です。 +一つのシナリオとしては、全ての母音を他の文字に置換するというものです。 +正規表現による解放は以下のようなものになるでしょう: + + $str =~ s/[aeiou]/x/g + +=begin original + +The C<tr> alternative might look like this: + +=end original + +C<tr> による代替案は以下のようになります: + + $str =~ tr/aeiou/xxxxx/ + +=begin original + +We can put that into a test file which we can run to check which approach is +the fastest, using a global C<$STR> variable to assign to the C<my $str> +variable so as to avoid perl trying to optimize any of the work away by +noticing it's assigned only the once. + +=end original + +どの手法が一番早いかをチェックするために、実行するテストファイルにこれを +置きます; perl が一度しか代入されないことを気付くことで処理しないように +最適化しようとすることを避けるために、C<my $str> 変数へ代入するために +グローバルな C<$STR> 変数を使います。 + +=begin original + +# regex-transliterate + +=end original + +# 正規表現-文字変換 + + #!/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; }, + }); + +=begin original + +Running the code gives us our results: + +=end original + +コードを実行することで結果が得られます: + + $> 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) + +=begin original + +The C<tr> version is a clear winner. One solution is flexible, the other is +fast - and it's appropriately the programmer's choice which to use. + +=end original + +C<tr> 版が明らかな勝者です。 +ある解決法は柔軟性があり、他の解決法は高速です - そして適切に +どちらを使うかはプログラマの選択です。 + +=begin original + +Check the C<Benchmark> docs for further useful techniques. + +=end original + +さらなる有用なテクニックについては C<Benchmark> の文書を参照してください。 + +=head1 PROFILING TOOLS + +(プロファイリングツール) + +=begin original + +A slightly larger piece of code will provide something on which a profiler can +produce more extensive reporting statistics. This example uses the simplistic +C<wordmatch> program which parses a given input file and spews out a short +report on the contents. + +=end original + +やや大きめのコードではプロファイラが生成するより大規模な状況報告が +何かを提供するでしょう。 +この例は、与えられた入力ファイルをパースして、内容の短いレポートを出力する +単純な C<wordmatch> プログラムを使います。 + +=begin original + +# wordmatch + +=end original + +# 単語マッチング + + #!/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; + +=head2 Devel::DProf + +=begin original + +This venerable module has been the de-facto standard for Perl code profiling +for more than a decade, but has been replaced by a number of other modules +which have brought us back to the 21st century. Although you're recommended to +evaluate your tool from the several mentioned here and from the CPAN list at +the base of this document, (and currently L<Devel::NYTProf> seems to be the +weapon of choice - see below), we'll take a quick look at the output from +L<Devel::DProf> first, to set a baseline for Perl profiling tools. Run the +above program under the control of C<Devel::DProf> by using the C<-d> switch on +the command-line. + +=end original + +この由緒あるモジュールは 10 年以上 Perl コードプロファイリングのデファクト +スタンダードでしたが、21 世紀になって色々なその他のモジュールに +置き換えられています。 +いくつかここで言及されたり、この文書の基礎となる CPAN リストからツールを +評価することを勧められていますが、(そして現在のところ L<Devel::NYTProf> が +選択する武器のようですが - 後述します)、Perl プロファイリングツールの +基本となる L<Devel::DProf> からの出力をまず簡単に見てみます。 +コマンドラインで C<-d> オプションを使うことで C<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 + +=begin original + +C<Devel::DProf> produces a special file, called F<tmon.out> by default, and +this file is read by the C<dprofpp> program, which is already installed as part +of the C<Devel::DProf> distribution. If you call C<dprofpp> with no options, +it will read the F<tmon.out> file in the current directory and produce a human +readable statistics report of the run of your program. Note that this may take +a little time. + +=end original + +C<Devel::DProf> は、デフォルトでは F<tmon.out> という名前の特殊なファイルを +出力し、このファイルは C<Devel::DProf> ディストリビューションの一部として +既にインストールされている C<dprofpp> プログラムによって読み込まれます。 +オプションなしで C<dprofpp> を呼び出すと、カレントディレクトリの +F<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 + +=begin original + +C<dprofpp> will produce some quite detailed reporting on the activity of the +C<wordmatch> program. The wallclock, user and system, times are at the top of +the analysis, and after this are the main columns defining which define the +report. Check the C<dprofpp> docs for details of the many options it supports. + +=end original + +C<dprofpp> は C<wordmatch> プログラムの活動のかなり詳細な報告を出力します。 +壁時計時間、ユーザーとシステム時間が分析の先頭にあり、その後は報告を +定義する定義で主な列です。 +対応している多くのオプションの詳細については C<dprofpp> の文書を +チェックしてください。 + +=begin original + +See also C<Apache::DProf> which hooks C<Devel::DProf> into C<mod_perl>. + +=end original + +C<Devel::DProf> を C<mod_perl> にフックする C<Apache::DProf> も +参照してください。 + +=head2 Devel::Profiler + +=begin original + +Let's take a look at the same program using a different profiler: +C<Devel::Profiler>, a drop-in Perl-only replacement for C<Devel::DProf>. The +usage is very slightly different in that instead of using the special C<-d:> +flag, you pull C<Devel::Profiler> in directly as a module using C<-M>. + +=end original + +同じプログラムの他のプロファイラによる結果も見てみましょう: +C<Devel::Profiler> は C<Devel::DProf> の Perl 専用のドロップインです。 +使用法は特殊な C<-d:> フラグを使うのとはほんの少し違って、 +C<Devel::Profiler> を C<-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 + +=begin original + +C<Devel::Profiler> generates a tmon.out file which is compatible with the +C<dprofpp> program, thus saving the construction of a dedicated statistics +reader program. C<dprofpp> usage is therefore identical to the above example. + +=end original + +C<Devel::Profiler> は C<dprofpp> プログラムと互換性のある tmon.out ファイルを +生成するので、専用の統計読み込みプログラムの構築を省略できます。 +従って C<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 + +=begin original + +Interestingly we get slightly different results, which is mostly because the +algorithm which generates the report is different, even though the output file +format was allegedly identical. The elapsed, user and system times are clearly +showing the time it took for C<Devel::Profiler> to execute its own run, but +the column listings feel more accurate somehow than the ones we had earlier +from C<Devel::DProf>. The 102% figure has disappeared, for example. This is +where we have to use the tools at our disposal, and recognise their pros and +cons, before using them. Interestingly, the numbers of calls for each +subroutine are identical in the two reports, it's the percentages which differ. +As the author of C<Devel::Proviler> writes: + +=end original + +興味深いことに少し異なった結果が得られました; その理由のほとんどは、 +出力ファイル形式は同一とされているにも関わらず、報告を生成するアルゴリズムが +異なることです。 +経過時間とユーザー+システム時間は明らかに C<Devel::Profiler> が自身の実行で +かかった時間を表示してますが、列一覧は先に C<Devel::DProf> で得られたものより +いくらかより正確なものに感じられます。 +例えば、102% の図は消えました。 +これが、ツールを使ってみて、それらを使う前にそれらの利点と欠点を認識する +必要があるところです。 +興味深いことに、それぞれのサブルーチンの呼び出し回数は二つの報告で +同じですが、百分率は異なっています。 +C<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. + +=begin original + +YMMV. + +=end original + +あなたの意見は違うかもしれません。 + +=begin original + +See also C<Devel::Apache::Profiler> which hooks C<Devel::Profiler> into C<mod_perl>. + +=end original + +C<mod_perl> に C<Devel::Profiler> フックを付ける +C<Devel::Apache::Profiler> も参照してください。 + +=head2 Devel::SmallProf + +=begin original + +The C<Devel::SmallProf> profiler examines the runtime of your Perl program and +produces a line-by-line listing to show how many times each line was called, +and how long each line took to execute. It is called by supplying the familiar +C<-d> flag to Perl at runtime. + +=end original + +C<Devel::SmallProf> プロファイラは Perl プログラムの実行時間を調べて、 +それぞれの行が何回呼び出されたかをしめす行単位の一覧を出力します。 +これは実行時に Perl に親しんだ C<-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 + +=begin original + +C<Devel::SmallProf> writes it's output into a file called F<smallprof.out>, by +default. The format of the file looks like this: + +=end original + +C<Devel::SmallProf> は出力を、デフォルトでは F<smallprof.out> と呼ばれる +ファイルに書き込みます。 +ファイルの形式は以下のようなものです: + + <num> <time> <ctime> <line>:<text> + +=begin original + +When the program has terminated, the output may be examined and sorted using +any standard text filtering utilities. Something like the following may be +sufficient: + +=end original + +プログラムが終了したとき、出力は任意の標準テキストフィルタリング +ユーティリティを使って検査とソートが行われます。 +以下のようなもので十分でしょう: + + $> 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- + +=begin original + +You can immediately see a slightly different focus to the subroutine profiling +modules, and we start to see exactly which line of code is taking the most +time. That regex line is looking a bit suspicious, for example. Remember that +these tools are supposed to be used together, there is no single best way to +profile your code, you need to use the best tools for the job. + +=end original + +サブルーチンプロファイリングモジュールとは少し異なったフォーカスであることが +すぐに分かります; そして正確にコードのどの行が一番時間がかかるかを +見始めます。 +例えば、正規表現行は少し疑わしく見えます。 +これらのツールは互いに使われることを想定されていて、コードを +プロファイリングする単一の最良の方法というのはなく、仕事によって最良の +ツールを使う必要があると言うことを忘れないでください。 + +=begin original + +See also C<Apache::SmallProf> which hooks C<Devel::SmallProf> into C<mod_perl>. + +=end original + +C<mod_perl> に C<Devel::SmallProf> フックを付ける C<Apache::SmallProf> も +参照してください。 + +=head2 Devel::FastProf + +=begin original + +C<Devel::FastProf> is another Perl line profiler. This was written with a view +to getting a faster line profiler, than is possible with for example +C<Devel::SmallProf>, because it's written in C<C>. To use C<Devel::FastProf>, +supply the C<-d> argument to Perl: + +=end original + +C<Devel::FastProf> はもう一つの Perl 行プロファイラです。 +これは、例えば C<Devel::SmallProf> などよりも速い行プロファイラとして +C<C> で書かれました。 +C<Devel::FastProf> を使うには、Perl に C<-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 + +=begin original + +C<Devel::FastProf> writes statistics to the file F<fastprof.out> in the current +directory. The output file, which can be specified, can be interpreted by using +the C<fprofpp> command-line program. + +=end original + +C<Devel::FastProf> は現在のディレクトリのファイル F<fastprof.out> に +統計情報を書き込みます。 +指定可能な出力ファイルは C<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; + +=begin original + +Straightaway we can see that the number of times each line has been called is +identical to the C<Devel::SmallProf> output, and the sequence is only very +slightly different based on the ordering of the amount of time each line took +to execute, C<if ( $debug ) { > and C<my $message = shift;>, for example. The +differences in the actual times recorded might be in the algorithm used +internally, or it could be due to system resource limitations or contention. + +=end original + +直ちに、各行が呼び出された回数が C<Devel::SmallProf> の出力と同じで、並びは +各行の実行時間順を基にして ほんの少しだけ異なる(例えば C<if ( $debug ) { > と +C<my $message = shift;>) ことがわかります。 +実際に記録されている時間の違いは内部で使われているアルゴリズムかも +しれませんし、システムリソースの制限や衝突によるかもしれません。 + +=begin original + +See also the L<DBIx::Profile> which will profile database queries running +under the C<DBIx::*> namespace. + +=end original + +C<DBIx::*> 名前空間で実行されるデータベース問い合わせをプロファイルする +L<DBIx::Profile> も参照してください。 + +=head2 Devel::NYTProf + +=begin original + +C<Devel::NYTProf> is the B<next generation> of Perl code profiler, fixing many +shortcomings in other tools and implementing many cool features. First of all it +can be used as either a I<line> profiler, a I<block> or a I<subroutine> +profiler, all at once. It can also use sub-microsecond (100ns) resolution on +systems which provide C<clock_gettime()>. It can be started and stopped even +by the program being profiled. It's a one-line entry to profile C<mod_perl> +applications. It's written in C<c> and is probably the fastest profiler +available for Perl. The list of coolness just goes on. Enough of that, let's +see how to it works - just use the familiar C<-d> switch to plug it in and run +the code. + +=end original + +C<Devel::NYTProf> は B<新世代> Perl コードプロファイラで、他のツールの +多くの欠点を修正し、多くのクールな機能を実装しています。 +まず、これは I<行> プロファイラと I<ブロック> または +I<サブルーチン> プロファイラとして一度に使えます。 +また、C<clock_gettime()> を提供しているシステムではマイクロ秒未満 (100ns) の +解像度を使えます。 +プログラムがプロファイルからでも開始終了できます。 +これは C<mod_perl> アプリケーションをプロファイルする一行エントリです。 +これは C<c> で書かれていて、おそらく Perl で利用可能な最速の +プロファイラです。 +素晴らしさの一覧はまだ続きます。 +これで十分でしょうから、どのように動作するかを見てみましょう - 単に親しんだ +C<-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 + +=begin original + +C<NYTProf> will generate a report database into the file F<nytprof.out> by +default. Human readable reports can be generated from here by using the +supplied C<nytprofhtml> (HTML output) and C<nytprofcsv> (CSV output) programs. +We've used the Unix sytem C<html2text> utility to convert the +F<nytprof/index.html> file for convenience here. + +=end original + +C<NYTProf> はデフォルトではファイル F<nytprof.out> にレポートデータベースを +生成します。 +人間が読める報告は、提供される C<nytprofhtml> (HTML 出力) または +C<nytprofcsv> (CSV 出力) プログラムを使うことでここから生成されます。 +F<nytprof/index.html> ファイルをここで便利なように変換するために Unix +システムの C<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. + +=begin original + +The first part of the report already shows the critical information regarding +which subroutines are using the most time. The next gives some statistics +about the source files profiled. + +=end original + +報告の最初の部分は既に、どのサブルーチンが一番時間がかかっているかという +重要な情報を表示しています。 +以下はプロファイリングしたソースファイルに関するいくつかの統計情報です。 + + 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. + +=begin original + +At this point, if you're using the I<html> report, you can click through the +various links to bore down into each subroutine and each line of code. Because +we're using the text reporting here, and there's a whole directory full of +reports built for each source file, we'll just display a part of the +corresponding F<wordmatch-line.html> file, sufficient to give an idea of the +sort of output you can expect from this cool tool. + +=end original + +この点で、I<html> レポートを使っているなら、サブルーチン単位と行単位の +詳細への様々なリンクをクリックできます。 +ここではテキストレポートを使っていて、それぞれのソースファイルに対して +ビルドされたレポートファイルがディレクトリにたくさんあるので、対応する +F<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 | | | | | + +=begin original + +Oodles of very useful information in there - this seems to be the way forward. + +=end original + +大量のとても有用な情報がここにあります - これは前進する道のように思えます。 + +=begin original + +See also C<Devel::NYTProf::Apache> which hooks C<Devel::NYTProf> into C<mod_perl>. + +=end original + +C<mod_perl> に C<Devel::NYTProf> フックを付ける C<Devel::NYTProf::Apache> も +参照してください。 + +=head1 SORTING + +(ソート) + +=begin original + +Perl modules are not the only tools a performance analyst has at their +disposal, system tools like C<time> should not be overlooked as the next +example shows, where we take a quick look at sorting. Many books, theses and +articles, have been written about efficient sorting algorithms, and this is not +the place to repeat such work, there's several good sorting modules which +deserve taking a look at too: C<Sort::Maker>, C<Sort::Key> spring to mind. +However, it's still possible to make some observations on certain Perl specific +interpretations on issues relating to sorting data sets and give an example or +two with regard to how sorting large data volumes can effect performance. +Firstly, an often overlooked point when sorting large amounts of data, one can +attempt to reduce the data set to be dealt with and in many cases C<grep()> can +be quite useful as a simple filter: + +=end original + +Perl モジュールは性能分析者が持っている唯一の道具というわけではなく、 +ソートについて軽く見てみる次の例のように、C<time> のようなシステムツールも +見落とすべきではありません。 +効率的なソートアルゴリズムについて書かれている多くの多くの本、論文、記事が +あり、ここはそのようなことを繰り返す場所ではありません; 調べてみる価値のある +いくつかのよいソートモジュールもあります: C<Sort::Maker>, C<Sort::Key> が +思い浮かびます。 +しかし、まだデータ集合のソートに関連する問題の Perl 特有の解釈に関して +いくつか観測できる可能性があるので、大量のデータがどのように性能に +影響するかに関する例をいくつか示します。 +最初に、大量のデータをソートするときにしばしば見落とされる点は、扱うデータ +集合を減らそうと出来ることと、多くの場合 C<grep()> が単純なフィルタとして +かなり有用であるということです: + + @data = sort grep { /$filter/ } @incoming + +=begin original + +A command such as this can vastly reduce the volume of material to actually +sort through in the first place, and should not be too lightly disregarded +purely on the basis of its simplicity. The C<KISS> principle is too often +overlooked - the next example uses the simple system C<time> utility to +demonstrate. Let's take a look at an actual example of sorting the contents of +a large file, an apache logfile would do. This one has over a quarter of a +million lines, is 50M in size, and a snippet of it looks like this: + +=end original + +このようなコマンドは最初に実際にソートする量をとても減らすことが出来、 +単純性の原則だけであまり簡単に無視するべきではありません。 +C<KISS> 原則はあまりにも見逃されています - 次の例はデモに単純なシステム +C<time> ユーティリティを使います。 +大きなファイルの内容をソートするという実際の例を見てみましょう; apache の +ログファイルを使ってみます。 +これは 25 万行 50M バイトを超えますが、その一部は以下のようなものです: + +=begin original + +# logfile + +=end original + +# ログファイル + + 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" + +=begin original + +The specific task here is to sort the 286,525 lines of this file by Response +Code, Query, Browser, Referring Url, and lastly Date. One solution might be to +use the following code, which iterates over the files given on the +command-line. + +=end original + +ここでのタスクは Response Code, Query, Browser, Referring Url, +lastly Date からなる 286,525 行のファイルをソートすることです。 +一つの解決法は、以下のコードのようにコマンドラインで指定されたファイルを +反復する方法かもしれません。 + +=begin original + +# sort-apache-log + +=end original + +# 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; + +=begin original + +When running this program, redirect C<STDOUT> so it is possible to check the +output is correct from following test runs and use the system C<time> utility +to check the overall runtime. + +=end original + +このプログラムを実行するとき、以後のテストで出力が正しいか +チェックできるように C<STDOUT> をリダイレクトして、全体の実行時間を +チェックするためにシステムの C<time> ユーティリティを使います。 + + $> time ./sort-apache-log logfile > out-sort + + real 0m17.371s + user 0m15.757s + sys 0m0.592s + +=begin original + +The program took just over 17 wallclock seconds to run. Note the different +values C<time> outputs, it's important to always use the same one, and to not +confuse what each one means. + +=end original + +プログラムは実行にちょうど 17 壁時計秒ほどかかりました。 +C<time> 出力の異なった値に注意して、いつも同じものを使い、それぞれの値の +意味を混乱しないことが重要です。 + +=over 4 + +=item Elapsed Real Time + +(実経過時間) + +=begin original + +The overall, or wallclock, time between when C<time> was called, and when it +terminates. The elapsed time includes both user and system times, and time +spent waiting for other users and processes on the system. Inevitably, this is +the most approximate of the measurements given. + +=end original + +C<time> が呼び出されてからそれが終了するまでの間の全体的な、あるいは +壁時計の、時間です。 +経過時間にはユーザー時間とシステム時間、およびシステム上の他のユーザーや +プロセスを待つために費やされた時間を含みます。 +必然的に、これは与えられたものに最も近い時間です。 + +=item User CPU Time + +(ユーザー CPU 時間) + +=begin original + +The user time is the amount of time the entire process spent on behalf of the +user on this system executing this program. + +=end original + +ユーザー時間はこのシステムでこのプログラムを実行することで消費された +全体のプロセス時間です。 + +=item System CPU Time + +(システム CPU 時間) + +=begin original + +The system time is the amount of time the kernel itself spent executing +routines, or system calls, on behalf of this process user. + +=end original + +システム時間はこのプロセスユーザーのためにカーネルが実行したルーチンや +システムコールの時間です。 + +=back + +=begin original + +Running this same process as a C<Schwarzian Transform> it is possible to +eliminate the input and output arrays for storing all the data, and work on the +input directly as it arrives too. Otherwise, the code looks fairly similar: + +=end original + +同じ処理を C<シュワルツ変換> (Schwarzian Transform) として実行すると、 +全てのデータを補完するための配列の入出力を除去することができ、 +入力を直接届いてすぐに処理します。 +さもなければ、コードはほぼ似て見えます: + +=begin original + +# sort-apache-log-schwarzian + +=end original + +# 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; + +=begin original + +Run the new code against the same logfile, as above, to check the new time. + +=end original + +新しい時間をチェックするために上述のように同じログファイルに対して +新しいコードを実行します。 + + $> time ./sort-apache-log-schwarzian logfile > out-schwarz + + real 0m9.664s + user 0m8.873s + sys 0m0.704s + +=begin original + +The time has been cut in half, which is a respectable speed improvement by any +standard. Naturally, it is important to check the output is consistent with +the first program run, this is where the Unix system C<cksum> utility comes in. + +=end original + +時間は半分になりました; これはあらゆる面で立派な速度改善です。 +当然ながら、出力が最初のプログラムの実行と一貫性があることをチェックするのは +重要です; ここは Unix システム C<cksum> ユーティリティの出番です。 + + $> cksum out-sort out-schwarz + 3044173777 52029194 out-sort + 3044173777 52029194 out-schwarz + +=begin original + +BTW. Beware too of pressure from managers who see you speed a program up by 50% +of the runtime once, only to get a request one month later to do the same again +(true story) - you'll just have to point out your only human, even if you are a +Perl programmer, and you'll see what you can do... + +=end original + +ところで。 +あなたが一度実行時間を 50% 高速化したのを見た管理者が喜びすぎて、 +一ヶ月後にもう一度同じことを要求してくることに注意してください(実話) - +例えあなたが Perl プログラマでもあなたがただの人間であることを +指摘する必要があり、何ができるかを見てみましょう… + +=head1 LOGGING + +(ロギング) + +=begin original + +An essential part of any good development process is appropriate error handling +with appropriately informative messages, however there exists a school of +thought which suggests that log files should be I<chatty>, as if the chain of +unbroken output somehow ensures the survival of the program. If speed is in +any way an issue, this approach is wrong. + +=end original + +良い開発プロセスの本質的な部分は、適切に情報があるメッセージによる +適切なエラー処理ですが、プログラムの生存を確実にするための壊れない +出力のチェーンのように、ログファイルは I<おしゃべり> であるべきという +考え方があります。 +速度が問題なら、この手法は間違っています。 + +=begin original + +A common sight is code which looks something like this: + +=end original + +よく見かけるのは以下のような感じのコードです: + + logger->debug( "A logging message via process-id: $$ INC: " . Dumper(\%INC) ) + +=begin original + +The problem is that this code will always be parsed and executed, even when the +debug level set in the logging configuration file is zero. Once the debug() +subroutine has been entered, and the internal C<$debug> variable confirmed to +be zero, for example, the message which has been sent in will be discarded and +the program will continue. In the example given though, the \%INC hash will +already have been dumped, and the message string constructed, all of which work +could be bypassed by a debug variable at the statement level, like this: + +=end original + +問題は、例えログ設定ファイルのデバッグレベルがゼロでも、このコードは常に +パースされて実行されることです。 +例えば、一度 debug() サブルーチンに入って、内部の C<$debug> 変数が +ゼロであることを確認すると、送られたメッセージは捨てられてプログラムは +続行します。 +しかし、上述の例では、\%INC はすでにダンプされていて、メッセージ文字列は +構築されていて、このような作業の全ては以下のような文レベルの +デバッグ変数によって回避されるかもしれません: + + logger->debug( "A logging message via process-id: $$ INC: " . Dumper(\%INC) ) if $DEBUG; + +=begin original + +This effect can be demonstrated by setting up a test script with both forms, +including a C<debug()> subroutine to emulate typical C<logger()> functionality. + +=end original + +この効果は、両方の形式で設定したテストスクリプトで図示します; +これには典型的な C<logger()> 機能をエミュレートするための +C<debug()> サブルーチンです。 + +=begin original + +# ifdebug + +=end original + +# 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 + }, + }); + +=begin original + +Let's see what C<Benchmark> makes of this: + +=end original + +これによって C<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) + +=begin original + +In the one case the code, which does exactly the same thing as far as +outputting any debugging information is concerned, in other words nothing, +takes 14 seconds, and in the other case the code takes one hundredth of a +second. Looks fairly definitive. Use a C<$DEBUG> variable BEFORE you call the +subroutine, rather than relying on the smart functionality inside it. + +=end original + +ある場合では、デバッグ情報を出力するのと全く同じ、言い換えると何もしない +コードが 14 秒掛かっています。 +他の場合ではコードは 0.01 秒掛かっています。 +かなり明確に見えます。 +内部のスマートな機能に依存するのではなく、サブルーチンを呼び出す前に +C<$DEBUG> 変数を使ってください。 + +=head2 Logging if DEBUG (constant) + +(DEBUG (定数) によるロギング) + +=begin original + +It's possible to take the previous idea a little further, by using a compile +time C<DEBUG> constant. + +=end original + +コンパイル時 C<DEBUG> 定数を使うことで、前述のアイデアをさらに少し +進めることも可能です。 + +=begin original + +# ifdebug-constant + +=end original + +# 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 + }, + }); + +=begin original + +Running this program produces the following output: + +=end original + +このプログラムを実行すると以下の出力が得られます: + + $> 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) + +=begin original + +The C<DEBUG> constant wipes the floor with even the C<$debug> variable, +clocking in at minus zero seconds, and generates a "warning: too few iterations +for a reliable count" message into the bargain. To see what is really going +on, and why we had too few iterations when we thought we asked for 100000, we +can use the very useful C<B::Deparse> to inspect the new code: + +=end original + +C<DEBUG> 定数は C<$debug> 変数に対してでも床掃除をして、マイナスゼロ秒として +記録しています。 +さらに "warning: too few iterations for a reliable count" メッセージを +生成します。 +何が本当に起きているか、そしてなぜ 100000 を聞いたときに反復が +少なすぎるのかを見るために、新しいコードを調べるためにとても有用な +C<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 + +=begin original + +The output shows the constant() subroutine we're testing being replaced with +the value of the C<DEBUG> constant: zero. The line to be tested has been +completely optimized away, and you can't get much more efficient than that. + +=end original + +出力は、テストしている constant() サブルーチンが C<DEBUG> 定数の値: ゼロに +置き換えられていることを示しています。 +テストしたラインは完全に最適化されていて、これ以上すごく効率的にすることは +できません。 + +=head1 POSTSCRIPT + +(あとがき) + +=begin original + +This document has provided several way to go about identifying hot-spots, and +checking whether any modifications have improved the runtime of the code. + +=end original + +この文書は、ホットスポットの識別と、どの修正がコードの実行時間を +改善するかのチェックに関するいくつかの方法を提供しました。 + +=begin original + +As a final thought, remember that it's not (at the time of writing) possible to +produce a useful program which will run in zero or negative time and this basic +principle can be written as: I<useful programs are slow> by their very +definition. It is of course possible to write a nearly instantaneous program, +but it's not going to do very much, here's a very efficient one: + +=end original + +最後の考慮点として、(これを書いている時点では) ゼロまたは負の時間で +実行できる有用なプログラムを作成することは不可能であることを +忘れないでください; そしてこの基本原則は次のように書けます: +定義により、I<有用なプログラムは遅い>。 +もちろんほぼ瞬間的に動作するプログラムを書くことは可能ですが、とても +多くのことをすることは出来ません; 以下はとても効率的なものです: + + $> perl -e 0 + +=begin original + +Optimizing that any further is a job for C<p5p>. + +=end original + +これ以上の最適化は C<p5p> の仕事です。 + +=head1 SEE ALSO + +=begin original + +Further reading can be found using the modules and links below. + +=end original + +さらなる読み物は以下のモジュールとリンクを使って得られます。 + +=head2 PERLDOCS + +(perldoc) + +=begin original + +For example: C<perldoc -f sort>. + +=end original + +例えば: C<perldoc -f sort> + +L<perlfaq4>. + +L<perlfork>, L<perlfunc>, L<perlretut>, L<perlthrtut>. + +L<threads>. + +=head2 MAN PAGES + +(man ページ) + +C<time>. + +=head2 MODULES + +(モジュール) + +=begin original + +It's not possible to individually showcase all the performance related code for +Perl here, naturally, but here's a short list of modules from the CPAN which +deserve further attention. + +=end original + +当然ながら、Perl で性能に関するコードを全て陳列することは不可能ですが、 +以下は CPAN の中からさらなる注目を受けるに値するモジュールの短いリストです。 + + Apache::DProf + Apache::SmallProf + Benchmark + DBIx::Profile + 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 + +=head2 URLS + +(URL) + +=begin original + +Very useful online reference material: + +=end original + +とても有用なオンラインリファレンス: + + 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.html + +=head1 AUTHOR + +Richard Foley <richa****@rfi*****> Copyright (c) 2008 + +=cut + +=begin meta + +Translate: SHIRAKATA Kentaro <argra****@ub32*****> +Status: completed + +=end meta +