プロファイリングを行うスクリプトはprofiler_test.pl。
$ cat profiler_test.pl
#!/usr/bin/perl
use strict;
use warnings;
#use Data::Dumper;
my $data = func();
func0($data);
func1($data);
#print Dumper $data;
exit;
sub func {
my $node0;
foreach ( 0 .. 31 ) {
$node0->{$_} = {};
my $node1 = $node0->{$_};
foreach ( 0 .. 31 ) {
$node1->{$_} = {};
my $node2 = $node1->{$_};
foreach ( 0 .. 31 ) {
$node2->{$_} = {};
my $node3 = $node2->{$_};
foreach ( 0 .. 31 ) {
$node3->{$_} = {};
my $node4 = $node3->{$_};
$node4->{func0} = 'func0';
$node4->{func1} = 'func1';
}
}
}
}
return $node0;
}
sub func0 {
my $node0 = shift;
foreach ( keys %{$node0} ) {
my $node1 = $node0->{$_};
foreach ( keys %{$node1} ) {
my $node2 = $node1->{$_};
foreach ( keys %{$node2} ) {
my $node3 = $node2->{$_};
foreach ( keys %{$node3} ) {
my $node4 = $node3->{$_};
$node4->{func0} = 'func0';
}
}
}
}
}
sub func1 {
my $node0 = shift;
foreach my $k0 ( keys %{$node0} ) {
foreach my $k1 ( keys %{ $node0->{$k0} } ) {
foreach my $k2 ( keys %{ $node0->{$k0}->{$k1} } ) {
foreach my $k3 ( keys %{ $node0->{$k0}->{$k1}->{$k2} } ) {
$node0->{$k0}->{$k1}->{$k2}->{$k3}->{func1} = 'func1';
}
}
}
}
}
速度はtimeコマンドで測定することにする。まずは単独で走らせたときの結果。
$ time perl profiler_test.pl real 0m44.375s user 0m4.816s sys 0m0.116s
Devel::DProfを使う例。timeコマンドによれば速度の低下はほとんど無し。tmon.outがカレントディレクトリに作成され、これはdprofppで参照できる。
$ time perl -d:DProf profiler_test.pl real 0m44.717s user 0m4.820s sys 0m0.148s $ dprofpp tmon.out Total Elapsed Time = 43.84998 Seconds User+System Time = 4.889983 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 43.3 2.120 2.120 1 2.1200 2.1200 main::func 23.1 1.130 1.130 1 1.1300 1.1300 main::func1 20.4 1.000 1.000 1 1.0000 1.0000 main::func0 0.00 - -0.000 1 - - strict::bits 0.00 - -0.000 1 - - strict::import 0.00 - -0.000 1 - - warnings::import 0.00 - -0.000 2 - - main::BEGIN
func0とfunc1は連想配列の中身を書き換える関数である。func0は連想配列へのアクセスにメモリ上の位置を使っている。func1は連想配列へのアクセスにキーを使っている。Devel::DProfの結果からメモリ上の位置を記憶させる方が(func0の方が)早いことがわかる。
Devel::SmallProfを使う例。timeコマンドによれば16倍程度に速度低下。smallprof.outがカレントディレクトリに作成され、これはcatコマンドなどで参照できる。
$ time perl -d:SmallProf profiler_test.pl
real 13m2.615s
user 1m17.213s
sys 0m9.753s
$ cat smallprof.out
================ SmallProf version 2.02 ================
Profile of profiler_test.pl Page 1
=================================================================
count wall tm cpu time line
0 0.00000 0.00000 1:#!/usr/bin/perl
0 0.00000 0.00000 2:use strict;
0 0.00000 0.00000 3:use warnings;
0 0.00000 0.00000 4:
0 0.00000 0.00000 5:#use Data::Dumper;
0 0.00000 0.00000 6:
1 0.00000 0.00000 7:my $data = func();
1 0.00000 0.00000 8:func0($data);
1 0.00000 0.00000 9:func1($data);
0 0.00000 0.00000 10:
0 0.00000 0.00000 11:#print Dumper $data;
1 4.41105 0.48000 12:exit;
0 0.00000 0.00000 13:
0 0.00000 0.00000 14:sub func {
1 0.00000 0.00000 15: my $node0;
1 0.00000 0.00000 16: foreach ( 0 .. 31 ) {
32 0.00001 0.00000 17: $node0->{$_} = {};
32 0.00003 0.00000 18: my $node1 = $node0->{$_};
32 0.00000 0.00000 19: foreach ( 0 .. 31 ) {
1024 0.03295 0.00000 20: $node1->{$_} = {};
1024 0.00033 0.01000 21: my $node2 = $node1->{$_};
1024 0.03236 0.01000 22: foreach ( 0 .. 31 ) {
32768 1.19528 0.20000 23: $node2->{$_} = {};
32768 0.77734 0.12000 24: my $node3 = $node2->{$_};
32768 1.03954 0.21000 25: foreach ( 0 .. 31 ) {
1048576 33.72827 6.53000 26: $node3->{$_} = {};
1048576 28.13931 5.45000 27: my $node4 = $node3->{$_};
1048576 36.07179 6.79000 28: $node4->{func0} =
1048576 33.76210 6.58000 29: $node4->{func1} =
0 0.00000 0.00000 30: }
0 0.00000 0.00000 31: }
0 0.00000 0.00000 32: }
0 0.00000 0.00000 33: }
1 0.00000 0.00000 34: return $node0;
0 0.00000 0.00000 35:}
0 0.00000 0.00000 36:
0 0.00000 0.00000 37:sub func0 {
1 0.00000 0.00000 38: my $node0 = shift;
1 0.00001 0.00000 39: foreach ( keys %{$node0} ) {
32 0.00001 0.00000 40: my $node1 = $node0->{$_};
32 0.00049 0.00000 41: foreach ( keys %{$node1} ) {
1024 0.03294 0.01000 42: my $node2 = $node1->{$_};
1024 0.07621 0.00000 43: foreach ( keys %{$node2} ) {
32768 0.86101 0.18000 44: my $node3 = $node2->{$_};
32768 2.78642 0.55000 45: foreach ( keys %{$node3} ) {
1048576 28.38261 6.24000 46: my $node4 = $node3->{$_};
1048576 29.96298 5.55000 47: $node4->{func0} =
0 0.00000 0.00000 48: }
0 0.00000 0.00000 49: }
0 0.00000 0.00000 50: }
0 0.00000 0.00000 51: }
0 0.00000 0.00000 52:}
0 0.00000 0.00000 53:
0 0.00000 0.00000 54:sub func1 {
1 0.00000 0.00000 55: my $node0 = shift;
1 0.00001 0.00000 56: foreach my $k0 ( keys %{$node0} ) {
================ SmallProf version 2.02 ================
Profile of profiler_test.pl Page 2
=================================================================
count wall tm cpu time line
32 0.00037 0.00000 57: foreach my $k1 ( keys %{ $node0-
1024 0.10307 0.02000 58: foreach my $k2 ( keys %{ $node0-
32768 2.68094 0.46000 59: foreach my $k3 ( keys %{
1048576 34.89408 6.64000 60: $node0->{$k0}->{$k1}-
0 0.00000 0.00000 61: }
0 0.00000 0.00000 62: }
0 0.00000 0.00000 63: }
0 0.00000 0.00000 64: }
0 0.00000 0.00000 65:}
Devel::FastProfを使う例。timeコマンドによれば1.6倍程度に速度低下。fastprof.outがカレントディレクトリに作成され、これはfprofppコマンドで参照できる。
$ time perl -d:FastProf profiler_test.pl
real 1m42.409s
user 0m7.993s
sys 0m3.384s
$ fprofpp -f fastprof.out
# fprofpp output format is:
# filename:line time count: source
profiler_test.pl:60 13.72410 1048576: $node0->{$k0}->{$k1}->{$k2}->{$k3}->{func1} = 'func1';
profiler_test.pl:29 11.09643 1048576: $node4->{func1} = 'func1';
profiler_test.pl:26 10.71653 1048576: $node3->{$_} = {};
profiler_test.pl:28 10.68122 1048576: $node4->{func0} = 'func0';
profiler_test.pl:47 9.70313 1048576: $node4->{func0} = 'func0';
profiler_test.pl:46 5.65761 1048576: my $node4 = $node3->{$_};
profiler_test.pl:27 5.00859 1048576: my $node4 = $node3->{$_};
profiler_test.pl:12 4.79216 1: exit;
profiler_test.pl:59 2.02908 32768: foreach my $k3 ( keys %{ $node0->{$k0}->{$k1}->{$k2} } ) {
profiler_test.pl:45 1.69200 32768: foreach ( keys %{$node3} ) {
profiler_test.pl:25 0.25556 32768: foreach ( 0 .. 31 ) {
profiler_test.pl:43 0.17796 1024: foreach ( keys %{$node2} ) {
profiler_test.pl:44 0.15651 32768: my $node3 = $node2->{$_};
profiler_test.pl:24 0.14754 32768: my $node3 = $node2->{$_};
profiler_test.pl:23 0.10395 32768: $node2->{$_} = {};
profiler_test.pl:58 0.07397 1024: foreach my $k2 ( keys %{ $node0->{$k0}->{$k1} } ) {
profiler_test.pl:22 0.03299 1024: foreach ( 0 .. 31 ) {
profiler_test.pl:42 0.00217 1024: my $node2 = $node1->{$_};
profiler_test.pl:20 0.00199 1024: $node1->{$_} = {};
profiler_test.pl:21 0.00078 1024: my $node2 = $node1->{$_};
profiler_test.pl:57 0.00047 32: foreach my $k1 ( keys %{ $node0->{$k0} } ) {
profiler_test.pl:41 0.00043 32: foreach ( keys %{$node1} ) {
profiler_test.pl:17 0.00007 32: $node0->{$_} = {};
profiler_test.pl:40 0.00006 32: my $node1 = $node0->{$_};
profiler_test.pl:19 0.00004 32: foreach ( 0 .. 31 ) {
profiler_test.pl:39 0.00002 1: foreach ( keys %{$node0} ) {
profiler_test.pl:18 0.00002 32: my $node1 = $node0->{$_};
profiler_test.pl:56 0.00001 1: foreach my $k0 ( keys %{$node0} ) {
profiler_test.pl:34 0.00000 1: return $node0;
profiler_test.pl:16 0.00000 1: foreach ( 0 .. 31 ) {
profiler_test.pl:8 0.00000 1: func0($data);
profiler_test.pl:9 0.00000 1: func1($data);
profiler_test.pl:7 0.00000 1: my $data = func();
profiler_test.pl:38 0.00000 1: my $node0 = shift;
profiler_test.pl:55 0.00000 1: my $node0 = shift;
profiler_test.pl:15 0.00000 1: my $node0;