perlperf 5.16.1 と 5.20.1 の差分

1	1
2	2	=encoding euc-jp
3	3
4	4	=head1 NAME
5	5
6	6	=begin original
7	7
8	8	perlperf - Perl Performance and Optimization Techniques
9	9
10	10	=end original
11	11
12	12	perlperf - Perl の性能と最適化のテクニック
13	13
14	14	=head1 DESCRIPTION
15	15
16	16	=begin original
17	17
18	18	This is an introduction to the use of performance and optimization techniques
19	19	which can be used with particular reference to perl programs. While many perl
20	20	developers have come from other languages, and can use their prior knowledge
21	21	where appropriate, there are many other people who might benefit from a few
22	22	perl specific pointers. If you want the condensed version, perhaps the best
23	23	advice comes from the renowned Japanese Samurai, Miyamoto Musashi, who said:
24	24
25	25	=end original
26	26
27	27	これは、perl プログラムへの個々の参考として使える性能と最適化の
28	28	テクニックの使用の紹介です。
29	29	多くの perl 開発者は他の言語から来ていて、適切な場所では以前の知識を
30	30	使えますが、いくつかの perl 特有の点から利益を得られるかもしれない多くの
31	31	人もいます。
32	32	要約版がほしいなら、おそらく最良のアドバイスは、有名な日本の侍である
33	33	宮本武蔵の言葉でしょう:
34	34
35	35	=begin original
36	36
37	37	"Do Not Engage in Useless Activity"
38	38
39	39	=end original
40	40
41	41	「役に立たないことをしないこと」
42	42
43	43	=begin original
44	44
45	45	in 1645.
46	46
47	47	=end original
48	48
49	49	と 1645 年に記しています。
50	50
51	51	=head1 OVERVIEW
52	52
53	53	(概観)
54	54
55	55	=begin original
56	56
57	57	Perhaps the most common mistake programmers make is to attempt to optimize
58	58	their code before a program actually does anything useful - this is a bad idea.
59	59	There's no point in having an extremely fast program that doesn't work. The
60	60	first job is to get a program to I<correctly> do something B<useful>, (not to
61	61	mention ensuring the test suite is fully functional), and only then to consider
62	62	optimizing it. Having decided to optimize existing working code, there are
63	63	several simple but essential steps to consider which are intrinsic to any
64	64	optimization process.
65	65
66	66	=end original
67	67
68	68	おそらくプログラマが犯す最もよくある間違いは、プログラムが実際に有用な
69	69	ものになる前にコードを最適化しようとすることです - これは悪い考えです。
70	70	うまく動かないすごく高速なプログラムには意味がありません。
71	71	最初の仕事はプログラムが I<正しく> 何か B<有用なこと> をするようにして
72	72	(テストスイートが完全に機能することを保証するという意味ではありません)、
73	73	それからそれを最適化することだけを考えます。
74	74	既に動作するコードを最適化すると決めたら、あらゆる最適化プロセスに内在すると
75	75	考えられる、いくつかの単純だけれども本質的なステップがあります。
76	76
77	77	=head2 ONE STEP SIDEWAYS
78	78
79	79	(一歩横に)
80	80
81	81	=begin original
82	82
83	83	Firstly, you need to establish a baseline time for the existing code, which
84	84	timing needs to be reliable and repeatable. You'll probably want to use the
85	85	C<Benchmark> or C<Devel::NYTProf> modules, or something similar, for this step,
86	86	or perhaps the Unix system C<time> utility, whichever is appropriate. See the
87	87	base of this document for a longer list of benchmarking and profiling modules,
88	88	and recommended further reading.
89	89
90	90	=end original
91	91
92	92	まず、既にあるコードの基準になる時間を決定する必要があります; ここで
93	93	時間は信頼性があって再現可能であるものです。
94	94	おそらく C<Benchmark> または C<Devel::NYTProf> モジュールやあるいは
95	95	似たようなものか、またはおそらく Unix システムの
96	96	C<time> ユーティリティのような、適切なものを使いたいでしょう。
97	97	ベンチマークとプロファイルのモジュールのより長い一覧および、さらに読むための
98	98	お勧めについてはこの文書の末尾を見てください。
99	99
100	100	=head2 ONE STEP FORWARD
101	101
102	102	(一歩前に)
103	103
104	104	=begin original
105	105
106	106	Next, having examined the program for I<hot spots>, (places where the code
107	107	seems to run slowly), change the code with the intention of making it run
108	108	faster. Using version control software, like C<subversion>, will ensure no
109	109	changes are irreversible. It's too easy to fiddle here and fiddle there -
110	110	don't change too much at any one time or you might not discover which piece of
111	111	code B<really> was the slow bit.
112	112
113	113	=end original
114	114
115	115	次に、プログラムの中の I<ホットスポット> (コード中で実行が遅くなっているらしい
116	116	場所) を調べ、より早く実行できるようにコードを変更します。
117	117	C<subversion> のようなバージョンコントロールソフトを使って、全ての変更を
118	118	差し戻せるようにします。
119	119	あちこちをいじるのはとても簡単です - 一度にたくさん変更しないようにします;
120	120	さもないとどこコードが B<本当に> 遅かったのかが分からなくなるかもしれません。
121	121
122	122	=head2 ANOTHER STEP SIDEWAYS
123	123
124	124	(もう一歩横に)
125	125
126	126	=begin original
127	127
128	128	It's not enough to say: "that will make it run faster", you have to check it.
129	129	Rerun the code under control of the benchmarking or profiling modules, from the
130	130	first step above, and check that the new code executed the B<same task> in
131	131	I<less time>. Save your work and repeat...
132	132
133	133	=end original
134	134
135	135	次のように言うだけでは不十分です: 「これでもっと速く動作する」;
136	136	これをチェックする必要があります。
137	137	上述の最初のステップから、ベンチマークやプロファイリングのモジュールの
138	138	制御下でコードを再実行して、新しいコードが I<より短い時間> で、
139	139	B<同じ処理> を実行したことをチェックします。
140	140	作業を保存して、繰り返します…。
141	141
142	142	=head1 GENERAL GUIDELINES
143	143
144	144	(一般的なガイドライン)
145	145
146	146	=begin original
147	147
148	148	The critical thing when considering performance is to remember there is no such
149	149	thing as a C<Golden Bullet>, which is why there are no rules, only guidelines.
150	150
151	151	=end original
152	152
153	153	性能について考えるときに重要なことは、C<金の弾丸> のようなものは
154	154	ないということを忘れないことです; それがなぜここにルールがなく、
155	155	ガイドラインだけがある理由です。
156	156
157	157	=begin original
158	158
159	159	It is clear that inline code is going to be faster than subroutine or method
160	160	calls, because there is less overhead, but this approach has the disadvantage
161	161	of being less maintainable and comes at the cost of greater memory usage -
162	162	there is no such thing as a free lunch. If you are searching for an element in
163	163	a list, it can be more efficient to store the data in a hash structure, and
164	164	then simply look to see whether the key is defined, rather than to loop through
165	165	the entire array using grep() for instance. substr() may be (a lot) faster
166	166	than grep() but not as flexible, so you have another trade-off to access. Your
167	167	code may contain a line which takes 0.01 of a second to execute which if you
168	168	call it 1,000 times, quite likely in a program parsing even medium sized files
169	169	for instance, you already have a 10 second delay, in just one single code
170	170	location, and if you call that line 100,000 times, your entire program will
171	171	slow down to an unbearable crawl.
172	172
173	173	=end original
174	174
175	175	オーバーヘッドが少ないので、インラインコードはサブルーチンやメソッドの
176	176	呼び出しより早いのは明らかですが、この手法は保守性が悪くなってメモリ消費が
177	177	大きくなると言う欠点があります - フリーランチのようなものはありません。
178	178	一覧の要素を探すとき、例えば配列全体を grep() を使ってループを
179	179	するのではなく、データをハッシュ構造に保管して、キーがあるかどうかを調べる
180	180	方がより効率的です。
181	181	substr() は grep() より(とても)早くなりますが、それほど柔軟ではないので、
182	182	アクセスするのにもう一つのトレードオフがあります。
183	183	例えば中くらいのサイズのファイルをパースするような、1,000 回呼び出される
184	184	0.01 秒かかる行が単一の行ですでに 10 秒の遅延があるかもしれませんし、
185	185	その行が 100,000 回呼び出されるなら、プログラム全体が耐えられないぐらい
186	186	遅くなります。
187	187
188	188	=begin original
189	189
190	190	Using a subroutine as part of your sort is a powerful way to get exactly what
191	191	you want, but will usually be slower than the built-in I<alphabetic> C<cmp> and
192	192	I<numeric> C<E<lt>=E<gt>> sort operators. It is possible to make multiple
193	193	passes over your data, building indices to make the upcoming sort more
194	194	efficient, and to use what is known as the C<OM> (Orcish Maneuver) to cache the
195	195	sort keys in advance. The cache lookup, while a good idea, can itself be a
196	196	source of slowdown by enforcing a double pass over the data - once to setup the
197	197	cache, and once to sort the data. Using C<pack()> to extract the required sort
198	198	key into a consistent string can be an efficient way to build a single string
199	199	to compare, instead of using multiple sort keys, which makes it possible to use
200	200	the standard, written in C<c> and fast, perl C<sort()> function on the output,
201	201	and is the basis of the C<GRT> (Guttman Rossler Transform). Some string
202	202	combinations can slow the C<GRT> down, by just being too plain complex for it's
203	203	own good.
204	204
205	205	=end original
206	206
207	207	ソートの一部としてサブルーチンを使うことは、したいことを正確にするための
208	208	強力な方法ですが、普通は組み込みの I<文字比較> の C<cmp> および
209	209	I<数値比較> の C<E<lt>=E<gt>> ソート演算子よりも遅いです。
210	210	データに対して複数パスを行って、ソートをより効率的にするためのインデックスを
211	211	構築し、予めソートキーをキャッシュするために C<OM> (Orcish Maneuver) として
212	212	知られてるものを使うことができます。
213	213	キャッシュの検索は、いい考えですが、それ自身データに対する 2 重パスを
214	214	強制することでスローダウンの元となり得ます - キャッシュの設定で一度、
215	215	データのソートでもう一度です。
216	216	必要なソートキーを永続的な文字列に展開するために C<pack()> を使うのは、
217	217	複数のソートキーを使わずに比較するための単一の文字列を構築する効率的な
218	218	方法になり得ます; これにより出力に標準で C<c> で書かれていて高速な
219	219	Perl の C<sort()> 関数を使えるようになり、C<GRT> (Guttman Rossler Transform)
220	220	の基礎となります。
221	221	一部の文字列比較は、単に複雑すぎるので C<GRT> を低下させます。
222	222
223	223	=begin original
224	224
225	225	For applications using database backends, the standard C<DBIx> namespace has
226	226	tries to help with keeping things nippy, not least because it tries to I<not>
227	227	query the database until the latest possible moment, but always read the docs
228	228	which come with your choice of libraries. Among the many issues facing
229	229	developers dealing with databases should remain aware of is to always use
230	230	C<SQL> placeholders and to consider pre-fetching data sets when this might
231	231	prove advantageous. Splitting up a large file by assigning multiple processes
232	232	to parsing a single file, using say C<POE>, C<threads> or C<fork> can also be a
233	233	useful way of optimizing your usage of the available C<CPU> resources, though
234	234	this technique is fraught with concurrency issues and demands high attention to
235	235	detail.
236	236
237	237	=end original
238	238
239	239	データベースバックエンドを使うアプリケーションで、標準の
240	240	C<DBIx> 名前空間は物事をぴりっとしたものにし続けるように助けようとします;
241	241	特に可能な限り遅くまでデータベースに問い合わせ I<しない> ようにしますが、
242	242	常に選択したライブラリに付属している文書を読んでください。
243	243	データベースを扱う開発者が直面する多くの問題で気にするべきことは、
244	244	常に C<SQL> プレースホルダを使うことと、利点がある分かるときにはデータ集合の
245	245	プリフェッチを考慮することです。
246	246	大きなファイルを、C<POE>, C<threads>, C<fork> と言ったものを使って
247	247	単一のファイルをパースする複数のプロセスに割り当てることで分割することも、
248	248	利用可能な C<CPU> リソースの仕様を最適化する有用な方法になり得ますが、
249	249	このテクニックは並列性の問題に直面し、詳細に関して高い注目を必要とします。
250	250
251	251	=begin original
252	252
253	253	Every case has a specific application and one or more exceptions, and there is
254	254	no replacement for running a few tests and finding out which method works best
255	255	for your particular environment, this is why writing optimal code is not an
256	256	exact science, and why we love using Perl so much - TMTOWTDI.
257	257
258	258	=end original
259	259
260	260	それぞれのケースには特定のアプリケーションと一つまたは複数の例外があり、
261	261	いくつかテストを実行して、特定の環境にとってどの手法が最良かを見つけることに
262	262	代わるものはありません; これは、最適なコードを書くことが正確な科学ではない
263	263	理由であり、我々が Perl を使うのをとても愛している理由です - TMTOWTDI。
264	264
265	265	=head1 BENCHMARKS
266	266
267	267	(ベンチマーク)
268	268
269	269	=begin original
270	270
271	271	Here are a few examples to demonstrate usage of Perl's benchmarking tools.
272	272
273	273	=end original
274	274
275	275	以下は、Perl のベンチマークツールの使い方を説明するいくつかの例です。
276	276
277	277	=head2 Assigning and Dereferencing Variables.
278	278
279	279	(変数への代入とデリファレンス)
280	280
281	281	=begin original
282	282
283	283	I'm sure most of us have seen code which looks like, (or worse than), this:
284	284
285	285	=end original
286	286
287	287	私たちのほとんどは、以下のような(あるいはもっとひどい)コードを見たことが
288	288	あるはずです:
289	289
290	290	if ( $obj->{_ref}->{_myscore} >= $obj->{_ref}->{_yourscore} ) {
291	291	...
292	292
293	293	=begin original
294	294
295	295	This sort of code can be a real eyesore to read, as well as being very
296	296	sensitive to typos, and it's much clearer to dereference the variable
297	297	explicitly. We're side-stepping the issue of working with object-oriented
298	298	programming techniques to encapsulate variable access via methods, only
299	299	accessible through an object. Here we're just discussing the technical
300	300	implementation of choice, and whether this has an effect on performance. We
301	301	can see whether this dereferencing operation, has any overhead by putting
302	302	comparative code in a file and running a C<Benchmark> test.
303	303
304	304	=end original
305	305
306	306	この種類のコードは読むと目が疲れ、タイプミスに弱く、変数を明示的に
307	307	デリファレンスすることで遥かに明確になります。
308	308	変数アクセスをメソッド経由でカプセル化して、オブジェクトを通してのみ
309	309	アクセス可能にすると言うオブジェクト指向プログラミングのテクニックを
310	310	使う問題を横に避けておきます。
311	311	ここでは単に選択する技術実装に関して、そしてこれが性能が向上するかどうかを
312	312	議論しています。
313	313	このデリファレンス操作がかなりのコードをファイルに置くことによる
314	314	オーバーヘッドがあるのかを C<Benchmark> テストで見てみます。
315	315
316	316	=begin original
317	317
318	318	# dereference
319	319
320	320	=end original
321	321
322	322	# デリファレンス
323	323
324	324	#!/usr/bin/perl
325	325
326	326	use strict;
327	327	use warnings;
328	328
329	329	use Benchmark;
330	330
331	331	my $ref = {
332	332	'ref' => {
333	333	_myscore => '100 + 1',
334	334	_yourscore => '102 - 1',
335	335	},
336	336	};
337	337
338	338	timethese(1000000, {
339	339	'direct' => sub {
340	340	my $x = $ref->{ref}->{_myscore} . $ref->{ref}->{_yourscore} ;
341	341	},
342	342	'dereference' => sub {
343	343	my $ref = $ref->{ref};
344	344	my $myscore = $ref->{_myscore};
345	345	my $yourscore = $ref->{_yourscore};
346	346	my $x = $myscore . $yourscore;
347	347	},
348	348	});
349	349
350	350	=begin original
351	351
352	352	It's essential to run any timing measurements a sufficient number of times so
353	353	the numbers settle on a numerical average, otherwise each run will naturally
354	354	fluctuate due to variations in the environment, to reduce the effect of
355	355	contention for C<CPU> resources and network bandwidth for instance. Running
356	356	the above code for one million iterations, we can take a look at the report
357	357	output by the C<Benchmark> module, to see which approach is the most effective.
358	358
359	359	=end original
360	360
361	361	時間計測は、平均を安定させるために十分な回数行うことが重要です;
362	362	さもなければそれぞれの実行は、例えば C<CPU> リソースの競合の効果や
363	363	ネットワーク帯域のような環境の変化によって自然に変動します。
364	364	どの手法が最も効果的を見るために、上述のコードを 100 万回繰り返して、
365	365	C<Benchmark> モジュールによって出力された報告を見てみます。
366	366
367	367	$> perl dereference
368	368
369	369	Benchmark: timing 1000000 iterations of dereference, direct...
370	370	dereference: 2 wallclock secs ( 1.59 usr + 0.00 sys = 1.59 CPU) @ 628930.82/s (n=1000000)
371	371	direct: 1 wallclock secs ( 1.20 usr + 0.00 sys = 1.20 CPU) @ 833333.33/s (n=1000000)
372	372
373	373	=begin original
374	374
375	375	The difference is clear to see and the dereferencing approach is slower. While
376	376	it managed to execute an average of 628,930 times a second during our test, the
377	377	direct approach managed to run an additional 204,403 times, unfortunately.
378	378	Unfortunately, because there are many examples of code written using the
379	379	multiple layer direct variable access, and it's usually horrible. It is,
380	380	however, minusculy faster. The question remains whether the minute gain is
381	381	actually worth the eyestrain, or the loss of maintainability.
382	382
383	383	=end original
384	384
385	385	違いははっきりと見え、デリファレンスの手法はより遅いです。
386	386	これはテスト中 1 秒間に平均して 628,930 回実行しましたが、直接手法は
387	387	残念ながらさらに 204,403 回実行しています。
388	388	残念ながら、複数層の直接変数アクセスを使ったコード例がたくさんあるので、
389	389	これは普通は恐ろしいものです。
390	390	しかし、これはほんの少し速いです。
391	391	問題は、ほんの少しの向上が疲れ目と保守性の喪失の価値があるかです。
392	392
393	393	=head2 Search and replace or tr
394	394
395	395	(検索と置換または tr)
396	396
397	397	=begin original
398	398
399	399	If we have a string which needs to be modified, while a regex will almost
400	400	always be much more flexible, C<tr>, an oft underused tool, can still be a
401	401	useful. One scenario might be replace all vowels with another character. The
402	402	regex solution might look like this:
403	403
404	404	=end original
405	405
406	406	変更する必要がある文字列がある場合、正規表現はほとんど常により柔軟性が
407	407	ありますが、活用されていない C<tr> も依然有用です。
408	408	一つのシナリオとしては、全ての母音を他の文字に置換するというものです。
409	409	正規表現による解放は以下のようなものになるでしょう:
410	410
411	411	$str =~ s/[aeiou]/x/g
412	412
413	413	=begin original
414	414
415	415	The C<tr> alternative might look like this:
416	416
417	417	=end original
418	418
419	419	C<tr> による代替案は以下のようになります:
420	420
421	421	$str =~ tr/aeiou/xxxxx/
422	422
423	423	=begin original
424	424
425	425	We can put that into a test file which we can run to check which approach is
426	426	the fastest, using a global C<$STR> variable to assign to the C<my $str>
427	427	variable so as to avoid perl trying to optimize any of the work away by
428	428	noticing it's assigned only the once.
429	429
430	430	=end original
431	431
432	432	どの手法が一番早いかをチェックするために、実行するテストファイルにこれを
433	433	置きます; perl が一度しか代入されないことを気付くことで処理しないように
434	434	最適化しようとすることを避けるために、C<my $str> 変数へ代入するために
435	435	グローバルな C<$STR> 変数を使います。
436	436
437	437	=begin original
438	438
439	439	# regex-transliterate
440	440
441	441	=end original
442	442
443	443	# 正規表現-文字変換
444	444
445	445	#!/usr/bin/perl
446	446
447	447	use strict;
448	448	use warnings;
449	449
450	450	use Benchmark;
451	451
452	452	my $STR = "$$-this and that";
453	453
454	454	timethese( 1000000, {
455	455	'sr' => sub { my $str = $STR; $str =~ s/[aeiou]/x/g; return $str; },
456	456	'tr' => sub { my $str = $STR; $str =~ tr/aeiou/xxxxx/; return $str; },
457	457	});
458	458
459	459	=begin original
460	460
461	461	Running the code gives us our results:
462	462
463	463	=end original
464	464
465	465	コードを実行することで結果が得られます:
466	466
467	467	$> perl regex-transliterate
468	468
469	469	Benchmark: timing 1000000 iterations of sr, tr...
470	470	sr: 2 wallclock secs ( 1.19 usr + 0.00 sys = 1.19 CPU) @ 840336.13/s (n=1000000)
471	471	tr: 0 wallclock secs ( 0.49 usr + 0.00 sys = 0.49 CPU) @ 2040816.33/s (n=1000000)
472	472
473	473	=begin original
474	474
475	475	The C<tr> version is a clear winner. One solution is flexible, the other is
476	476	fast - and it's appropriately the programmer's choice which to use.
477	477
478	478	=end original
479	479
480	480	C<tr> 版が明らかな勝者です。
481	481	ある解決法は柔軟性があり、他の解決法は高速です - そして適切に
482	482	どちらを使うかはプログラマの選択です。
483	483
484	484	=begin original
485	485
486	486	Check the C<Benchmark> docs for further useful techniques.
487	487
488	488	=end original
489	489
490	490	さらなる有用なテクニックについては C<Benchmark> の文書を参照してください。
491	491
492	492	=head1 PROFILING TOOLS
493	493
494	494	(プロファイリングツール)
495	495
496	496	=begin original
497	497
498	498	A slightly larger piece of code will provide something on which a profiler can
499	499	produce more extensive reporting statistics. This example uses the simplistic
500	500	C<wordmatch> program which parses a given input file and spews out a short
501	501	report on the contents.
502	502
503	503	=end original
504	504
505	505	やや大きめのコードではプロファイラが生成するより大規模な状況報告が
506	506	何かを提供するでしょう。
507	507	この例は、与えられた入力ファイルをパースして、内容の短いレポートを出力する
508	508	単純な C<wordmatch> プログラムを使います。
509	509
510	510	=begin original
511	511
512	512	# wordmatch
513	513
514	514	=end original
515	515
516	516	# 単語マッチング
517	517
518	518	#!/usr/bin/perl
519	519
520	520	use strict;
521	521	use warnings;
522	522
523	523	=head1 NAME
524	524
525	525	filewords - word analysis of input file
526	526
527	527	=head1 SYNOPSIS
528	528
529	529	filewords -f inputfilename [-d]
530	530
531	531	=head1 DESCRIPTION
532	532
533	533	This program parses the given filename, specified with C<-f>, and displays a
534	534	simple analysis of the words found therein. Use the C<-d> switch to enable
535	535	debugging messages.
536	536
537	537	=cut
538	538
539	539	use FileHandle;
540	540	use Getopt::Long;
541	541
542	542	my $debug = 0;
543	543	my $file = '';
544	544
545	545	my $result = GetOptions (
546	546	'debug' => \$debug,
547	547	'file=s' => \$file,
548	548	);
549	549	die("invalid args") unless $result;
550	550
551	551	unless ( -f $file ) {
552	552	die("Usage: $0 -f filename [-d]");
553	553	}
554	554	my $FH = FileHandle->new("< $file") or die("unable to open file($file): $!");
555	555
556	556	my $i_LINES = 0;
557	557	my $i_WORDS = 0;
558	558	my %count = ();
559	559
560	560	my @lines = <$FH>;
561	561	foreach my $line ( @lines ) {
562	562	$i_LINES++;
563	563	$line =~ s/\n//;
564	564	my @words = split(/ +/, $line);
565	565	my $i_words = scalar(@words);
566	566	$i_WORDS = $i_WORDS + $i_words;
567	567	debug("line: $i_LINES supplying $i_words words: @words");
568	568	my $i_word = 0;
569	569	foreach my $word ( @words ) {
570	570	$i_word++;
571	571	$count{$i_LINES}{spec} += matches($i_word, $word, '[^a-zA-Z0-9]');
572	572	$count{$i_LINES}{only} += matches($i_word, $word, '^[^a-zA-Z0-9]+$');
573	573	$count{$i_LINES}{cons} += matches($i_word, $word, '^[(?i:bcdfghjklmnpqrstvwxyz)]+$');
574	574	$count{$i_LINES}{vows} += matches($i_word, $word, '^[(?i:aeiou)]+$');
575	575	$count{$i_LINES}{caps} += matches($i_word, $word, '^[(A-Z)]+$');
576	576	}
577	577	}
578	578
579	579	print report( %count );
580	580
581	581	sub matches {
582	582	my $i_wd = shift;
583	583	my $word = shift;
584	584	my $regex = shift;
585	585	my $has = 0;
586	586
587	587	if ( $word =~ /($regex)/ ) {
588	588	$has++ if $1;
589	589	}
590	590
591	591	debug("word: $i_wd ".($has ? 'matches' : 'does not match')." chars: /$regex/");
592	592
593	593	return $has;
594	594	}
595	595
596	596	sub report {
597	597	my %report = @_;
598	598	my %rep;
599	599
600	600	foreach my $line ( keys %report ) {
601	601	foreach my $key ( keys %{ $report{$line} } ) {
602	602	$rep{$key} += $report{$line}{$key};
603	603	}
604	604	}
605	605
606	606	my $report = qq\|
607	607	$0 report for $file:
608	608	lines in file: $i_LINES
609	609	words in file: $i_WORDS
610	610	words with special (non-word) characters: $i_spec
611	611	words with only special (non-word) characters: $i_only
612	612	words with only consonants: $i_cons
613	613	words with only capital letters: $i_caps
614	614	words with only vowels: $i_vows
615	615	\|;
616	616
617	617	return $report;
618	618	}
619	619
620	620	sub debug {
621	621	my $message = shift;
622	622
623	623	if ( $debug ) {
624	624	print STDERR "DBG: $message\n";
625	625	}
626	626	}
627	627
628	628	exit 0;
629	629
630	630	=head2 Devel::DProf
631	631
632	632	=begin original
633	633
634	634	This venerable module has been the de-facto standard for Perl code profiling
635	635	for more than a decade, but has been replaced by a number of other modules
636	636	which have brought us back to the 21st century. Although you're recommended to
637	637	evaluate your tool from the several mentioned here and from the CPAN list at
638	638	the base of this document, (and currently L<Devel::NYTProf> seems to be the
639	639	weapon of choice - see below), we'll take a quick look at the output from
640	640	L<Devel::DProf> first, to set a baseline for Perl profiling tools. Run the
641	641	above program under the control of C<Devel::DProf> by using the C<-d> switch on
642	642	the command-line.
643	643
644	644	=end original
645	645
646	646	この由緒あるモジュールは 10 年以上 Perl コードプロファイリングのデファクト
647	647	スタンダードでしたが、21 世紀になって色々なその他のモジュールに
648	648	置き換えられています。
649	649	いくつかここで言及されたり、この文書の基礎となる CPAN リストからツールを
650	650	評価することを勧められていますが、(そして現在のところ L<Devel::NYTProf> が
651	651	選択する武器のようですが - 後述します)、Perl プロファイリングツールの
652	652	基本となる L<Devel::DProf> からの出力をまず簡単に見てみます。
653	653	コマンドラインで C<-d> オプションを使うことで C<Devel::DProf> の制御下で
654	654	プログラムを実行します。
655	655
656	656	$> perl -d:DProf wordmatch -f perl5db.pl
657	657
658	658	<...multiple lines snipped...>
659	659
660	660	wordmatch report for perl5db.pl:
661	661	lines in file: 9428
662	662	words in file: 50243
663	663	words with special (non-word) characters: 20480
664	664	words with only special (non-word) characters: 7790
665	665	words with only consonants: 4801
666	666	words with only capital letters: 1316
667	667	words with only vowels: 1701
668	668
669	669	=begin original
670	670
671	671	C<Devel::DProf> produces a special file, called F<tmon.out> by default, and
672	672	this file is read by the C<dprofpp> program, which is already installed as part
673	673	of the C<Devel::DProf> distribution. If you call C<dprofpp> with no options,
674	674	it will read the F<tmon.out> file in the current directory and produce a human
675	675	readable statistics report of the run of your program. Note that this may take
676	676	a little time.
677	677
678	678	=end original
679	679
680	680	C<Devel::DProf> は、デフォルトでは F<tmon.out> という名前の特殊なファイルを
681	681	出力し、このファイルは C<Devel::DProf> ディストリビューションの一部として
682	682	既にインストールされている C<dprofpp> プログラムによって読み込まれます。
683	683	オプションなしで C<dprofpp> を呼び出すと、カレントディレクトリの
684	684	F<tmon.out> ファイルを読み込んで、あなたのプログラムの実行に関する
685	685	人間が読める形での統計情報を出力します。
686	686	これには少し時間がかかるかもしれないことに注意してください。
687	687
688	688	$> dprofpp
689	689
690	690	Total Elapsed Time = 2.951677 Seconds
691	691	User+System Time = 2.871677 Seconds
692	692	Exclusive Times
693	693	%Time ExclSec CumulS #Calls sec/call Csec/c Name
694	694	102. 2.945 3.003 251215 0.0000 0.0000 main::matches
695	695	2.40 0.069 0.069 260643 0.0000 0.0000 main::debug
696	696	1.74 0.050 0.050 1 0.0500 0.0500 main::report
697	697	1.04 0.030 0.049 4 0.0075 0.0123 main::BEGIN
698	698	0.35 0.010 0.010 3 0.0033 0.0033 Exporter::as_heavy
699	699	0.35 0.010 0.010 7 0.0014 0.0014 IO::File::BEGIN
700	700	0.00 - -0.000 1 - - Getopt::Long::FindOption
701	701	0.00 - -0.000 1 - - Symbol::BEGIN
702	702	0.00 - -0.000 1 - - Fcntl::BEGIN
703	703	0.00 - -0.000 1 - - Fcntl::bootstrap
704	704	0.00 - -0.000 1 - - warnings::BEGIN
705	705	0.00 - -0.000 1 - - IO::bootstrap
706	706	0.00 - -0.000 1 - - Getopt::Long::ConfigDefaults
707	707	0.00 - -0.000 1 - - Getopt::Long::Configure
708	708	0.00 - -0.000 1 - - Symbol::gensym
709	709
710	710	=begin original
711	711
712	712	C<dprofpp> will produce some quite detailed reporting on the activity of the
713	713	C<wordmatch> program. The wallclock, user and system, times are at the top of
714	714	the analysis, and after this are the main columns defining which define the
715	715	report. Check the C<dprofpp> docs for details of the many options it supports.
716	716
717	717	=end original
718	718
719	719	C<dprofpp> は C<wordmatch> プログラムの活動のかなり詳細な報告を出力します。
720	720	壁時計時間、ユーザーとシステム時間が分析の先頭にあり、その後は報告を
721	721	定義する定義で主な列です。
722	722	対応している多くのオプションの詳細については C<dprofpp> の文書を
723	723	チェックしてください。
724	724
725	725	=begin original
726	726
727	727	See also C<Apache::DProf> which hooks C<Devel::DProf> into C<mod_perl>.
728	728
729	729	=end original
730	730
731	731	C<Devel::DProf> を C<mod_perl> にフックする C<Apache::DProf> も
732	732	参照してください。
733	733
734	734	=head2 Devel::Profiler
735	735
736	736	=begin original
737	737
738	738	Let's take a look at the same program using a different profiler:
739	739	C<Devel::Profiler>, a drop-in Perl-only replacement for C<Devel::DProf>. The
740	740	usage is very slightly different in that instead of using the special C<-d:>
741	741	flag, you pull C<Devel::Profiler> in directly as a module using C<-M>.
742	742
743	743	=end original
744	744
745	745	同じプログラムの他のプロファイラによる結果も見てみましょう:
746	746	C<Devel::Profiler> は C<Devel::DProf> の Perl 専用のドロップインです。
747	747	使用法は特殊な C<-d:> フラグを使うのとはほんの少し違って、
748	748	C<Devel::Profiler> を C<-M> を使ってモジュールとして直接読み込みます。
749	749
750	750	$> perl -MDevel::Profiler wordmatch -f perl5db.pl
751	751
752	752	<...multiple lines snipped...>
753	753
754	754	wordmatch report for perl5db.pl:
755	755	lines in file: 9428
756	756	words in file: 50243
757	757	words with special (non-word) characters: 20480
758	758	words with only special (non-word) characters: 7790
759	759	words with only consonants: 4801
760	760	words with only capital letters: 1316
761	761	words with only vowels: 1701
762	762
763	763	=begin original
764	764
765	765	C<Devel::Profiler> generates a tmon.out file which is compatible with the
766	766	C<dprofpp> program, thus saving the construction of a dedicated statistics
767	767	reader program. C<dprofpp> usage is therefore identical to the above example.
768	768
769	769	=end original
770	770
771	771	C<Devel::Profiler> は C<dprofpp> プログラムと互換性のある tmon.out ファイルを
772	772	生成するので、専用の統計読み込みプログラムの構築を省略できます。
773	773	従って C<dprofpp> の使用法は上述の例と同じです。
774	774
775	775	$> dprofpp
776	776
777	777	Total Elapsed Time = 20.984 Seconds
778	778	User+System Time = 19.981 Seconds
779	779	Exclusive Times
780	780	%Time ExclSec CumulS #Calls sec/call Csec/c Name
781	781	49.0 9.792 14.509 251215 0.0000 0.0001 main::matches
782	782	24.4 4.887 4.887 260643 0.0000 0.0000 main::debug
783	783	0.25 0.049 0.049 1 0.0490 0.0490 main::report
784	784	0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::GetOptions
785	785	0.00 0.000 0.000 2 0.0000 0.0000 Getopt::Long::ParseOptionSpec
786	786	0.00 0.000 0.000 1 0.0000 0.0000 Getopt::Long::FindOption
787	787	0.00 0.000 0.000 1 0.0000 0.0000 IO::File::new
788	788	0.00 0.000 0.000 1 0.0000 0.0000 IO::Handle::new
789	789	0.00 0.000 0.000 1 0.0000 0.0000 Symbol::gensym
790	790	0.00 0.000 0.000 1 0.0000 0.0000 IO::File::open
791	791
792	792	=begin original
793	793
794	794	Interestingly we get slightly different results, which is mostly because the
795	795	algorithm which generates the report is different, even though the output file
796	796	format was allegedly identical. The elapsed, user and system times are clearly
797	797	showing the time it took for C<Devel::Profiler> to execute its own run, but
798	798	the column listings feel more accurate somehow than the ones we had earlier
799	799	from C<Devel::DProf>. The 102% figure has disappeared, for example. This is
800	800	where we have to use the tools at our disposal, and recognise their pros and
801	801	cons, before using them. Interestingly, the numbers of calls for each
802	802	subroutine are identical in the two reports, it's the percentages which differ.
803	803	As the author of C<Devel::Proviler> writes:
804	804
805	805	=end original
806	806
807	807	興味深いことに少し異なった結果が得られました; その理由のほとんどは、
808	808	出力ファイル形式は同一とされているにも関わらず、報告を生成するアルゴリズムが
809	809	異なることです。
810	810	経過時間とユーザー+システム時間は明らかに C<Devel::Profiler> が自身の実行で
811	811	かかった時間を表示してますが、列一覧は先に C<Devel::DProf> で得られたものより
812	812	いくらかより正確なものに感じられます。
813	813	例えば、102% の図は消えました。
814	814	これが、ツールを使ってみて、それらを使う前にそれらの利点と欠点を認識する
815	815	必要があるところです。
816	816	興味深いことに、それぞれのサブルーチンの呼び出し回数は二つの報告で
817	817	同じですが、百分率は異なっています。
818	818	C<Devel::Proviler> の作者が書いているように:
819	819
820	820	...running HTML::Template's test suite under Devel::DProf shows output()
821	821	taking NO time but Devel::Profiler shows around 10% of the time is in output().
822	822	I don't know which to trust but my gut tells me something is wrong with
823	823	Devel::DProf. HTML::Template::output() is a big routine that's called for
824	824	every test. Either way, something needs fixing.
825	825
826	826	=begin original
827	827
828	828	YMMV.
829	829
830	830	=end original
831	831
832	832	あなたの意見は違うかもしれません。
833	833
834	834	=begin original
835	835
836	836	See also C<Devel::Apache::Profiler> which hooks C<Devel::Profiler> into C<mod_perl>.
837	837
838	838	=end original
839	839
840	840	C<mod_perl> に C<Devel::Profiler> フックを付ける
841	841	C<Devel::Apache::Profiler> も参照してください。
842	842
843	843	=head2 Devel::SmallProf
844	844
845	845	=begin original
846	846
847	847	The C<Devel::SmallProf> profiler examines the runtime of your Perl program and
848	848	produces a line-by-line listing to show how many times each line was called,
849	849	and how long each line took to execute. It is called by supplying the familiar
850	850	C<-d> flag to Perl at runtime.
851	851
852	852	=end original
853	853
854	854	C<Devel::SmallProf> プロファイラは Perl プログラムの実行時間を調べて、
855	855	それぞれの行が何回呼び出されたかをしめす行単位の一覧を出力します。
856	856	これは実行時に Perl に親しんだ C<-d> フラグを指定することで呼び出されます。
857	857
858	858	$> perl -d:SmallProf wordmatch -f perl5db.pl
859	859
860	860	<...multiple lines snipped...>
861	861
862	862	wordmatch report for perl5db.pl:
863	863	lines in file: 9428
864	864	words in file: 50243
865	865	words with special (non-word) characters: 20480
866	866	words with only special (non-word) characters: 7790
867	867	words with only consonants: 4801
868	868	words with only capital letters: 1316
869	869	words with only vowels: 1701
870	870
871	871	=begin original
872	872
873	873	C<Devel::SmallProf> writes it's output into a file called F<smallprof.out>, by
874	874	default. The format of the file looks like this:
875	875
876	876	=end original
877	877
878	878	C<Devel::SmallProf> は出力を、デフォルトでは F<smallprof.out> と呼ばれる
879	879	ファイルに書き込みます。
880	880	ファイルの形式は以下のようなものです:
881	881
882	882	<num> <time> <ctime> <line>:<text>
883	883
884	884	=begin original
885	885
886	886	When the program has terminated, the output may be examined and sorted using
887	887	any standard text filtering utilities. Something like the following may be
888	888	sufficient:
889	889
890	890	=end original
891	891
892	892	プログラムが終了したとき、出力は任意の標準テキストフィルタリング
893	893	ユーティリティを使って検査とソートが行われます。
894	894	以下のようなもので十分でしょう:
895	895
896	896	$> cat smallprof.out \| grep \d*: \| sort -k3 \| tac \| head -n20
897	897
898	898	251215 1.65674 7.68000 75: if ( $word =~ /($regex)/ ) {
899	899	251215 0.03264 4.40000 79: debug("word: $i_wd ".($has ? 'matches' :
900	900	251215 0.02693 4.10000 81: return $has;
901	901	260643 0.02841 4.07000 128: if ( $debug ) {
902	902	260643 0.02601 4.04000 126: my $message = shift;
903	903	251215 0.02641 3.91000 73: my $has = 0;
904	904	251215 0.03311 3.71000 70: my $i_wd = shift;
905	905	251215 0.02699 3.69000 72: my $regex = shift;
906	906	251215 0.02766 3.68000 71: my $word = shift;
907	907	50243 0.59726 1.00000 59: $count{$i_LINES}{cons} =
908	908	50243 0.48175 0.92000 61: $count{$i_LINES}{spec} =
909	909	50243 0.00644 0.89000 56: my $i_cons = matches($i_word, $word,
910	910	50243 0.48837 0.88000 63: $count{$i_LINES}{caps} =
911	911	50243 0.00516 0.88000 58: my $i_caps = matches($i_word, $word, '^[(A-
912	912	50243 0.00631 0.81000 54: my $i_spec = matches($i_word, $word, '[^a-
913	913	50243 0.00496 0.80000 57: my $i_vows = matches($i_word, $word,
914	914	50243 0.00688 0.80000 53: $i_word++;
915	915	50243 0.48469 0.79000 62: $count{$i_LINES}{only} =
916	916	50243 0.48928 0.77000 60: $count{$i_LINES}{vows} =
917	917	50243 0.00683 0.75000 55: my $i_only = matches($i_word, $word, '^[^a-
918	918
919	919	=begin original
920	920
921	921	You can immediately see a slightly different focus to the subroutine profiling
922	922	modules, and we start to see exactly which line of code is taking the most
923	923	time. That regex line is looking a bit suspicious, for example. Remember that
924	924	these tools are supposed to be used together, there is no single best way to
925	925	profile your code, you need to use the best tools for the job.
926	926
927	927	=end original
928	928
929	929	サブルーチンプロファイリングモジュールとは少し異なったフォーカスであることが
930	930	すぐに分かります; そして正確にコードのどの行が一番時間がかかるかを
931	931	見始めます。
932	932	例えば、正規表現行は少し疑わしく見えます。
933	933	これらのツールは互いに使われることを想定されていて、コードを
934	934	プロファイリングする単一の最良の方法というのはなく、仕事によって最良の
935	935	ツールを使う必要があると言うことを忘れないでください。
936	936
937	937	=begin original
938	938
939	939	See also C<Apache::SmallProf> which hooks C<Devel::SmallProf> into C<mod_perl>.
940	940
941	941	=end original
942	942
943	943	C<mod_perl> に C<Devel::SmallProf> フックを付ける C<Apache::SmallProf> も
944	944	参照してください。
945	945
946	946	=head2 Devel::FastProf
947	947
948	948	=begin original
949	949
950	950	C<Devel::FastProf> is another Perl line profiler. This was written with a view
951	951	to getting a faster line profiler, than is possible with for example
952	952	C<Devel::SmallProf>, because it's written in C<C>. To use C<Devel::FastProf>,
953	953	supply the C<-d> argument to Perl:
954	954
955	955	=end original
956	956
957	957	C<Devel::FastProf> はもう一つの Perl 行プロファイラです。
958	958	これは、例えば C<Devel::SmallProf> などよりも速い行プロファイラとして
959	959	C<C> で書かれました。
960	960	C<Devel::FastProf> を使うには、Perl に C<-d> オプションを指定します:
961	961
962	962	$> perl -d:FastProf wordmatch -f perl5db.pl
963	963
964	964	<...multiple lines snipped...>
965	965
966	966	wordmatch report for perl5db.pl:
967	967	lines in file: 9428
968	968	words in file: 50243
969	969	words with special (non-word) characters: 20480
970	970	words with only special (non-word) characters: 7790
971	971	words with only consonants: 4801
972	972	words with only capital letters: 1316
973	973	words with only vowels: 1701
974	974
975	975	=begin original
976	976
977	977	C<Devel::FastProf> writes statistics to the file F<fastprof.out> in the current
978	978	directory. The output file, which can be specified, can be interpreted by using
979	979	the C<fprofpp> command-line program.
980	980
981	981	=end original
982	982
983	983	C<Devel::FastProf> は現在のディレクトリのファイル F<fastprof.out> に
984	984	統計情報を書き込みます。
985	985	指定可能な出力ファイルは C<fprofpp> コマンドラインプログラムを使って
986	986	解釈されます。
987	987
988	988	$> fprofpp \| head -n20
989	989
990	990	# fprofpp output format is:
991	991	# filename:line time count: source
992	992	wordmatch:75 3.93338 251215: if ( $word =~ /($regex)/ ) {
993	993	wordmatch:79 1.77774 251215: debug("word: $i_wd ".($has ? 'matches' : 'does not match')." chars: /$regex/");
994	994	wordmatch:81 1.47604 251215: return $has;
995	995	wordmatch:126 1.43441 260643: my $message = shift;
996	996	wordmatch:128 1.42156 260643: if ( $debug ) {
997	997	wordmatch:70 1.36824 251215: my $i_wd = shift;
998	998	wordmatch:71 1.36739 251215: my $word = shift;
999	999	wordmatch:72 1.35939 251215: my $regex = shift;
1000	1000
1001	1001	=begin original
1002	1002
1003	1003	Straightaway we can see that the number of times each line has been called is
1004	1004	identical to the C<Devel::SmallProf> output, and the sequence is only very
1005	1005	slightly different based on the ordering of the amount of time each line took
1006	1006	to execute, C<if ( $debug ) { > and C<my $message = shift;>, for example. The
1007	1007	differences in the actual times recorded might be in the algorithm used
1008	1008	internally, or it could be due to system resource limitations or contention.
1009	1009
1010	1010	=end original
1011	1011
1012	1012	直ちに、各行が呼び出された回数が C<Devel::SmallProf> の出力と同じで、並びは
1013	1013	各行の実行時間順を基にしてほんの少しだけ異なる(例えば C<if ( $debug ) { > と
1014	1014	C<my $message = shift;>) ことがわかります。
1015	1015	実際に記録されている時間の違いは内部で使われているアルゴリズムかも
1016	1016	しれませんし、システムリソースの制限や衝突によるかもしれません。
1017	1017
1018	1018	=begin original
1019	1019
1020	1020	See also the L<DBIx::Profile> which will profile database queries running
1021	1021	under the C<DBIx::*> namespace.
1022	1022
1023	1023	=end original
1024	1024
1025	1025	C<DBIx::*> 名前空間で実行されるデータベース問い合わせをプロファイルする
1026	1026	L<DBIx::Profile> も参照してください。
1027	1027
1028	1028	=head2 Devel::NYTProf
1029	1029
1030	1030	=begin original
1031	1031
1032	1032	C<Devel::NYTProf> is the B<next generation> of Perl code profiler, fixing many
1033	1033	shortcomings in other tools and implementing many cool features. First of all it
1034	1034	can be used as either a I<line> profiler, a I<block> or a I<subroutine>
1035	1035	profiler, all at once. It can also use sub-microsecond (100ns) resolution on
1036	1036	systems which provide C<clock_gettime()>. It can be started and stopped even
1037	1037	by the program being profiled. It's a one-line entry to profile C<mod_perl>
1038	1038	applications. It's written in C<c> and is probably the fastest profiler
1039	1039	available for Perl. The list of coolness just goes on. Enough of that, let's
1040	1040	see how to it works - just use the familiar C<-d> switch to plug it in and run
1041	1041	the code.
1042	1042
1043	1043	=end original
1044	1044
1045	1045	C<Devel::NYTProf> は B<新世代> Perl コードプロファイラで、他のツールの
1046	1046	多くの欠点を修正し、多くのクールな機能を実装しています。
1047	1047	まず、これは I<行> プロファイラと I<ブロック> または
1048	1048	I<サブルーチン> プロファイラとして一度に使えます。
1049	1049	また、C<clock_gettime()> を提供しているシステムではマイクロ秒未満 (100ns) の
1050	1050	解像度を使えます。
1051	1051	プログラムがプロファイルからでも開始終了できます。
1052	1052	これは C<mod_perl> アプリケーションをプロファイルする一行エントリです。
1053	1053	これは C<c> で書かれていて、おそらく Perl で利用可能な最速の
1054	1054	プロファイラです。
1055	1055	素晴らしさの一覧はまだ続きます。
1056	1056	これで十分でしょうから、どのように動作するかを見てみましょう - 単に親しんだ
1057	1057	C<-d> スイッチを使って、コードを実行します。
1058	1058
1059	1059	$> perl -d:NYTProf wordmatch -f perl5db.pl
1060	1060
1061	1061	wordmatch report for perl5db.pl:
1062	1062	lines in file: 9427
1063	1063	words in file: 50243
1064	1064	words with special (non-word) characters: 20480
1065	1065	words with only special (non-word) characters: 7790
1066	1066	words with only consonants: 4801
1067	1067	words with only capital letters: 1316
1068	1068	words with only vowels: 1701
1069	1069
1070	1070	=begin original
1071	1071
1072	1072	C<NYTProf> will generate a report database into the file F<nytprof.out> by
1073	1073	default. Human readable reports can be generated from here by using the
1074	1074	supplied C<nytprofhtml> (HTML output) and C<nytprofcsv> (CSV output) programs.
1075	1075	We've used the Unix system C<html2text> utility to convert the
1076	1076	F<nytprof/index.html> file for convenience here.
1077	1077
1078	1078	=end original
1079	1079
1080	1080	C<NYTProf> はデフォルトではファイル F<nytprof.out> にレポートデータベースを
1081	1081	生成します。
1082	1082	人間が読める報告は、提供される C<nytprofhtml> (HTML 出力) または
1083	1083	C<nytprofcsv> (CSV 出力) プログラムを使うことでここから生成されます。
1084	1084	F<nytprof/index.html> ファイルをここで便利なように変換するために Unix
1085	1085	システムの C<html2text> ユーティリティを使っています。
1086	1086
1087	1087	$> html2text nytprof/index.html
1088	1088
1089	1089	Performance Profile Index
1090	1090	For wordmatch
1091	1091	Run on Fri Sep 26 13:46:39 2008
1092	1092	Reported on Fri Sep 26 13:47:23 2008
1093	1093
1094	1094	Top 15 Subroutines -- ordered by exclusive time
1095	1095	\|Calls \|P \|F \|Inclusive\|Exclusive\|Subroutine \|
1096	1096	\| \| \| \|Time \|Time \| \|
1097	1097	\|251215\|5 \|1 \|13.09263 \|10.47692 \|main:: \|matches \|
1098	1098	\|260642\|2 \|1 \|2.71199 \|2.71199 \|main:: \|debug \|
1099	1099	\|1 \|1 \|1 \|0.21404 \|0.21404 \|main:: \|report \|
1100	1100	\|2 \|2 \|2 \|0.00511 \|0.00511 \|XSLoader:: \|load (xsub) \|
1101	1101	\|14 \|14\|7 \|0.00304 \|0.00298 \|Exporter:: \|import \|
1102	1102	\|3 \|1 \|1 \|0.00265 \|0.00254 \|Exporter:: \|as_heavy \|
1103	1103	\|10 \|10\|4 \|0.00140 \|0.00140 \|vars:: \|import \|
1104	1104	\|13 \|13\|1 \|0.00129 \|0.00109 \|constant:: \|import \|
1105	1105	\|1 \|1 \|1 \|0.00360 \|0.00096 \|FileHandle:: \|import \|
1106	1106	\|3 \|3 \|3 \|0.00086 \|0.00074 \|warnings::register::\|import \|
1107	1107	\|9 \|3 \|1 \|0.00036 \|0.00036 \|strict:: \|bits \|
1108	1108	\|13 \|13\|13\|0.00032 \|0.00029 \|strict:: \|import \|
1109	1109	\|2 \|2 \|2 \|0.00020 \|0.00020 \|warnings:: \|import \|
1110	1110	\|2 \|1 \|1 \|0.00020 \|0.00020 \|Getopt::Long:: \|ParseOptionSpec\|
1111	1111	\|7 \|7 \|6 \|0.00043 \|0.00020 \|strict:: \|unimport \|
1112	1112
1113	1113	For more information see the full list of 189 subroutines.
1114	1114
1115	1115	=begin original
1116	1116
1117	1117	The first part of the report already shows the critical information regarding
1118	1118	which subroutines are using the most time. The next gives some statistics
1119	1119	about the source files profiled.
1120	1120
1121	1121	=end original
1122	1122
1123	1123	報告の最初の部分は既に、どのサブルーチンが一番時間がかかっているかという
1124	1124	重要な情報を表示しています。
1125	1125	以下はプロファイリングしたソースファイルに関するいくつかの統計情報です。
1126	1126
1127	1127	Source Code Files -- ordered by exclusive time then name
1128	1128	\|Stmts \|Exclusive\|Avg. \|Reports \|Source File \|
1129	1129	\| \|Time \| \| \| \|
1130	1130	\|2699761\|15.66654 \|6e-06 \|line . block . sub\|wordmatch \|
1131	1131	\|35 \|0.02187 \|0.00062\|line . block . sub\|IO/Handle.pm \|
1132	1132	\|274 \|0.01525 \|0.00006\|line . block . sub\|Getopt/Long.pm \|
1133	1133	\|20 \|0.00585 \|0.00029\|line . block . sub\|Fcntl.pm \|
1134	1134	\|128 \|0.00340 \|0.00003\|line . block . sub\|Exporter/Heavy.pm \|
1135	1135	\|42 \|0.00332 \|0.00008\|line . block . sub\|IO/File.pm \|
1136	1136	\|261 \|0.00308 \|0.00001\|line . block . sub\|Exporter.pm \|
1137	1137	\|323 \|0.00248 \|8e-06 \|line . block . sub\|constant.pm \|
1138	1138	\|12 \|0.00246 \|0.00021\|line . block . sub\|File/Spec/Unix.pm \|
1139	1139	\|191 \|0.00240 \|0.00001\|line . block . sub\|vars.pm \|
1140	1140	\|77 \|0.00201 \|0.00003\|line . block . sub\|FileHandle.pm \|
1141	1141	\|12 \|0.00198 \|0.00016\|line . block . sub\|Carp.pm \|
1142	1142	\|14 \|0.00175 \|0.00013\|line . block . sub\|Symbol.pm \|
1143	1143	\|15 \|0.00130 \|0.00009\|line . block . sub\|IO.pm \|
1144	1144	\|22 \|0.00120 \|0.00005\|line . block . sub\|IO/Seekable.pm \|
1145	1145	\|198 \|0.00085 \|4e-06 \|line . block . sub\|warnings/register.pm\|
1146	1146	\|114 \|0.00080 \|7e-06 \|line . block . sub\|strict.pm \|
1147	1147	\|47 \|0.00068 \|0.00001\|line . block . sub\|warnings.pm \|
1148	1148	\|27 \|0.00054 \|0.00002\|line . block . sub\|overload.pm \|
1149	1149	\|9 \|0.00047 \|0.00005\|line . block . sub\|SelectSaver.pm \|
1150	1150	\|13 \|0.00045 \|0.00003\|line . block . sub\|File/Spec.pm \|
1151	1151	\|2701595\|15.73869 \| \|Total \|
1152	1152	\|128647 \|0.74946 \| \|Average \|
1153	1153	\| \|0.00201 \|0.00003\|Median \|
1154	1154	\| \|0.00121 \|0.00003\|Deviation \|
1155	1155
1156	1156	Report produced by the NYTProf 2.03 Perl profiler, developed by Tim Bunce and
1157	1157	Adam Kaplan.
1158	1158
1159	1159	=begin original
1160	1160
1161	1161	At this point, if you're using the I<html> report, you can click through the
1162	1162	various links to bore down into each subroutine and each line of code. Because
1163	1163	we're using the text reporting here, and there's a whole directory full of
1164	1164	reports built for each source file, we'll just display a part of the
1165	1165	corresponding F<wordmatch-line.html> file, sufficient to give an idea of the
1166	1166	sort of output you can expect from this cool tool.
1167	1167
1168	1168	=end original
1169	1169
1170	1170	この点で、I<html> レポートを使っているなら、サブルーチン単位と行単位の
1171	1171	詳細への様々なリンクをクリックできます。
1172	1172	ここではテキストレポートを使っていて、それぞれのソースファイルに対して
1173	1173	ビルドされたレポートファイルがディレクトリにたくさんあるので、対応する
1174	1174	F<wordmatch-line.html> ファイルの一部だけを表示します; この素晴らしいツールで
1175	1175	どのような出力が得られるかの考えを与えるには十分です。
1176	1176
1177	1177	$> html2text nytprof/wordmatch-line.html
1178	1178
1179	1179	Performance Profile -- -block view-.-line view-.-sub view-
1180	1180	For wordmatch
1181	1181	Run on Fri Sep 26 13:46:39 2008
1182	1182	Reported on Fri Sep 26 13:47:22 2008
1183	1183
1184	1184	File wordmatch
1185	1185
1186	1186	Subroutines -- ordered by exclusive time
1187	1187	\|Calls \|P\|F\|Inclusive\|Exclusive\|Subroutine \|
1188	1188	\| \| \| \|Time \|Time \| \|
1189	1189	\|251215\|5\|1\|13.09263 \|10.47692 \|main::\|matches\|
1190	1190	\|260642\|2\|1\|2.71199 \|2.71199 \|main::\|debug \|
1191	1191	\|1 \|1\|1\|0.21404 \|0.21404 \|main::\|report \|
1192	1192	\|0 \|0\|0\|0 \|0 \|main::\|BEGIN \|
1193	1193
1194	1194	\|Line\|Stmts.\|Exclusive\|Avg. \|Code \|
1195	1195	\| \| \|Time \| \| \|
1196	1196	\|1 \| \| \| \|#!/usr/bin/perl \|
1197	1197	\|2 \| \| \| \| \|
1198	1198	\| \| \| \| \|use strict; \|
1199	1199	\|3 \|3 \|0.00086 \|0.00029\|# spent 0.00003s making 1 calls to strict:: \|
1200	1200	\| \| \| \| \|import \|
1201	1201	\| \| \| \| \|use warnings; \|
1202	1202	\|4 \|3 \|0.01563 \|0.00521\|# spent 0.00012s making 1 calls to warnings:: \|
1203	1203	\| \| \| \| \|import \|
1204	1204	\|5 \| \| \| \| \|
1205	1205	\|6 \| \| \| \|=head1 NAME \|
1206	1206	\|7 \| \| \| \| \|
1207	1207	\|8 \| \| \| \|filewords - word analysis of input file \|
1208	1208	<...snip...>
1209	1209	\|62 \|1 \|0.00445 \|0.00445\|print report( %count ); \|
1210	1210	\| \| \| \| \|# spent 0.21404s making 1 calls to main::report\|
1211	1211	\|63 \| \| \| \| \|
1212	1212	\| \| \| \| \|# spent 23.56955s (10.47692+2.61571) within \|
1213	1213	\| \| \| \| \|main::matches which was called 251215 times, \|
1214	1214	\| \| \| \| \|avg 0.00005s/call: # 50243 times \|
1215	1215	\| \| \| \| \|(2.12134+0.51939s) at line 57 of wordmatch, avg\|
1216	1216	\| \| \| \| \|0.00005s/call # 50243 times (2.17735+0.54550s) \|
1217	1217	\|64 \| \| \| \|at line 56 of wordmatch, avg 0.00005s/call # \|
1218	1218	\| \| \| \| \|50243 times (2.10992+0.51797s) at line 58 of \|
1219	1219	\| \| \| \| \|wordmatch, avg 0.00005s/call # 50243 times \|
1220	1220	\| \| \| \| \|(2.12696+0.51598s) at line 55 of wordmatch, avg\|
1221	1221	\| \| \| \| \|0.00005s/call # 50243 times (1.94134+0.51687s) \|
1222	1222	\| \| \| \| \|at line 54 of wordmatch, avg 0.00005s/call \|
1223	1223	\| \| \| \| \|sub matches { \|
1224	1224	<...snip...>
1225	1225	\|102 \| \| \| \| \|
1226	1226	\| \| \| \| \|# spent 2.71199s within main::debug which was \|
1227	1227	\| \| \| \| \|called 260642 times, avg 0.00001s/call: # \|
1228	1228	\| \| \| \| \|251215 times (2.61571+0s) by main::matches at \|
1229	1229	\|103 \| \| \| \|line 74 of wordmatch, avg 0.00001s/call # 9427 \|
1230	1230	\| \| \| \| \|times (0.09628+0s) at line 50 of wordmatch, avg\|
1231	1231	\| \| \| \| \|0.00001s/call \|
1232	1232	\| \| \| \| \|sub debug { \|
1233	1233	\|104 \|260642\|0.58496 \|2e-06 \|my $message = shift; \|
1234	1234	\|105 \| \| \| \| \|
1235	1235	\|106 \|260642\|1.09917 \|4e-06 \|if ( $debug ) { \|
1236	1236	\|107 \| \| \| \|print STDERR "DBG: $message\n"; \|
1237	1237	\|108 \| \| \| \|} \|
1238	1238	\|109 \| \| \| \|} \|
1239	1239	\|110 \| \| \| \| \|
1240	1240	\|111 \|1 \|0.01501 \|0.01501\|exit 0; \|
1241	1241	\|112 \| \| \| \| \|
1242	1242
1243	1243	=begin original
1244	1244
1245	1245	Oodles of very useful information in there - this seems to be the way forward.
1246	1246
1247	1247	=end original
1248	1248
1249	1249	大量のとても有用な情報がここにあります - これは前進する道のように思えます。
1250	1250
1251	1251	=begin original
1252	1252
1253	1253	See also C<Devel::NYTProf::Apache> which hooks C<Devel::NYTProf> into C<mod_perl>.
1254	1254
1255	1255	=end original
1256	1256
1257	1257	C<mod_perl> に C<Devel::NYTProf> フックを付ける C<Devel::NYTProf::Apache> も
1258	1258	参照してください。
1259	1259
1260	1260	=head1 SORTING
1261	1261
1262	1262	(ソート)
1263	1263
1264	1264	=begin original
1265	1265
1266	1266	Perl modules are not the only tools a performance analyst has at their
1267	1267	disposal, system tools like C<time> should not be overlooked as the next
1268	1268	example shows, where we take a quick look at sorting. Many books, theses and
1269	1269	articles, have been written about efficient sorting algorithms, and this is not
1270	1270	the place to repeat such work, there's several good sorting modules which
1271	1271	deserve taking a look at too: C<Sort::Maker>, C<Sort::Key> spring to mind.
1272	1272	However, it's still possible to make some observations on certain Perl specific
1273	1273	interpretations on issues relating to sorting data sets and give an example or
1274	1274	two with regard to how sorting large data volumes can effect performance.
1275	1275	Firstly, an often overlooked point when sorting large amounts of data, one can
1276	1276	attempt to reduce the data set to be dealt with and in many cases C<grep()> can
1277	1277	be quite useful as a simple filter:
1278	1278
1279	1279	=end original
1280	1280
1281	1281	Perl モジュールは性能分析者が持っている唯一の道具というわけではなく、
1282	1282	ソートについて軽く見てみる次の例のように、C<time> のようなシステムツールも
1283	1283	見落とすべきではありません。
1284	1284	効率的なソートアルゴリズムについて書かれている多くの多くの本、論文、記事が
1285	1285	あり、ここはそのようなことを繰り返す場所ではありません; 調べてみる価値のある
1286	1286	いくつかのよいソートモジュールもあります: C<Sort::Maker>, C<Sort::Key> が
1287	1287	思い浮かびます。
1288	1288	しかし、まだデータ集合のソートに関連する問題の Perl 特有の解釈に関して
1289	1289	いくつか観測できる可能性があるので、大量のデータがどのように性能に
1290	1290	影響するかに関する例をいくつか示します。
1291	1291	最初に、大量のデータをソートするときにしばしば見落とされる点は、扱うデータ
1292	1292	集合を減らそうと出来ることと、多くの場合 C<grep()> が単純なフィルタとして
1293	1293	かなり有用であるということです:
1294	1294
1295	1295	@data = sort grep { /$filter/ } @incoming
1296	1296
1297	1297	=begin original
1298	1298
1299	1299	A command such as this can vastly reduce the volume of material to actually
1300	1300	sort through in the first place, and should not be too lightly disregarded
1301	1301	purely on the basis of its simplicity. The C<KISS> principle is too often
1302	1302	overlooked - the next example uses the simple system C<time> utility to
1303	1303	demonstrate. Let's take a look at an actual example of sorting the contents of
1304	1304	a large file, an apache logfile would do. This one has over a quarter of a
1305	1305	million lines, is 50M in size, and a snippet of it looks like this:
1306	1306
1307	1307	=end original
1308	1308
1309	1309	このようなコマンドは最初に実際にソートする量をとても減らすことが出来、
1310	1310	単純性の原則だけであまり簡単に無視するべきではありません。
1311	1311	C<KISS> 原則はあまりにも見逃されています - 次の例はデモに単純なシステム
1312	1312	C<time> ユーティリティを使います。
1313	1313	大きなファイルの内容をソートするという実際の例を見てみましょう; apache の
1314	1314	ログファイルを使ってみます。
1315	1315	これは 25 万行 50M バイトを超えますが、その一部は以下のようなものです:
1316	1316
1317	1317	=begin original
1318	1318
1319	1319	# logfile
1320	1320
1321	1321	=end original
1322	1322
1323	1323	# ログファイル
1324	1324
1325	1325	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)"
1326	1326	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)"
1327	1327	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"
1328	1328	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"
1329	1329	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"
1330	1330	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)"
1331	1331	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)"
1332	1332	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)"
1333	1333	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)"
1334	1334	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)"
1335	1335	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"
1336	1336	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"
1337	1337	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"
1338	1338	crawl1.cosmixcorp.com - - [08/Feb/2007:13:27:57 +0000] "GET /robots.txt HTTP/1.0" 200 179 "-" "voyager/1.0"
1339	1339	crawl1.cosmixcorp.com - - [08/Feb/2007:13:28:25 +0000] "GET /links.html HTTP/1.0" 200 3413 "-" "voyager/1.0"
1340	1340	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)"
1341	1341	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)"
1342	1342	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)"
1343	1343	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)"
1344	1344	pop.compuscan.co.za - - [08/Feb/2007:14:10:43 +0000] "GET / HTTP/1.1" 200 3309 "-" "www.clamav.net"
1345	1345	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)"
1346	1346	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)"
1347	1347	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"
1348	1348	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"
1349	1349
1350	1350	=begin original
1351	1351
1352	1352	The specific task here is to sort the 286,525 lines of this file by Response
1353	1353	Code, Query, Browser, Referring Url, and lastly Date. One solution might be to
1354	1354	use the following code, which iterates over the files given on the
1355	1355	command-line.
1356	1356
1357	1357	=end original
1358	1358
1359	1359	ここでのタスクは Response Code, Query, Browser, Referring Url,
1360	1360	lastly Date からなる 286,525 行のファイルをソートすることです。
1361	1361	一つの解決法は、以下のコードのようにコマンドラインで指定されたファイルを
1362	1362	反復する方法かもしれません。
1363	1363
1364	1364	=begin original
1365	1365
1366	1366	# sort-apache-log
1367	1367
1368	1368	=end original
1369	1369
1370	1370	# apache のログのソート
1371	1371
1372	1372	#!/usr/bin/perl -n
1373	1373
1374	1374	use strict;
1375	1375	use warnings;
1376	1376
1377	1377	my @data;
1378	1378
1379	1379	LINE:
1380	1380	while ( <> ) {
1381	1381	my $line = $_;
1382	1382	if (
1383	1383	$line =~ m/^(
1384	1384	([\w\.\-]+) # client
1385	1385	\s-\s-\s*\[
1386	1386	([^]]+) # date
1387	1387	\]\s"\w+\s
1388	1388	(\S+) # query
1389	1389	[^"]+"\s*
1390	1390	(\d+) # status
1391	1391	\s+\S+\s+"[^"]*"\s+"
1392	1392	([^"]*) # browser
1393	1393	"
1394	1394	.*
1395	1395	)$/x
1396	1396	) {
1397	1397	my @chunks = split(/ +/, $line);
1398	1398	my $ip = $1;
1399	1399	my $date = $2;
1400	1400	my $query = $3;
1401	1401	my $status = $4;
1402	1402	my $browser = $5;
1403	1403
1404	1404	push(@data, [$ip, $date, $query, $status, $browser, $line]);
1405	1405	}
1406	1406	}
1407	1407
1408	1408	my @sorted = sort {
1409	1409	$a->[3] cmp $b->[3]
1410	1410	\|\|
1411	1411	$a->[2] cmp $b->[2]
1412	1412	\|\|
1413	1413	$a->[0] cmp $b->[0]
1414	1414	\|\|
1415	1415	$a->[1] cmp $b->[1]
1416	1416	\|\|
1417	1417	$a->[4] cmp $b->[4]
1418	1418	} @data;
1419	1419
1420	1420	foreach my $data ( @sorted ) {
1421	1421	print $data->[5];
1422	1422	}
1423	1423
1424	1424	exit 0;
1425	1425
1426	1426	=begin original
1427	1427
1428	1428	When running this program, redirect C<STDOUT> so it is possible to check the
1429	1429	output is correct from following test runs and use the system C<time> utility
1430	1430	to check the overall runtime.
1431	1431
1432	1432	=end original
1433	1433
1434	1434	このプログラムを実行するとき、以後のテストで出力が正しいか
1435	1435	チェックできるように C<STDOUT> をリダイレクトして、全体の実行時間を
1436	1436	チェックするためにシステムの C<time> ユーティリティを使います。
1437	1437
1438	1438	$> time ./sort-apache-log logfile > out-sort
1439	1439
1440	1440	real 0m17.371s
1441	1441	user 0m15.757s
1442	1442	sys 0m0.592s
1443	1443
1444	1444	=begin original
1445	1445
1446	1446	The program took just over 17 wallclock seconds to run. Note the different
1447	1447	values C<time> outputs, it's important to always use the same one, and to not
1448	1448	confuse what each one means.
1449	1449
1450	1450	=end original
1451	1451
1452	1452	プログラムは実行にちょうど 17 壁時計秒ほどかかりました。
1453	1453	C<time> 出力の異なった値に注意して、いつも同じものを使い、それぞれの値の
1454	1454	意味を混乱しないことが重要です。
1455	1455
1456	1456	=over 4
1457	1457
1458	1458	=item Elapsed Real Time
1459	1459
1460	1460	(実経過時間)
1461	1461
1462	1462	=begin original
1463	1463
1464	1464	The overall, or wallclock, time between when C<time> was called, and when it
1465	1465	terminates. The elapsed time includes both user and system times, and time
1466	1466	spent waiting for other users and processes on the system. Inevitably, this is
1467	1467	the most approximate of the measurements given.
1468	1468
1469	1469	=end original
1470	1470
1471	1471	C<time> が呼び出されてからそれが終了するまでの間の全体的な、あるいは
1472	1472	壁時計の、時間です。
1473	1473	経過時間にはユーザー時間とシステム時間、およびシステム上の他のユーザーや
1474	1474	プロセスを待つために費やされた時間を含みます。
1475	1475	必然的に、これは与えられたものに最も近い時間です。
1476	1476
1477	1477	=item User CPU Time
1478	1478
1479	1479	(ユーザー CPU 時間)
1480	1480
1481	1481	=begin original
1482	1482
1483	1483	The user time is the amount of time the entire process spent on behalf of the
1484	1484	user on this system executing this program.
1485	1485
1486	1486	=end original
1487	1487
1488	1488	ユーザー時間はこのシステムでこのプログラムを実行することで消費された
1489	1489	全体のプロセス時間です。
1490	1490
1491	1491	=item System CPU Time
1492	1492
1493	1493	(システム CPU 時間)
1494	1494
1495	1495	=begin original
1496	1496
1497	1497	The system time is the amount of time the kernel itself spent executing
1498	1498	routines, or system calls, on behalf of this process user.
1499	1499
1500	1500	=end original
1501	1501
1502	1502	システム時間はこのプロセスユーザーのためにカーネルが実行したルーチンや
1503	1503	システムコールの時間です。
1504	1504
1505	1505	=back
1506	1506
1507	1507	=begin original
1508	1508
1509	1509	Running this same process as a C<Schwarzian Transform> it is possible to
1510	1510	eliminate the input and output arrays for storing all the data, and work on the
1511	1511	input directly as it arrives too. Otherwise, the code looks fairly similar:
1512	1512
1513	1513	=end original
1514	1514
1515	1515	同じ処理を C<シュワルツ変換> (Schwarzian Transform) として実行すると、
1516	1516	全てのデータを補完するための配列の入出力を除去することができ、
1517	1517	入力を直接届いてすぐに処理します。
1518	1518	さもなければ、コードはほぼ似て見えます:
1519	1519
1520	1520	=begin original
1521	1521
1522	1522	# sort-apache-log-schwarzian
1523	1523
1524	1524	=end original
1525	1525
1526	1526	# apache のログをシュワルツ変換ソート
1527	1527
1528	1528	#!/usr/bin/perl -n
1529	1529
1530	1530	use strict;
1531	1531	use warnings;
1532	1532
1533	1533	print
1534	1534
1535	1535	map $_->[0] =>
1536	1536
1537	1537	sort {
1538	1538	$a->[4] cmp $b->[4]
1539	1539	\|\|
1540	1540	$a->[3] cmp $b->[3]
1541	1541	\|\|
1542	1542	$a->[1] cmp $b->[1]
1543	1543	\|\|
1544	1544	$a->[2] cmp $b->[2]
1545	1545	\|\|
1546	1546	$a->[5] cmp $b->[5]
1547	1547	}
1548	1548	map [ $_, m/^(
1549	1549	([\w\.\-]+) # client
1550	1550	\s-\s-\s*\[
1551	1551	([^]]+) # date
1552	1552	\]\s"\w+\s
1553	1553	(\S+) # query
1554	1554	[^"]+"\s*
1555	1555	(\d+) # status
1556	1556	\s+\S+\s+"[^"]*"\s+"
1557	1557	([^"]*) # browser
1558	1558	"
1559	1559	.*
1560	1560	)$/xo ]
1561	1561
1562	1562	=> <>;
1563	1563
1564	1564	exit 0;
1565	1565
1566	1566	=begin original
1567	1567
1568	1568	Run the new code against the same logfile, as above, to check the new time.
1569	1569
1570	1570	=end original
1571	1571
1572	1572	新しい時間をチェックするために上述のように同じログファイルに対して
1573	1573	新しいコードを実行します。
1574	1574
1575	1575	$> time ./sort-apache-log-schwarzian logfile > out-schwarz
1576	1576
1577	1577	real 0m9.664s
1578	1578	user 0m8.873s
1579	1579	sys 0m0.704s
1580	1580
1581	1581	=begin original
1582	1582
1583	1583	The time has been cut in half, which is a respectable speed improvement by any
1584	1584	standard. Naturally, it is important to check the output is consistent with
1585	1585	the first program run, this is where the Unix system C<cksum> utility comes in.
1586	1586
1587	1587	=end original
1588	1588
1589	1589	時間は半分になりました; これはあらゆる面で立派な速度改善です。
1590	1590	当然ながら、出力が最初のプログラムの実行と一貫性があることをチェックするのは
1591	1591	重要です; ここは Unix システム C<cksum> ユーティリティの出番です。
1592	1592
1593	1593	$> cksum out-sort out-schwarz
1594	1594	3044173777 52029194 out-sort
1595	1595	3044173777 52029194 out-schwarz
1596	1596
1597	1597	=begin original
1598	1598
1599	1599	BTW. Beware too of pressure from managers who see you speed a program up by 50%
1600	1600	of the runtime once, only to get a request one month later to do the same again
1601	1601	(true story) - you'll just have to point out your only human, even if you are a
1602	1602	Perl programmer, and you'll see what you can do...
1603	1603
1604	1604	=end original
1605	1605
1606	1606	ところで。
1607	1607	あなたが一度実行時間を 50% 高速化したのを見た管理者が喜びすぎて、
1608	1608	一ヶ月後にもう一度同じことを要求してくることに注意してください(実話) -
1609	1609	例えあなたが Perl プログラマでもあなたがただの人間であることを
1610	1610	指摘する必要があり、何ができるかを見てみましょう…
1611	1611
1612	1612	=head1 LOGGING
1613	1613
1614	1614	(ロギング)
1615	1615
1616	1616	=begin original
1617	1617
1618	1618	An essential part of any good development process is appropriate error handling
1619	1619	with appropriately informative messages, however there exists a school of
1620	1620	thought which suggests that log files should be I<chatty>, as if the chain of
1621	1621	unbroken output somehow ensures the survival of the program. If speed is in
1622	1622	any way an issue, this approach is wrong.
1623	1623
1624	1624	=end original
1625	1625
1626	1626	良い開発プロセスの本質的な部分は、適切に情報があるメッセージによる
1627	1627	適切なエラー処理ですが、プログラムの生存を確実にするための壊れない
1628	1628	出力のチェーンのように、ログファイルは I<おしゃべり> であるべきという
1629	1629	考え方があります。
1630	1630	速度が問題なら、この手法は間違っています。
1631	1631
1632	1632	=begin original
1633	1633
1634	1634	A common sight is code which looks something like this:
1635	1635
1636	1636	=end original
1637	1637
1638	1638	よく見かけるのは以下のような感じのコードです:
1639	1639
1640	1640	logger->debug( "A logging message via process-id: $$ INC: " . Dumper(\%INC) )
1641	1641
1642	1642	=begin original
1643	1643
1644	1644	The problem is that this code will always be parsed and executed, even when the
1645	1645	debug level set in the logging configuration file is zero. Once the debug()
1646	1646	subroutine has been entered, and the internal C<$debug> variable confirmed to
1647	1647	be zero, for example, the message which has been sent in will be discarded and
1648	1648	the program will continue. In the example given though, the \%INC hash will
1649	1649	already have been dumped, and the message string constructed, all of which work
1650	1650	could be bypassed by a debug variable at the statement level, like this:
1651	1651
1652	1652	=end original
1653	1653
1654	1654	問題は、例えログ設定ファイルのデバッグレベルがゼロでも、このコードは常に
1655	1655	パースされて実行されることです。
1656	1656	例えば、一度 debug() サブルーチンに入って、内部の C<$debug> 変数が
1657	1657	ゼロであることを確認すると、送られたメッセージは捨てられてプログラムは
1658	1658	続行します。
1659	1659	しかし、上述の例では、\%INC はすでにダンプされていて、メッセージ文字列は
1660	1660	構築されていて、このような作業の全ては以下のような文レベルの
1661	1661	デバッグ変数によって回避されるかもしれません:
1662	1662
1663	1663	logger->debug( "A logging message via process-id: $$ INC: " . Dumper(\%INC) ) if $DEBUG;
1664	1664
1665	1665	=begin original
1666	1666
1667	1667	This effect can be demonstrated by setting up a test script with both forms,
1668	1668	including a C<debug()> subroutine to emulate typical C<logger()> functionality.
1669	1669
1670	1670	=end original
1671	1671
1672	1672	この効果は、両方の形式で設定したテストスクリプトで図示します;
1673	1673	これには典型的な C<logger()> 機能をエミュレートするための
1674	1674	C<debug()> サブルーチンです。
1675	1675
1676	1676	=begin original
1677	1677
1678	1678	# ifdebug
1679	1679
1680	1680	=end original
1681	1681
1682	1682	# ifdebug
1683	1683
1684	1684	#!/usr/bin/perl
1685	1685
1686	1686	use strict;
1687	1687	use warnings;
1688	1688
1689	1689	use Benchmark;
1690	1690	use Data::Dumper;
1691	1691	my $DEBUG = 0;
1692	1692
1693	1693	sub debug {
1694	1694	my $msg = shift;
1695	1695
1696	1696	if ( $DEBUG ) {
1697	1697	print "DEBUG: $msg\n";
1698	1698	}
1699	1699	};
1700	1700
1701	1701	timethese(100000, {
1702	1702	'debug' => sub {
1703	1703	debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) )
1704	1704	},
1705	1705	'ifdebug' => sub {
1706	1706	debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if $DEBUG
1707	1707	},
1708	1708	});
1709	1709
1710	1710	=begin original
1711	1711
1712	1712	Let's see what C<Benchmark> makes of this:
1713	1713
1714	1714	=end original
1715	1715
1716	1716	これによって C<Benchmark> がすることを見てみましょう:
1717	1717
1718	1718	$> perl ifdebug
1719	1719	Benchmark: timing 100000 iterations of constant, sub...
1720	1720	ifdebug: 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU) @ 10000000.00/s (n=100000)
1721	1721	(warning: too few iterations for a reliable count)
1722	1722	debug: 14 wallclock secs (13.18 usr + 0.04 sys = 13.22 CPU) @ 7564.30/s (n=100000)
1723	1723
1724	1724	=begin original
1725	1725
1726	1726	In the one case the code, which does exactly the same thing as far as
1727	1727	outputting any debugging information is concerned, in other words nothing,
1728	1728	takes 14 seconds, and in the other case the code takes one hundredth of a
1729	1729	second. Looks fairly definitive. Use a C<$DEBUG> variable BEFORE you call the
1730	1730	subroutine, rather than relying on the smart functionality inside it.
1731	1731
1732	1732	=end original
1733	1733
1734	1734	ある場合では、デバッグ情報を出力するのと全く同じ、言い換えると何もしない
1735	1735	コードが 14 秒掛かっています; 他の場合ではコードは 0.01 秒掛かっています。
1736	1736	かなり明確に見えます。
1737	1737	内部のスマートな機能に依存するのではなく、サブルーチンを呼び出す前に
1738	1738	C<$DEBUG> 変数を使ってください。
1739	1739
1740	1740	=head2 Logging if DEBUG (constant)
1741	1741
1742	1742	(DEBUG (定数) によるロギング)
1743	1743
1744	1744	=begin original
1745	1745
1746	1746	It's possible to take the previous idea a little further, by using a compile
1747	1747	time C<DEBUG> constant.
1748	1748
1749	1749	=end original
1750	1750
1751	1751	コンパイル時 C<DEBUG> 定数を使うことで、前述のアイデアをさらに少し
1752	1752	進めることも可能です。
1753	1753
1754	1754	=begin original
1755	1755
1756	1756	# ifdebug-constant
1757	1757
1758	1758	=end original
1759	1759
1760	1760	# ifdebug-定数
1761	1761
1762	1762	#!/usr/bin/perl
1763	1763
1764	1764	use strict;
1765	1765	use warnings;
1766	1766
1767	1767	use Benchmark;
1768	1768	use Data::Dumper;
1769	1769	use constant
1770	1770	DEBUG => 0
1771	1771	;
1772	1772
1773	1773	sub debug {
1774	1774	if ( DEBUG ) {
1775	1775	my $msg = shift;
1776	1776	print "DEBUG: $msg\n";
1777	1777	}
1778	1778	};
1779	1779
1780	1780	timethese(100000, {
1781	1781	'debug' => sub {
1782	1782	debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) )
1783	1783	},
1784	1784	'constant' => sub {
1785	1785	debug( "A $0 logging message via process-id: $$" . Dumper(\%INC) ) if DEBUG
1786	1786	},
1787	1787	});
1788	1788
1789	1789	=begin original
1790	1790
1791	1791	Running this program produces the following output:
1792	1792
1793	1793	=end original
1794	1794
1795	1795	このプログラムを実行すると以下の出力が得られます:
1796	1796
1797	1797	$> perl ifdebug-constant
1798	1798	Benchmark: timing 100000 iterations of constant, sub...
1799	1799	constant: 0 wallclock secs (-0.00 usr + 0.00 sys = -0.00 CPU) @ -7205759403792793600000.00/s (n=100000)
1800	1800	(warning: too few iterations for a reliable count)
1801	1801	sub: 14 wallclock secs (13.09 usr + 0.00 sys = 13.09 CPU) @ 7639.42/s (n=100000)
1802	1802
1803	1803	=begin original
1804	1804
1805	1805	The C<DEBUG> constant wipes the floor with even the C<$debug> variable,
1806	1806	clocking in at minus zero seconds, and generates a "warning: too few iterations
1807	1807	for a reliable count" message into the bargain. To see what is really going
1808	1808	on, and why we had too few iterations when we thought we asked for 100000, we
1809	1809	can use the very useful C<B::Deparse> to inspect the new code:
1810	1810
1811	1811	=end original
1812	1812
1813	1813	C<DEBUG> 定数は C<$debug> 変数に対してでも床掃除をして、マイナスゼロ秒として
1814	1814	記録しています; さらに
1815	1815	"warning: too few iterations for a reliable count" メッセージを生成します。
1816	1816	何が本当に起きているか、そしてなぜ 100000 を聞いたときに反復が
1817	1817	少なすぎるのかを見るために、新しいコードを調べるためにとても有用な
1818	1818	C<B::Deparse> を使えます:
1819	1819
1820	1820	$> perl -MO=Deparse ifdebug-constant
1821	1821
1822	1822	use Benchmark;
1823	1823	use Data::Dumper;
1824	1824	use constant ('DEBUG', 0);
1825	1825	sub debug {
1826	1826	use warnings;
1827	1827	use strict 'refs';
1828	1828	0;
1829	1829	}
1830	1830	use warnings;
1831	1831	use strict 'refs';
1832	1832	timethese(100000, {'sub', sub {
1833	1833	debug "A $0 logging message via process-id: $$" . Dumper(\%INC);
1834	1834	}
1835	1835	, 'constant', sub {
1836	1836	0;
1837	1837	}
1838	1838	});
1839	1839	ifdebug-constant syntax OK
1840	1840
1841	1841	=begin original
1842	1842
1843	1843	The output shows the constant() subroutine we're testing being replaced with
1844	1844	the value of the C<DEBUG> constant: zero. The line to be tested has been
1845	1845	completely optimized away, and you can't get much more efficient than that.
1846	1846
1847	1847	=end original
1848	1848
1849	1849	出力は、テストしている constant() サブルーチンが C<DEBUG> 定数の値: ゼロに
1850	1850	置き換えられていることを示しています。
1851	1851	テストしたラインは完全に最適化されていて、これ以上すごく効率的にすることは
1852	1852	できません。
1853	1853
1854	1854	=head1 POSTSCRIPT
1855	1855
1856	1856	(あとがき)
1857	1857
1858	1858	=begin original
1859	1859
1860	1860	This document has provided several way to go about identifying hot-spots, and
1861	1861	checking whether any modifications have improved the runtime of the code.
1862	1862
1863	1863	=end original
1864	1864
1865	1865	この文書は、ホットスポットの識別と、どの修正がコードの実行時間を
1866	1866	改善するかのチェックに関するいくつかの方法を提供しました。
1867	1867
1868	1868	=begin original
1869	1869
1870	1870	As a final thought, remember that it's not (at the time of writing) possible to
1871	1871	produce a useful program which will run in zero or negative time and this basic
1872	1872	principle can be written as: I<useful programs are slow> by their very
1873	1873	definition. It is of course possible to write a nearly instantaneous program,
1874	1874	but it's not going to do very much, here's a very efficient one:
1875	1875
1876	1876	=end original
1877	1877
1878	1878	最後の考慮点として、(これを書いている時点では) ゼロまたは負の時間で
1879	1879	実行できる有用なプログラムを作成することは不可能であることを
1880	1880	忘れないでください; そしてこの基本原則は次のように書けます:
1881	1881	定義により、I<有用なプログラムは遅い>。
1882	1882	もちろんほぼ瞬間的に動作するプログラムを書くことは可能ですが、とても
1883	1883	多くのことをすることは出来ません; 以下はとても効率的なものです:
1884	1884
1885	1885	$> perl -e 0
1886	1886
1887	1887	=begin original
1888	1888
1889	1889	Optimizing that any further is a job for C<p5p>.
1890	1890
1891	1891	=end original
1892	1892
1893	1893	これ以上の最適化は C<p5p> の仕事です。
1894	1894
1895	1895	=head1 SEE ALSO
1896	1896
1897	1897	=begin original
1898	1898
1899	1899	Further reading can be found using the modules and links below.
1900	1900
1901	1901	=end original
1902	1902
1903	1903	さらなる読み物は以下のモジュールとリンクを使って得られます。
1904	1904
1905	1905	=head2 PERLDOCS
1906	1906
1907	1907	(perldoc)
1908	1908
1909	1909	=begin original
1910	1910
1911	1911	For example: C<perldoc -f sort>.
1912	1912
1913	1913	=end original
1914	1914
1915	1915	例えば: C<perldoc -f sort>
1916	1916
1917	1917	L<perlfaq4>.
1918	1918
1919	1919	L<perlfork>, L<perlfunc>, L<perlretut>, L<perlthrtut>.
1920	1920
1921	1921	L<threads>.
1922	1922
1923	1923	=head2 MAN PAGES
1924	1924
1925	1925	(man ページ)
1926	1926
1927	1927	C<time>.
1928	1928
1929	1929	=head2 MODULES
1930	1930
1931	1931	(モジュール)
1932	1932
1933	1933	=begin original
1934	1934
1935	1935	It's not possible to individually showcase all the performance related code for
1936	1936	Perl here, naturally, but here's a short list of modules from the CPAN which
1937	1937	deserve further attention.
1938	1938
1939	1939	=end original
1940	1940
1941	1941	当然ながら、Perl で性能に関するコードを全て陳列することは不可能ですが、
1942	1942	以下は CPAN の中からさらなる注目を受けるに値するモジュールの短いリストです。
1943	1943
1944	1944	Apache::DProf
1945	1945	Apache::SmallProf
1946	1946	Benchmark
1947	1947	DBIx::Profile
1948	1948	Devel::AutoProfiler
1949	1949	Devel::DProf
1950	1950	Devel::DProfLB
1951	1951	Devel::FastProf
1952	1952	Devel::GraphVizProf
1953	1953	Devel::NYTProf
1954	1954	Devel::NYTProf::Apache
1955	1955	Devel::Profiler
1956	1956	Devel::Profile
1957	1957	Devel::Profit
1958	1958	Devel::SmallProf
1959	1959	Devel::WxProf
1960	1960	POE::Devel::Profiler
1961	1961	Sort::Key
1962	1962	Sort::Maker
1963	1963
1964	1964	=head2 URLS
1965	1965
1966	1966	(URL)
1967	1967
1968	1968	=begin original
1969	1969
1970	1970	Very useful online reference material:
1971	1971
1972	1972	=end original
1973	1973
1974	1974	とても有用なオンラインリファレンス:
1975	1975
1976	1976	http://www.ccl4.org/~nick/P/Fast_Enough/
1977	1977
1978	1978	http://www-128.ibm.com/developerworks/library/l-optperl.html
1979	1979
1980	1980	http://perlbuzz.com/2007/11/bind-output-variables-in-dbi-for-speed-and-safety.html
1981	1981
1982	1982	http://en.wikipedia.org/wiki/Performance_analysis
1983	1983
1984	1984	http://apache.perl.org/docs/1.0/guide/performance.html
1985	1985
1986	1986	http://perlgolf.sourceforge.net/
1987	1987
1988	1988	http://www.sysarch.com/Perl/sort_paper.html
1989	1989
1990	1990	=head1 AUTHOR
1991	1991
1992	1992	Richard Foley <richard.foley@rfi.net> Copyright (c) 2008
1993	1993
1994	1994	=cut
1995	1995
1996	1996	=begin meta
1997	1997
1998	1998	Translate: SHIRAKATA Kentaro <argrath@ub32.org>
1999	1999	Status: completed
2000	2000
2001	2001	=end meta

Powered by Amon2, 翻訳, サイト. Operated by Japan Perl Association